Ssh – In journald, why are some sshd log entries not attributed to ssh.service

sshdsystemdsystemd-journald

When using journalctl to inspect my journald logs the output from the commands

journalctl -u ssh.service

and 

journalctl _COMM=sshd

differ. The first command produces just a subset of the log entries displayed by the second. However there is no clear distinction between log entries that only show up in the first case and those showing up in both cases. In the following are two near identical log entries in the "-o verbose" format. The one that shows up in both has the _SYSTEMD_UNIT=ssh.service attribute but is otherwise near identical. There are also entries that only show up with _COMM=sshd that are completely unrelated to an entry showing up in both cases.

What is the reason for this behavior?

I am running debian testing with sshd version "OpenSSH_7.2p2 Debian-2, OpenSSL 1.0.2g" and systemd 229.

Tue 2016-04-12 06:43:38.498526 CEST [s=0430cdfa7fb2408cbc98dccb31e42ffc;i=17096e;b=d17df7e99dfa496894cc1e5b6314ffa2;m=6a36040f2c;t=530424
    PRIORITY=6
    _UID=0
    _GID=0
    _CAP_EFFECTIVE=3fffffffff
    _SYSTEMD_SLICE=-.slice
    _BOOT_ID=d17df7e99dfa496894cc1e5b6314ffa2
    _MACHINE_ID=05019d58a4004f9f90c1cfbd295b54ca
    _HOSTNAME=homeserver
    _SYSTEMD_CGROUP=/
    _TRANSPORT=syslog
    SYSLOG_FACILITY=4
    SYSLOG_IDENTIFIER=sshd
    _COMM=sshd
    SYSLOG_PID=31025
    _PID=31025
    MESSAGE=Disconnected from 183.3.202.172 port 36152 [preauth]
    _SOURCE_REALTIME_TIMESTAMP=1460436218498526
Tue 2016-04-12 06:43:38.498459 CEST [s=0430cdfa7fb2408cbc98dccb31e42ffc;i=17096d;b=d17df7e99dfa496894cc1e5b6314ffa2;m=6a36040d71;t=530424
    PRIORITY=6
    _UID=0
    _GID=0
    _CAP_EFFECTIVE=3fffffffff
    _BOOT_ID=d17df7e99dfa496894cc1e5b6314ffa2
    _MACHINE_ID=05019d58a4004f9f90c1cfbd295b54ca
    _HOSTNAME=homeserver
    _TRANSPORT=syslog
    _SYSTEMD_SLICE=system.slice
    SYSLOG_FACILITY=4
    SYSLOG_IDENTIFIER=sshd
    _COMM=sshd
    _EXE=/usr/sbin/sshd
    _CMDLINE=sshd: unknown [priv]
    _SYSTEMD_CGROUP=/system.slice/ssh.service
    _SYSTEMD_UNIT=ssh.service
    SYSLOG_PID=31025
    _PID=31025
    MESSAGE=Received disconnect from 183.3.202.172 port 36152:11:  [preauth]
    _SOURCE_REALTIME_TIMESTAMP=1460436218498459

Best Answer

Because journald (probably) differentiate the message according to _COMM of the logging service.

sshd is running multiple processes and changes proctitle accordingly. It probably confuses journald. In your example, the [priv] is distinguished correctly, but [preauth] not. The second process is also running in chroot, but parent ([priv]) should log for him.

Related Question