Bug 1115508

Summary: [RFE] Send debug logs to journald by default
Product: Red Hat Enterprise Linux 7 Reporter: Jakub Hrozek <jhrozek>
Component: sssdAssignee: Jakub Hrozek <jhrozek>
Status: CLOSED ERRATA QA Contact: Kaushik Banerjee <kbanerje>
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: 7.0CC: grajaiya, jgalipea, lslebodn, mkosek, nkarandi, pbrezina, preichl
Target Milestone: rcKeywords: FutureFeature
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
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.
 Story Points: ---
Clone Of: Environment:
Last Closed: 2015-03-05 10:32:55 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

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