Bug 2503

Summary: The sshd log files are insufficient to detect sessions
Product: Portable OpenSSH Reporter: Felix von Leitner <felix-mindrot>
Component: sshdAssignee: Assigned to nobody <unassigned-bugs>
Status: CLOSED FIXED    
Severity: enhancement CC: djm, dtucker
Priority: P5    
Version: 7.1p1   
Hardware: All   
OS: All   
See Also: https://bugzilla.mindrot.org/show_bug.cgi?id=2741
Bug Depends on:    
Bug Blocks: 2451    
Attachments:
Description Flags
include port number in more places dtucker: ok+

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