Topic: POP3S logging: determine which user access from which IP

[tran.nathan]

We run a mail server with SME server 9.1. We want to analyze which user access the mail server from which IP.

For users accessing using roundcube webmail, we analyze the file /var/log/roundcubemail/userlogins. Both username and accessed IP are in that log file.

For users accessing using IMAP, we analyze the file /var/log/dovecot.log. We can see both username and accessed IP in this log file also.

However, we have problem with analyzing the POP3S logging file. We analyze the files /var/log/secure*. We either see the usernames, for example

Jan 16 14:31:27 mx pop3[28611]: pam_unix(pop3:session): session opened for user nathan by (uid=0)

or we see the accessed IP, for example something like

Jan 16 14:32:58 mx stunnel: LOG5[28683:139725346039744]: pop3s accepted connection from 123.45.67.89:61091

We don't know how to determine which user access the mail server from which IP based on the info in /var/log/secure log file.

Is there a way to do this? or is there another way to get the info we want ? I really appreciate any pointer on this.

Nathan

[Stefano]

first of all, welcome here

if you're really running SME9.1 you'd update asap to the last stable release, SME9.2

about logs, I'll dig a bit and report back asap (not at my pc right now)

[mmccarn]

If your pop3 userbase is small, you can get close to what you want by searching for "pop3" in /var/log/secure.  Each connection will show an "accepted connection" entry giving the IP and a "session opened" entry showing the username.

However, two users connecting at the same time, or one user from two devices, might result in interleaved information; separating them in that case looks tricky.

Here's a log extract showing two test connections I made to my server - one from the server itself, and another from my workstation:

Code: [Select]

# grep pop3 /var/log/secure
Jan 17 07:38:36 office stunnel: LOG5[18791:139651368576960]: pop3s accepted connection from 127.0.0.1:40360
Jan 17 07:38:44 office pop3[18793]: pam_unix(pop3:session): session opened for user mmccarn by (uid=0)
Jan 17 07:38:44 office pop3[18793]: pam_unix(pop3:session): session closed for user mmccarn
Jan 17 07:44:29 office stunnel: LOG5[19167:139848992675776]: pop3s accepted connection from 192.168.200.110:51341
Jan 17 07:44:37 office pop3[19169]: pam_unix(pop3:session): session opened for user mmccarn by (uid=0)
Jan 17 07:44:37 office pop3[19169]: pam_unix(pop3:session): session closed for user mmccarn

Here is the corresponding section of /var/log/pop3s/current.  These connections can be tied to the "accepted connection" entries from /var/log/secure, but not unambiguously to the "session opened" entries.  Perhaps the "session opened" entry is always 2 more than the "accepted connection" entry, as in my tests -- but perhaps not...

Code: [Select]

@400000005a5f432336e4bdf4 tcpsvd: info: status 0/40
@400000005a5f43d63079acf4 tcpsvd: info: status 1/40
@400000005a5f43d6307b3f4c tcpsvd: info: pid 18791 from 127.0.0.1
@400000005a5f43d6307caa94 tcpsvd: info: concurrency 18791 127.0.0.1 1/4
@400000005a5f43d6307cba34 tcpsvd: info: start 18791 0:127.0.0.1 ::127.0.0.1:40360 ./peers/127.0.0.1
@400000005a5f43d631eb1b2c 2018.01.17 07:38:36 LOG5[18791:139651368576960]: Could not load DH parameters from /service/imap/ssl/imapd.pem
@400000005a5f43d631ee4f7c 2018.01.17 07:38:36 LOG4[18791:139651368576960]: Diffie-Hellman initialization failed
@400000005a5f43d631f29d0c 2018.01.17 07:38:36 LOG5[18791:139651368576960]: stunnel 4.29 on x86_64-redhat-linux-gnu with OpenSSL 1.0.1e-fips 11 Feb 2013
@400000005a5f43d631f669b4 2018.01.17 07:38:36 LOG5[18791:139651368576960]: Threading:PTHREAD SSL:ENGINE,FIPS Sockets:POLL,IPv6 Auth:LIBWRAP
@400000005a5f43d6320221b4 2018.01.17 07:38:36 LOG5[18791:139651368576960]: pop3s accepted connection from 127.0.0.1:40360
@400000005a5f43e2234814e4 2018.01.17 07:38:48 LOG5[18791:139651368576960]: Connection closed: 13503 bytes sent to SSL, 38 bytes sent to socket
@400000005a5f43e2235b27b4 tcpsvd: info: end 18791 exit 0
@400000005a5f43e2235b336c tcpsvd: info: status 0/40
@400000005a5f45370927fc8c tcpsvd: info: status 1/40
@400000005a5f4537092b5404 tcpsvd: info: pid 19167 from 192.168.200.110
@400000005a5f4537092dad94 tcpsvd: info: concurrency 19167 192.168.200.110 1/4
@400000005a5f4537092db94c tcpsvd: info: start 19167 0:192.168.200.2 ::192.168.200.110:51341 ./peers/192.168.200
@400000005a5f45370a99861c 2018.01.17 07:44:29 LOG5[19167:139848992675776]: Could not load DH parameters from /service/imap/ssl/imapd.pem
@400000005a5f45370a9bace4 2018.01.17 07:44:29 LOG4[19167:139848992675776]: Diffie-Hellman initialization failed
@400000005a5f45370a9e587c 2018.01.17 07:44:29 LOG5[19167:139848992675776]: stunnel 4.29 on x86_64-redhat-linux-gnu with OpenSSL 1.0.1e-fips 11 Feb 2013
@400000005a5f45370a9ff2a4 2018.01.17 07:44:29 LOG5[19167:139848992675776]: Threading:PTHREAD SSL:ENGINE,FIPS Sockets:POLL,IPv6 Auth:LIBWRAP
@400000005a5f45370aa7ddfc 2018.01.17 07:44:29 LOG5[19167:139848992675776]: pop3s accepted connection from 192.168.200.110:51341
@400000005a5f454312f20f3c 2018.01.17 07:44:41 LOG5[19167:139848992675776]: Connection closed: 13503 bytes sent to SSL, 38 bytes sent to socket
@400000005a5f45431305dd8c tcpsvd: info: end 19167 exit 0
@400000005a5f45431305e944 tcpsvd: info: status 0/40