openssh bugs - Nov 2015 - [Bug 2503] New: The sshd log files are insufficient to detect sessions

https://bugzilla.mindrot.org/show_bug.cgi?id=2503

            Bug ID: 2503
           Summary: The sshd log files are insufficient to detect sessions
           Product: Portable OpenSSH
           Version: 7.1p1
          Hardware: All
                OS: All
            Status: NEW
          Severity: enhancement
          Priority: P5
         Component: sshd
          Assignee: unassigned-bugs at mindrot.org
          Reporter: felix-mindrot at fefe.de

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?

-- 
You are receiving this mail because:
You are watching the assignee of the bug.

https://bugzilla.mindrot.org/show_bug.cgi?id=2503

Damien Miller <djm at mindrot.org> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
                 CC|                            |djm at mindrot.org,
                   |                            |dtucker at zip.com.au
   Attachment #2765|                            |ok?(dtucker at zip.com.au)
              Flags|                            |

--- Comment #1 from Damien Miller <djm at mindrot.org> ---
Created attachment 2765
  --> https://bugzilla.mindrot.org/attachment.cgi?id=2765&action=edit
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.

-- 
You are receiving this mail because:
You are watching someone on the CC list of the bug.
You are watching the assignee of the bug.

https://bugzilla.mindrot.org/show_bug.cgi?id=2503

Damien Miller <djm at mindrot.org> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
             Blocks|                            |2451


Referenced Bugs:

https://bugzilla.mindrot.org/show_bug.cgi?id=2451
[Bug 2451] Bugs intended to be fixed in 7.2
-- 
You are receiving this mail because:
You are watching the assignee of the bug.
You are watching someone on the CC list of the bug.

https://bugzilla.mindrot.org/show_bug.cgi?id=2503

Darren Tucker <dtucker at zip.com.au> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
   Attachment #2765|ok?(dtucker at zip.com.au)     |ok+
              Flags|                            |

--- Comment #2 from Darren Tucker <dtucker at zip.com.au> ---
Comment on attachment 2765
  --> https://bugzilla.mindrot.org/attachment.cgi?id=2765
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.

-- 
You are receiving this mail because:
You are watching the assignee of the bug.
You are watching someone on the CC list of the bug.

https://bugzilla.mindrot.org/show_bug.cgi?id=2503

Damien Miller <djm at mindrot.org> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
             Status|NEW                         |RESOLVED
         Resolution|---                         |FIXED

--- Comment #3 from Damien Miller <djm at mindrot.org> ---
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

-- 
You are receiving this mail because:
You are watching the assignee of the bug.
You are watching someone on the CC list of the bug.

https://bugzilla.mindrot.org/show_bug.cgi?id=2503

Damien Miller <djm at mindrot.org> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
             Status|RESOLVED                    |CLOSED

--- Comment #4 from Damien Miller <djm at mindrot.org> ---
Close all resolved bugs after 7.3p1 release

-- 
You are receiving this mail because:
You are watching someone on the CC list of the bug.
You are watching the assignee of the bug.

https://bugzilla.mindrot.org/show_bug.cgi?id=2503

Sebastian Roland <seroland86 at gmail.com> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
           See Also|                            |https://bugzilla.mindrot.or
                   |                            |g/show_bug.cgi?id=2741

-- 
You are receiving this mail because:
You are watching someone on the CC list of the bug.
You are watching the assignee of the bug.