Bug 1115508 - [RFE] Send debug logs to journald by default
Summary: [RFE] Send debug logs to journald by default
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Enterprise Linux 7
Classification: Red Hat
Component: sssd
Version: 7.0
Hardware: Unspecified
OS: Unspecified
unspecified
unspecified
Target Milestone: rc
: ---
Assignee: Jakub Hrozek
QA Contact: Kaushik Banerjee
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2014-07-02 13:45 UTC by Jakub Hrozek
Modified: 2020-05-02 17:35 UTC (History)
7 users (show)

Fixed In Version: sssd-1.12.0-1.el7
Doc Type: Enhancement
Doc Text:
Feature: SSSD gained the capability to send its debug logs to journald in addition to private SSSD debug logs Reason: journald allows the debug logs to be queried easily and stored centrally Result: the admin can view the logs with the usual journalctl tool, view the logs in JSON format, query the logs per-domain and other data fields.
Clone Of:
Environment:
Last Closed: 2015-03-05 10:32:55 UTC
Target Upstream Version:


Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
Github SSSD sssd issues 3237 0 None closed [RFE] Send debug logs to journald by default 2021-02-16 12:06:19 UTC
Red Hat Product Errata RHBA-2015:0441 0 normal SHIPPED_LIVE sssd bug fix and enhancement update 2015-03-05 15:05:27 UTC

Description Jakub Hrozek 2014-07-02 13:45:11 UTC
This bug is created as a clone of upstream ticket:
https://fedorahosted.org/sssd/ticket/2195

Instead of writing the debug logs directly to the disk, it is possible to send them to journald, on platforms where journald is available.

The biggest benefit is that the debug logs are structured, so it's possible to decorate the debug messages with key/value pairs and later query based on these extra fields. Examples of the extra fields are source file, line or SSSD domain.

There might even be a performance enhancement as SSSD had to perform an fsync() after each debug line, although I haven't done any measurements.

Comment 1 Jakub Hrozek 2014-07-02 15:17:25 UTC
Fixed upstream:
    9542512d7be40f2000298c86d3d2b728f4f0f65a
    b96988a35bfb5f6faf2e364ae966166398afeca3
    60df591b865831a71e93eb57f4c353c4555b66cf
    41354b0b972df187d5b6f6b02b26b736ec6bce23

Comment 2 Jakub Hrozek 2014-07-16 09:21:33 UTC
To clarify -- the journald support is compiled in by default, but not enabled. We don't want to suddenly change how logs are produced in an update.

In order to enable the journald logging, the admin must:
1) edit /usr/lib/systemd/system/sssd.service and change:
  ExecStart=/usr/sbin/sssd -D -f
to:
  ExecStart=/usr/sbin/sssd -D

2) reload the systemd unit
systemctl daemon-reload

3) restart the sssd
systemctl restart sssd.service

Comment 3 Lukas Slebodnik 2014-07-16 11:28:44 UTC
(In reply to Jakub Hrozek from comment #2)
> To clarify -- the journald support is compiled in by default, but not
> enabled. We don't want to suddenly change how logs are produced in an update.
> 
> In order to enable the journald logging, the admin must:
> 1) edit /usr/lib/systemd/system/sssd.service and change:
Service files in directory /usr/lib/systemd/ should not be edited.

We already have files in /etc which should be used for this purpose and will override values from /usr/lib/systemd/system/sssd.service

sh-4.2$ rpm -ql sssd-common | grep service
/etc/systemd/system/sssd.service.d
/etc/systemd/system/sssd.service.d/journal.conf
/usr/lib/systemd/system/sssd.service

1) systemctl stop sssd
2) edit /etc/systemd/system/sssd.service.d/journal.conf

 diff -u old_journal.conf journal.conf 
--- old_journal.conf    2014-07-16 13:23:12.355269131 +0200
+++ journal.conf        2014-07-16 13:15:51.322691498 +0200
@@ -3,5 +3,5 @@
 # to go to journald instead of /var/log/sssd. You will need to
 # run 'systemctl daemon-reload' and then restart the SSSD service
 # for this to take effect
-#ExecStart=
-#ExecStart=/usr/sbin/sssd -D
+ExecStart=
+ExecStart=/usr/sbin/sssd -D

3) systemctl daemon-reload
4) systemctl start sssd
5) sss_debuglevel 9
6) journalctl -f
 You will se a lot of messages from sssd
7) sss_debuglevel 9
  disable logging from sssd. This step is optional to reduce messages in journalctl output.

Comment 5 Nirupama Karandikar 2014-11-25 06:52:06 UTC
Tested with sssd-1.12.2-16.el7.x86_64

Setup:
- Edit /etc/systemd/system/sssd.service.d/journal.conf and add 
ExecStart=
ExecStart=/usr/sbin/sssd -D

- systemctl daemon-reload
- Set "debug_level = 9" in sssd section, domain section and nss, pam sections. 
- systemctl start sssd
- Check for the debug logs in journalctl output. With different options of in journalctl utility.

Tests:

1.
# journalctl -f _SYSTEMD_UNIT=sssd.service SYSLOG_IDENTIFIER=sssd_be

