Multiple log entries: "session opened for user popuser"

[chrismcb]

Hi,

I've been seeing this for some time now, but never got round to looking further into it.
This is taken from /var/log/secure:

Code: Select all

su: pam_unix(su-l:session): session opened for user popuser by (uid=0)

Logwatch also lists:

Code: Select all

su-l: 
  Unknown Entries: 
  session closed for user popuser: 1448 Time(s) 
  session opened for user popuser by (uid=0): 1448 Time(s) 

The reason I haven't bothered doing anything is that on a Google search, a few people have the same issue and Igor at Parallels says "postfix is corrupt" - which I don't believe is the case.

http://forum.parallels.com/showthread.php?t=107672
http://forum.parallels.com/showthread.php?t=259904
http://forum.parallels.com/showthread.php?t=109440

No one seems to know what is causing it.

Anyone else see this or have an idea what might be causing it?

I'm running Centos 5.8, Plesk 11.0.9 Update #12, ASL 3.0.34-1 with everything up to date.

[faris]

The "session opened" and "session closed" is perfectly normal. Every time there's an email login, you get that pair shown. It is not a bug and is not something that will be fixed. Igor's comments are regarding something else, I think.

The issue is just that logwatch doesn't know how to deal with them. I don't think they used to be in /var/log/secure - they were in one of the other logs.

[chrismcb]

Sorry, never ticked the box for an email on notify...

Faris, I do note these throughout the day in general patterns, but the size of the server doesn't warrant the amount of connections.

The connections are coming in during the night, in very quick succession - to me, it looks automated, and there are thousands of them.

My /var/log/secure is full of these, just about each night, - last night from 4:50am to 5:40am.

I do believe something is causing them.


Something perhaps ASL could look at and block?
The problem is, there are no IP addresses listed in the logs:

Excerpt:

Code: Select all

Sep 16 05:38:31 server su: pam_unix(su-l:session): session closed for user popuser
Sep 16 05:38:31 server su: pam_unix(su-l:session): session opened for user popuser by (uid=0)
Sep 16 05:38:33 server su: pam_unix(su-l:session): session closed for user popuser
Sep 16 05:38:33 server su: pam_unix(su-l:session): session opened for user popuser by (uid=0)
Sep 16 05:38:34 server su: pam_unix(su-l:session): session closed for user popuser
Sep 16 05:38:34 server su: pam_unix(su-l:session): session opened for user popuser by (uid=0)
Sep 16 05:38:36 server su: pam_unix(su-l:session): session closed for user popuser
Sep 16 05:38:36 server su: pam_unix(su-l:session): session opened for user popuser by (uid=0)
Sep 16 05:38:37 server su: pam_unix(su-l:session): session closed for user popuser
Sep 16 05:38:37 server su: pam_unix(su-l:session): session opened for user popuser by (uid=0)
Sep 16 05:38:38 server su: pam_unix(su-l:session): session closed for user popuser
Sep 16 05:38:39 server su: pam_unix(su-l:session): session opened for user popuser by (uid=0)
Sep 16 05:38:40 server su: pam_unix(su-l:session): session closed for user popuser
Sep 16 05:38:40 server su: pam_unix(su-l:session): session opened for user popuser by (uid=0)
Sep 16 05:38:41 server su: pam_unix(su-l:session): session closed for user popuser
Sep 16 05:38:41 server su: pam_unix(su-l:session): session opened for user popuser by (uid=0)
Sep 16 05:38:43 server su: pam_unix(su-l:session): session closed for user popuser
Sep 16 05:38:43 server su: pam_unix(su-l:session): session opened for user popuser by (uid=0)
Sep 16 05:38:44 server su: pam_unix(su-l:session): session closed for user popuser
Sep 16 05:38:44 server su: pam_unix(su-l:session): session opened for user popuser by (uid=0)
Sep 16 05:38:45 server su: pam_unix(su-l:session): session closed for user popuser
Sep 16 05:38:45 server su: pam_unix(su-l:session): session opened for user popuser by (uid=0)
Sep 16 05:38:47 server su: pam_unix(su-l:session): session closed for user popuser
Sep 16 05:38:47 server su: pam_unix(su-l:session): session opened for user popuser by (uid=0)
Sep 16 05:38:49 server su: pam_unix(su-l:session): session closed for user popuser
Sep 16 05:38:49 server su: pam_unix(su-l:session): session opened for user popuser by (uid=0)
Sep 16 05:38:50 server su: pam_unix(su-l:session): session closed for user popuser
Sep 16 05:38:51 server su: pam_unix(su-l:session): session opened for user popuser by (uid=0)
Sep 16 05:38:52 server su: pam_unix(su-l:session): session closed for user popuser
Sep 16 05:38:52 server su: pam_unix(su-l:session): session opened for user popuser by (uid=0)
Sep 16 05:38:53 server su: pam_unix(su-l:session): session closed for user popuser
Sep 16 05:38:53 server su: pam_unix(su-l:session): session opened for user popuser by (uid=0)
Sep 16 05:38:55 server su: pam_unix(su-l:session): session closed for user popuser
Sep 16 05:38:55 server su: pam_unix(su-l:session): session opened for user popuser by (uid=0)
Sep 16 05:38:56 server su: pam_unix(su-l:session): session closed for user popuser
Sep 16 05:38:56 server su: pam_unix(su-l:session): session opened for user popuser by (uid=0)
Sep 16 05:38:58 server su: pam_unix(su-l:session): session closed for user popuser
Sep 16 05:38:58 server su: pam_unix(su-l:session): session opened for user popuser by (uid=0)
Sep 16 05:38:59 server su: pam_unix(su-l:session): session closed for user popuser

