A syslog-ng message correlation example [LWN.net]

For example, the following log messages describe a login-logout pair for the OpenSSH server:

Jan 18 10:43:02 ubuntu sshd[2186]: Accepted password for root from 192.168.101.1 port 38420 ssh2
Jan 18 10:43:02 ubuntu sshd[2186]: pam_unix(sshd:session): session opened for user root by (uid=0)
Jan 18 10:43:18 ubuntu sshd[2186]: Received disconnect from 192.168.101.1: 11: disconnected by user
Jan 18 10:43:18 ubuntu sshd[2186]: pam_unix(sshd:session): session closed for user root

The following sample syslog-ng pattern database rules match the first the and the fourth log message, and generate a new message when the fourth message is received. This generated message contains both the login and the logout dates:

<patterndb version='4' pub_date='2010-10-17'>
    <ruleset name='sshd' id='12345678'>
        <pattern>sshd</pattern>
            <rules>
                <!-- The pattern database rule for the first log message -->
                <rule provider='me' id='12347598' class='system' 
                    context-id="ssh-login-logout" context-timeout="86400" 
                    context-scope="process">
                <!-- Note the context-id that groups together the
		relevant messages, and the context-timeout value that
		determines how long a new message can be added to the
		context  -->
                    <patterns>
                        <pattern>
                            Accepted @QSTRING:SSH.AUTH_METHOD: @ \
			    for@QSTRING:SSH_USERNAME: \
                            @from @QSTRING:SSH_CLIENT_ADDRESS: \ 
                            @port @NUMBER:SSH_PORT_NUMBER:@ ssh2
                        </pattern>
                        <!-- This is the actual pattern used to identify
			the log message. The segments between the @
			characters are parsers that recognize the variable
			parts of the message - they can also be used as
			macros.  -->
                    </patterns>
                </rule>
                <!-- The pattern database rule for the fourth log message -->
                <rule provider='me' id='12347599' class='system' context-id="ssh-login-logout" context-scope="process">
                    <patterns>
                        <pattern>pam_unix(sshd:session): session closed for user @ESTRING:SSH_USERNAME: @</pattern>
                    </patterns>
                    <actions>
                        <action>
                            <message>
                                <values>
                                    <value name="MESSAGE">
                                        An SSH session for $SSH_USERNAME from \
                                        ${SSH_CLIENT_ADDRESS}@1 closed. \
                                        Session lasted from ${DATE}@1 $DATE.
                                    </value>
                                    <!-- This is the new log message
				    that is generated when the logout
				    message is received. The macros ending
				    with @1 reference values of the
				    previous message from the context. -->
                                </values>
                            </message>
                        </action>
                    </actions>
                </rule>
            </rules>
    </ruleset>
</patterndb>

A syslog-ng message correlation example

Posted Mar 7, 2012 19:27 UTC (Wed) by larsks (guest, #61120) [Link] (2 responses)

The problem with this example is that most modern sshd installations will not have the same process id for the "Accepted" message and the "Received disconnect" message due the use of privilege separation. For example:

Mar 7 14:19:29 login.example.com [authpriv:info] sshd[2671]: Accepted publickey for lars from 10.243.18.22 port 36265 ssh2
Mar 7 14:19:31 login.example.com [authpriv:info] sshd[2673]: Received disconnect from 10.243.18.22: 11: disconnected by user

So while these messages *should* be correlated, they don't provide enough data in order to do so. I think the problem here is primarily with OpenSSH. For example, if the disconnect message also included the port number, that could be used to match it with the corresponding Accepted... message.

A syslog-ng message correlation example

Posted Mar 7, 2012 21:28 UTC (Wed) by mp (subscriber, #5615) [Link] (1 responses)

But this example correlates the "Accepted" message with the "session closed" one, and they seem to come from the same process under privilege separation.

A syslog-ng message correlation example

Posted Aug 8, 2013 13:12 UTC (Thu) by faxm0dem (guest, #92265) [Link]

In my installation, the PID of the "Accepted password for" message is logged.
However, the PID of the "pam_unix(sshd:session)" message is not available.
So using scope=process doesn't work.
Using scope=program does, but will mix unrelated sessions.