Nov 24 19:11:41 dhcp207-182.lab.eng.pnq.redhat.com sssd_be[5095]: Marking server 'dhcp207-102.lab.eng.pnq.redhat.com' as 'resolving name'
Nov 24 19:11:41 dhcp207-182.lab.eng.pnq.redhat.com sssd_be[5095]: Marking server 'dhcp207-102.lab.eng.pnq.redhat.com' as 'name resolved'
Nov 24 19:11:41 dhcp207-182.lab.eng.pnq.redhat.com sssd_be[5095]: Saving the first resolved server
Nov 24 19:11:41 dhcp207-182.lab.eng.pnq.redhat.com sssd_be[5095]: Found address for server dhcp207-102.lab.eng.pnq.redhat.com: [10.65.207.102] TTL 7200
Nov 24 19:11:41 dhcp207-182.lab.eng.pnq.redhat.com sssd_be[5095]: Constructed uri 'ldap://dhcp207-102.lab.eng.pnq.redhat.com'
Nov 24 19:11:41 dhcp207-182.lab.eng.pnq.redhat.com sssd_be[5095]: Using file descriptor [18] for LDAP connection.
Nov 24 19:11:41 dhcp207-182.lab.eng.pnq.redhat.com sssd_be[5095]: Setting 6 seconds timeout for connecting
Nov 24 19:11:41 dhcp207-182.lab.eng.pnq.redhat.com sssd_be[5095]: New LDAP connection to [ldap://dhcp207-102.lab.eng.pnq.redhat.com:389/??base] with fd [18].
Nov 24 19:11:41 dhcp207-182.lab.eng.pnq.redhat.com sssd_be[5095]: Executing START TLS
Nov 24 19:11:41 dhcp207-182.lab.eng.pnq.redhat.com sssd_be[5095]: Trace: sh[0x7f1d15717ae0], connected[1], ops[0x7f1d157149c0], ldap[0x7f1d15713100]
Nov 24 19:11:41 dhcp207-182.lab.eng.pnq.redhat.com sssd_be[5095]: Message type: [LDAP_RES_EXTENDED]
Nov 24 19:11:41 dhcp207-182.lab.eng.pnq.redhat.com sssd_be[5095]: START TLS result: Success(0), Start TLS request accepted.Server willing to negotiate SSL.
Nov 24 19:11:41 dhcp207-182.lab.eng.pnq.redhat.com sssd_be[5095]: Getting rootdse
Nov 24 19:11:41 dhcp207-182.lab.eng.pnq.redhat.com sssd_be[5095]: Searching 10.65.207.102
Nov 24 19:11:41 dhcp207-182.lab.eng.pnq.redhat.com sssd_be[5095]: calling ldap_search_ext with [(objectclass=*)][].

# journalctl _SYSTEMD_UNIT=sssd.service SYSLOG_IDENTIFIER=sssd_nss

Nov 24 19:12:50 dhcp207-182.lab.eng.pnq.redhat.com sssd_nss[5119]: Returning info for user [dsuser1@LDAP]
Nov 24 19:12:50 dhcp207-182.lab.eng.pnq.redhat.com sssd_nss[5119]: Deleting request: [0x7fc276240b90:1:dsuser1@LDAP]
Nov 24 19:12:50 dhcp207-182.lab.eng.pnq.redhat.com sssd_nss[5119]: Idle timer re-set for client [0x7fc277059ca0][19]
Nov 24 19:12:50 dhcp207-182.lab.eng.pnq.redhat.com sssd_nss[5119]: Idle timer re-set for client [0x7fc277059ca0][19]
Nov 24 19:12:50 dhcp207-182.lab.eng.pnq.redhat.com sssd_nss[5119]: Client disconnected!
Nov 24 19:12:50 dhcp207-182.lab.eng.pnq.redhat.com sssd_nss[5119]: Terminated client [0x7fc277059ca0][19]
Nov 24 19:12:54 dhcp207-182.lab.eng.pnq.redhat.com sssd_nss[5119]: dbus conn: 0x7fc277051e50


# journalctl -f -o short-precise

-- Logs begin at Sun 2014-11-23 17:26:43 IST. --
Nov 24 19:13:54.011074 dhcp207-182.lab.eng.pnq.redhat.com sssd_be[5118]: dbus conn: 0x7eff8a027ac0
Nov 24 19:13:54.011088 dhcp207-182.lab.eng.pnq.redhat.com sssd_be[5118]: Dispatching.
Nov 24 19:13:54.011102 dhcp207-182.lab.eng.pnq.redhat.com sssd_be[5118]: Received SBUS method [ping]
Nov 24 19:13:54.011116 dhcp207-182.lab.eng.pnq.redhat.com sssd_be[5118]: Not a sysbus message, quit
Nov 24 19:13:54.011128 dhcp207-182.lab.eng.pnq.redhat.com sssd_be[5118]: Received SBUS method [ping]
Nov 24 19:13:54.011197 dhcp207-182.lab.eng.pnq.redhat.com sssd_nss[5119]: dbus conn: 0x7fc277051e50
Nov 24 19:13:54.011206 dhcp207-182.lab.eng.pnq.redhat.com sssd_nss[5119]: Dispatching.
Nov 24 19:13:54.011219 dhcp207-182.lab.eng.pnq.redhat.com sssd_nss[5119]: Received SBUS method [ping]
Nov 24 19:13:54.011230 dhcp207-182.lab.eng.pnq.redhat.com sssd_nss[5119]: Not a sysbus message, quit
Nov 24 19:13:54.011241 dhcp207-182.lab.eng.pnq.redhat.com sssd_nss[5119]: Received SBUS method [ping]

with micro-seconds time stamp.

2. Repeat testing after firing up sssd from cmdline

# sssd -d 10

Works as expected.

Comment 7 errata-xmlrpc 2015-03-05 10:32:55 UTC
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://rhn.redhat.com/errata/RHBA-2015-0441.html


Note You need to log in before you can comment on or make changes to this bug.