"Timeout of session for" in auth.log every 8 minutes

On one of my Virtualmin hosting VMs I just found these entries in the auth.log, recurring every 8 minutes:

Oct 7 06:42:10 orion webmin[3885]: Timeout of session for

Nothing is given after the "for". There's nothing suspicious at the time in miniserv.log or Webmin's debug.log. Any idea where those entries might come from? My first idea was a break-in attempt, but the entries occur too regularly for that.

Status: 
Closed (fixed)

Comments

That's wierd, it looks like those log messages are due to session database entries being cleared. I don't think this indicates a breakin attempt, but may indicate a bug elsewhere..

Are you using the Virtualmin feature to automatically switch from the root login to domain owner permissions?

Hey Jamie, thanks for reply!

I also don't think it's a break-in attempt. It's occurring too regularly for that, exactly one entry every 5-8 minutes.

As for your question, I'm afraid I don't know what feature you mean with "automatically switching from root login to domain owner permissions". Where would I configure/use that feature?

(I suppose, since I don't even know what feature you mean, that I'm not using it. :) Except it's automatically used if not configured otherwise.)

Mmh, I kinda seem to recall that at some point I saw a link "Switch to domain owner" in some menu. But I can't recall where that was, and when I search the Virtualmin built-in help for "Switch", I get no helpful results.

If you need further information or log excerpts, please let me know!

Yes, I'm referring to that "switch to domain user" link .. but if you don't ever use it, it is unlikely to be the cause of this issue.

If you go to Webmin -> Webmin Users -> View Login Sessions , what does the list of active sessions contain?

I usually don't use "switch to domain user", that's right. I just re-discovered where that link actually is... And that the feature "Webmin login" (logically) needs to be enabled for it to appear at all. :)

In "View Login Sessions", there is indeed an odd entry, one without a user name and IP address, and a garbled Login time:

Session ID              Webmin user    IP address          Logged in at   
JBDXF5nR6q/8ov1cS7p0b/  xxx.xxxxxxx    109.46.xxx.xxx  08/Oct/2012 17:58    View logs..
wu57BhdMTMQBOUjkff2EY/ root                 10.1.191.6        07/Oct/2012 11:15 View logs..
QuFiATdMKnJAc5GKzdt8A.                                                  01/Jan/1970 01:00   View logs..

