4

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
3

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.

  • I edited the question, it now includes the versions. Thanks for your help, however I cannot quite follow (yet). The PIDs are the same in both cases, so how does journald differentiate with it? I missed the CMDLINE thing with [priv], thanks for pointing that out. And how did you find out that the second process is running in chroot? I am actually not using any chroots on that system. – imsodin Apr 12 '16 at 18:19
  • 2
    Now I see that there are both of them originated from same PID. But the suffix of message is telling from which process does it come from. It is pre-auth child to increase security (it is by default). Now it looks like it differentiates by _COMM, which differs. Openssh is changing proctitle to keep some "order" in the mess of processes. Anyway it is more than weird ... – Jakuje Apr 12 '16 at 18:23

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.