[faris]

Is there no matching login failure in /usr/local/psa/var/log/messages?
That's where asl will be logging for login failures and will shun if need be (depending on settings).

If not then maybe something is connecting to port 110 (on the assumption that that's what would cause a popuser session to be opened/closed) and then not doing anything.

tcpdump for port 110 will reveal more, if there's anything happening there. Using netstat may also help pinpoint things.

Of course it might also be an automated watchdog-type thing, checking that pop3 is up?
A bit too frequent for that really, but still a possibility I suppose.

[chrismcb]

I checked /var/log/psa/mailllog (was that where you meant?) and at 05:38:xx there are 10 lines of normal logging.

/var/log/messages shows nothing.

Since it's during the night, I don't quite fancy sitting up waiting for it to run a tcpdump - it'd quickly fill up disk space if left on all night - unless there's a better option?


I do have monitoring stuff set up - but they're shown in the logs, so i know it's not it.


Got me kinda stumped here...

[faris]

How about a cron script that triggers the TCPdump for 2 hours with things limited to X logfiles of Y Mb each? If you've not looked at it in detail before, tcpdump has this limiting capability built-in. Basically it cycles through X logfiles, overwriting the oldest once it gets to X, and keeping each logfile no larger than Y.

Unfortunately I have no idea how to make a script run for X minutes/hours then stop.

The following appears to be a script that might work:
http://www.varesano.net/blog/fabio/exec ... ash-script

But even if it doesn't, the worst that will happen is that you'll have X files of YMb on your hands.
Stick to something small like 2Mb and 10 files and you'll be fine.

[chrismcb]

Great, thanks.

Using the script from the link you gave, I've come up with this line in the Crontab:

Code: Select all

*/10      5       *       *       *       /root/sleeper.sh "/usr/sbin/tcpdump -n dst port 110" 30 >> /root/capture.txt

Which should:

• Run every 10 minutes
• At 5am
• TCP Dump IP addresses (not hostnames) with the -n
• For traffic connecting to port 110
• For 30 seconds
• and append to a txt file

Testing it out now, but hopefully will have some data by tomorrow morning.


Thanks

[chrismcb]

After picking this up again, I've finally found out what is causing it.

It is sa-learn - part of a cron.daily script for Plesk - 50plesk-daily - which goes through mailboxes and learns what is spam and what is ham.

http://spamassassin.apache.org/full/3.1 ... learn.html

Since this is a legitimate use, is there anything Atomicorp can recommend here to stop this inflating level 3 logs without disabling rules 5501/5502?


I surely can't be the only one with this issue!

[faris]

Oooh! Interesting.

The annoying thing is that I don't know of a way to leverage the plesk sa-learn process if you aren't using the plesk spamassassin implementation. Or can one simply set up some spam@ and ham@ mailboxes or something? Or does this process do something else entirely that I'm not aware of?

It is very wasteful in terms of CPU cycles if it isn't doing any good.

[chrismcb]

I also have SpamGuardian from 4PSA - I wonder if it is only with this that the feature becomes useful/available?

If you create a junk_learn and ham_learn folder in your IMAP folders, it will go through each day and empty them - learning from your classifications.