(I x-ed out some valid data in the list, to protect my customers' privacy.)

When I click "View logs" for the odd entry, I get:

Actions from by user root in session QuFiATdMKnJAc5GKzdt8A. ..
Action                                  Module             User    Client Address   Date                Time   
Modified Webmin user root   Webmin Users   root     10.0.9.6           25/Dec/2011  13:36
Deleted virtual server [...]    Virtualmin Virtual Servers  root    10.0.9.6    25/Dec/2011 13:29
Started FTP server                Virtualmin Virtual Servers    root    87.79.76.199    24/Dec/2011 12:52

Is it actually possible that this garbled session is around since December 2011?!

I recall that there was a hacking incident last year one day before x-mas eve which required some cleanup, and the log entries there look like the remainder of that cleanup. (If I recall correctly, I started the FTP server back up which I had taken down when the hacking break-in started, configured the root user to be allowed only from certain IP addresses and deleted a compromised domain.)

When clicking on the session ID to, as the screen tells me, "cancel the session and force the user to log in again", it takes about 10 seconds until the page reloads, and then the session is still there. I'll post some debug log entries in a bit.

Here's the debug.log contents when I click the session ID to delete it:

18155 [08/Oct/2012 23:32:07.055984] - 10.1.191.6 - START "script=delete_session.cgi"
18155 [08/Oct/2012 23:32:07.056153] - 10.1.191.6 - READ "/etc/webmin/miniserv.conf"
18155 [08/Oct/2012 23:32:07.056515] root 10.1.191.6 - READ "/etc/webmin/acl/config"
18155 [08/Oct/2012 23:32:07.056994] root 10.1.191.6 - READ "/usr/share/webmin/virtual-server-theme/config"
18155 [08/Oct/2012 23:32:07.058264] root 10.1.191.6 - READ "/etc/webmin/custom-lang"
18155 [08/Oct/2012 23:32:07.058994] root 10.1.191.6 - READ "/etc/webmin/acl/custom-lang"
18155 [08/Oct/2012 23:32:07.059693] root 10.1.191.6 - READ "/etc/webmin/module.infos.cache"
18155 [08/Oct/2012 23:32:07.079890] root 10.1.191.6 - READ "/usr/share/webmin//defaultacl"
18155 [08/Oct/2012 23:32:07.080121] root 10.1.191.6 - READ "/etc/webmin/root.acl"
18155 [08/Oct/2012 23:32:07.080363] root 10.1.191.6 - READ "/etc/webmin//root.acl"
18155 [08/Oct/2012 23:32:07.080595] root 10.1.191.6 - READ "/etc/webmin/installed.cache"
18155 [08/Oct/2012 23:32:07.081785] root 10.1.191.6 - READ "/usr/share/webmin/acl/module.info"
18155 [08/Oct/2012 23:32:07.082127] root 10.1.191.6 - READ "/etc/webmin/webmin.cats"
18155 [08/Oct/2012 23:32:07.082267] root 10.1.191.6 - READ "/etc/webmin/webmin.descs"
18155 [08/Oct/2012 23:32:07.084765] root 10.1.191.6 acl READ "/usr/share/webmin/acl/defaultacl"
18155 [08/Oct/2012 23:32:07.085084] root 10.1.191.6 acl READ "/etc/webmin/acl/root.acl"
18155 [08/Oct/2012 23:32:07.085469] root 10.1.191.6 acl KILL "signal=HUP pids=18090"
18155 [08/Oct/2012 23:32:11.090136] root 10.1.191.6 acl TCP "host=127.0.0.1 port=10000"
18397 [08/Oct/2012 23:32:12.112835] - - - START "script=webmincron.pl"
18397 [08/Oct/2012 23:32:12.113029] - - - READ "/etc/webmin/miniserv.conf"
18397 [08/Oct/2012 23:32:12.113369] - - - READ "/etc/webmin/webmincron/config"
18397 [08/Oct/2012 23:32:12.113760] - - - READ "/usr/share/webmin/virtual-server-theme/config"
18155 [08/Oct/2012 23:32:12.090680] root 10.1.191.6 acl TCP "host=127.0.0.1 port=10000"
18155 [08/Oct/2012 23:32:12.115523] root 10.1.191.6 - STOP "runtime=5"
18397 [08/Oct/2012 23:32:12.115013] - - - READ "/etc/webmin/custom-lang"
18397 [08/Oct/2012 23:32:12.122246] - - - READ "/etc/webmin/webmincron/custom-lang"
18397 [08/Oct/2012 23:32:12.122650] - - - READ "/etc/webmin/module.infos.cache"
18397 [08/Oct/2012 23:32:12.140158] - - - READ "/usr/share/webmin//defaultacl"
18397 [08/Oct/2012 23:32:12.140387] - - - READ "/etc/webmin/.acl"
18397 [08/Oct/2012 23:32:12.140571] - - - READ "/etc/webmin/installed.cache"
18397 [08/Oct/2012 23:32:12.142538] - - webmincron READ "/usr/share/webmin/cron/module.info"
18397 [08/Oct/2012 23:32:12.142842] - - webmincron READ "/etc/webmin/webmin.cats"
18397 [08/Oct/2012 23:32:12.142967] - - webmincron READ "/etc/webmin/webmin.descs"
18397 [08/Oct/2012 23:32:12.149522] - - - READ "/etc/webmin/cron/config"
18397 [08/Oct/2012 23:32:12.150536] - - - READ "/etc/webmin/cron/custom-lang"
18397 [08/Oct/2012 23:32:12.159616] - - cron READ "/usr/share/webmin/cron/defaultacl"
18397 [08/Oct/2012 23:32:12.160653] - - - UNLINK "/tmp/.webmin/3798_18397_1_webmincron.pl"
18397 [08/Oct/2012 23:32:12.160793] - - - UNLINK "/tmp/.webmin/506168_18397_2_webmincron.pl"
18397 [08/Oct/2012 23:32:12.160896] - - - STOP "runtime=0"
18398 [08/Oct/2012 23:32:12.497969] - 10.1.191.6 - START "script=list_sessions.cgi"
18398 [08/Oct/2012 23:32:12.498149] - 10.1.191.6 - READ "/etc/webmin/miniserv.conf"
18398 [08/Oct/2012 23:32:12.498525] root 10.1.191.6 - READ "/etc/webmin/acl/config"
18398 [08/Oct/2012 23:32:12.498953] root 10.1.191.6 - READ "/usr/share/webmin/virtual-server-theme/config"
18398 [08/Oct/2012 23:32:12.500175] root 10.1.191.6 - READ "/etc/webmin/custom-lang"
18398 [08/Oct/2012 23:32:12.500879] root 10.1.191.6 - READ "/etc/webmin/acl/custom-lang"
18398 [08/Oct/2012 23:32:12.501569] root 10.1.191.6 - READ "/etc/webmin/module.infos.cache"
18398 [08/Oct/2012 23:32:12.521079] root 10.1.191.6 - READ "/usr/share/webmin//defaultacl"
18398 [08/Oct/2012 23:32:12.521287] root 10.1.191.6 - READ "/etc/webmin/root.acl"
18398 [08/Oct/2012 23:32:12.521513] root 10.1.191.6 - READ "/etc/webmin//root.acl"
18398 [08/Oct/2012 23:32:12.521728] root 10.1.191.6 - READ "/etc/webmin/installed.cache"
18398 [08/Oct/2012 23:32:12.522822] root 10.1.191.6 - READ "/usr/share/webmin/acl/module.info"
18398 [08/Oct/2012 23:32:12.523152] root 10.1.191.6 - READ "/etc/webmin/webmin.cats"
18398 [08/Oct/2012 23:32:12.523276] root 10.1.191.6 - READ "/etc/webmin/webmin.descs"
18398 [08/Oct/2012 23:32:12.525669] root 10.1.191.6 acl READ "/usr/share/webmin/acl/defaultacl"
18398 [08/Oct/2012 23:32:12.525967] root 10.1.191.6 acl READ "/etc/webmin/acl/root.acl"
18398 [08/Oct/2012 23:32:12.590585] root 10.1.191.6 acl READ "/etc/hostname"
18398 [08/Oct/2012 23:32:12.590793] root 10.1.191.6 acl CMD "cmd=hostname"
18398 [08/Oct/2012 23:32:12.593872] root 10.1.191.6 acl CMD "cmd=hostname -f"
18398 [08/Oct/2012 23:32:12.660056] root 10.1.191.6 acl READ "/usr/share/webmin/webminlog/module.info"
18398 [08/Oct/2012 23:32:12.672903] root 10.1.191.6 - STOP "runtime=0"

And this gets logged in auth.log:

Oct  8 23:32:07 orion perl: pam_unix(webmin:auth): authentication failure; logname= uid=0 euid=0 tty= ruser= rhost=  user=root
Oct  8 23:32:07 orion perl: pam_winbind(webmin:auth): getting password (0x00000388)
Oct  8 23:32:07 orion perl: pam_winbind(webmin:auth): pam_get_item returned a password
Oct  8 23:32:07 orion perl: pam_winbind(webmin:auth): request wbcLogonUser failed: WBC_ERR_AUTH_ERROR, PAM error: PAM_USER_UNKNOWN (10), NTSTATUS: NT_STATUS_NO_SUCH_USER, Error
Oct  8 23:32:09 orion webmin[18090]: Webmin starting

The simplest way to clear this invalid session permanently is to SSH in as root and run :

/etc/webmin/stop
rm /var/webmin/sessiondb.*
/etc/webmin/start

This will force all logged-in users to re-authenticate though.

The fact that this session cannot be deleted suggests that the session DBM file is corrupt somehow..

I grepped for the session IDs, and found them in /var/webmin/sessiondb.pag. That file is owned by root:bin and has permissions 700.

Roger that, forcing users to log in again is no problem. I'll copy the corrupt DB file away in case you need it for debugging purposes! Let me know in that case. :)

So, the reason for those "Timeout" log entries is that every ~8 minutes Webmin tried to clear that garbled session from last xmas from the DB, and failed, so it tried again and again?

Yes, the log entries are due to Webmin trying and failing continually to delete a corrupt session entry,

The next Webmin release will handle this case better.

Holy cow. So this has been going on for a year and I didn't notice it until just now. I should read my logs better. :|

Actually, the reason why I noticed it just now is because I installed - for that exact reason - "logcheck", which promptly listed those entries as "unknown, better check what's going on there".

In any case, thanks a lot for your time and help, and case closed! :)

Automatically closed -- issue fixed for 2 weeks with no activity.