Bug 2503 - The sshd log files are insufficient to detect sessions
Summary: The sshd log files are insufficient to detect sessions
Status: CLOSED FIXED
Alias: None
Product: Portable OpenSSH
Classification: Unclassified
Component: sshd (show other bugs)
Version: 7.1p1
Hardware: All All
: P5 enhancement
Assignee: Assigned to nobody
URL:
Keywords:
Depends on:
Blocks: V_7_2
  Show dependency treegraph
 
Reported: 2015-11-20 22:16 AEDT by Felix von Leitner
Modified: 2017-07-11 01:47 AEST (History)
2 users (show)

See Also:


Attachments
include port number in more places (4.97 KB, patch)
2015-12-11 13:54 AEDT, Damien Miller
dtucker: ok+
Details | Diff

Note You need to log in before you can comment on or make changes to this bug.
Description Felix von Leitner 2015-11-20 22:16:30 AEDT
I am working on a software for log file analysis, and one of the ideas is to identify active sessions on a system so the software can warn if something is running as a user on a system when that user is not logged in.

Here is a typical log output from sshd (the portable version) on my Linux server:

Nov 20 12:00:42 ptrace sshd[27769]: Accepted publickey for leitner from [ip] port 41122 ssh2: ED25519 [fingerprint]
Nov 20 12:00:51 ptrace sshd[27773]: Received disconnect from [ip]: 11: disconnected by user

Note how there is insufficient information here to link these two log entries. The PID of sshd is different, and the IP alone is not sufficient to link the entry. There could be more than one login from that IP.

Adding the user name that is disconnecting would help, but it would still be more of a heuristic than a real link. Suggestion: Add the port to the disconnect message. Or make sure both the accept and disconnect messages come from the same PID. Or put a unique session ID in the messages so collation is possible. Or all of the above :-)

Note that the problem goes away if you use PAM, because PAM does additional logging on top of what sshd does. However, PAM is not mandatory (I don't use PAM here), and I think it should be possible to do this kind of analysis even without PAM. Otherwise why do we have sshd logs in the first place?
Comment 1 Damien Miller 2015-12-11 13:54:25 AEDT
Created attachment 2765 [details]
include port number in more places

Loglevel=verbose already gives you most of the information you want:

Dec 11 13:26:53 fuyu sshd[14096]: Connection from 203.217.30.82 port 36726 on 203.217.30.81 port 22
Dec 11 13:26:54 fuyu sshd[14096]: Postponed publickey for djm from 203.217.30.82 port 36726 ssh2 [preauth]
Dec 11 13:26:58 fuyu sshd[14096]: Accepted publickey for djm from 203.217.30.82 port 36726 ssh2: ECDSA SHA256:LmoNaxGFFurT6S2Q67RFuuxIq4is0rVLLdkt6Qgvy66E
Dec 11 13:26:58 fuyu sshd[14096]: User child is on pid 17347
Dec 11 13:26:58 fuyu sshd[17347]: Starting session: shell on ttyp2 for djm from 203.217.30.82 port 36726
Dec 11 13:27:13 fuyu sshd[17347]: Received disconnect from 203.217.30.82: 11: disconnected by user
Dec 11 13:27:13 fuyu sshd[17347]: Disconnected from 203.217.30.82

That being said, we could include the port in disconnect messages.
Comment 2 Darren Tucker 2015-12-11 14:09:51 AEDT
Comment on attachment 2765 [details]
include port number in more places

ok, but I think we should also explicitly cache these values as early as practical (ie just after accept, and just after the inetd/reexec handling) to minimise the chance they'll vanish by the time they're needed.
Comment 3 Damien Miller 2015-12-11 14:29:35 AEDT
The caching is already triggered as soon as the packet code is informed of the connection fds. See https://anongit.mindrot.org/openssh.git/tree/packet.c?id=39736be06c#n298

Anyway, patch is applied - this will be in OpenSSH 7.2. It looks like this now:

Dec 11 14:28:29 fuyu sshd[15956]: Connection from 203.217.30.82 port 38485 on 203.217.30.81 port 22
Dec 11 14:28:30 fuyu sshd[15956]: Postponed publickey for djm from 203.217.30.82 port 38485 ssh2 [preauth]
Dec 11 14:28:32 fuyu sshd[15956]: Accepted publickey for djm from 203.217.30.82 port 38485 ssh2: ECDSA SHA256:LmoNaxGFFurT6S2Q67RFuuxIq4is0rVLLdkt6Qgvy66E
Dec 11 14:28:32 fuyu sshd[15956]: User child is on pid 26320
Dec 11 14:28:32 fuyu sshd[26320]: Starting session: shell on ttyp3 for djm from 203.217.30.82 port 38485
Dec 11 14:28:38 fuyu sshd[26320]: Received disconnect from 203.217.30.82 port 38485:11: disconnected by user
Dec 11 14:28:38 fuyu sshd[26320]: Disconnected from 203.217.30.82 port 38485
Comment 4 Damien Miller 2016-08-02 10:41:42 AEST
Close all resolved bugs after 7.3p1 release