No automatic Logout of users after idle time exceeded



  • Hello,

    my Captive portal is set up. I produced the voucher and set the idle time to 30 min., the hard idle time is set to 90 min. Logging in with the vouchers works perfectly. Automatic logout of users unfortunately not.

    The interesting thing: After any reconfig of the captive portals all logged-in users, probably idle since several hours, are thrown out promptly - but not automatically.

    One maybe not so relevant observation: the test login-access from the pfsense server (192.168.178.1:8000) to the login screen (192.168.178.1:8000) is recorded in the log. The timeout happens automatically within a minute. Is this perhaps because the check-process, whether a user is too long idle, is different on the server?

    Which hidden config file can I check, please?

    Requesting for a helpful advice.
    Michael


  • Netgate

    What version of pfSense? What are all the configs on your portal?

    I have never used idle timeout with vouchers.  It certainly works fine on "no authentication."

    Vouchers are set to allow access for a certain period of time so I wouldn't be surprised if that overrode the timeouts, or if the captive portal prune process ignored voucher sessions when walking the table looking for sessions to terminate.



  • My realease is 2.1.5. The vouchers are valid for half of a year. In between, the students change on the computers. For the sake of security I kick them after the idle time "soft and hard".

    The auth.log has things like that:

    Oct 22 14:45:12 pfsense logportalauth[37277]: Voucher login good for 288000 min.: k123456, 00:0f:fe:6b:53:a4, 192.168.123.199
    

    And after I touch the portal-config via web:

    
    Oct 22 19:31:29 pfsense logportalauth[36135]: Reconfiguring captive portal(Seminar).
    Oct 22 19:32:30 pfsense logportalauth[37760]: TIMEOUT: 123123, 5c:8d:4e:3b:c3:9d, 192.168.123.173
    
    

    Strange, isn't it?


  • Netgate

    minicron should be running "/etc/rc.prunecaptiveportal Seminar" every 60 seconds.  All that does is implement some locking to make sure only one runs at a time and calls captiveportal_prune_old();  Looking at that function, it should do what you want.  If the lock fails it logs "Skipping CP prunning process because previous/another instance is already running"

    You should be able to run /etc/rc.prunecaptiveportal from diagnostics->command prompt if you want to see what it does.



  • minicron is running, see the 8th line:

    
    [2.1.5-RELEASE][admin@pfsense.localdomain]/root(9): ps ax | grep minicron
     3961  ??  Is     0:00.00 /usr/local/bin/minicron 240 /var/run/ping_hosts.pid /usr/local/bin/ping_hosts.sh
     4435  ??  I      0:00.08 minicron: helper /usr/local/bin/ping_hosts.sh  (minicron)
     4438  ??  Is     0:00.00 /usr/local/bin/minicron 3600 /var/run/expire_accounts.pid /etc/rc.expireaccounts
     4851  ??  I      0:00.01 minicron: helper /etc/rc.expireaccounts  (minicron)
     5095  ??  Is     0:00.00 /usr/local/bin/minicron 86400 /var/run/update_alias_url_data.pid /etc/rc.update_alias_url_data
     5578  ??  I      0:00.00 minicron: helper /etc/rc.update_alias_url_data  (minicron)
    51959  ??  Is     0:00.00 /usr/local/bin/minicron 60 /var/run/cp_prunedb_seminar.pid /etc/rc.prunecaptiveportal seminar
    52115  ??  I      0:00.34 minicron: helper /etc/rc.prunecaptiveportal seminar (minicron)
    33775   0  S+     0:00.00 grep minicron
    [2.1.5-RELEASE][admin@pfsense.localdomain]/root(10):
    
    

    The locking doesn't leave anything n the system.log. Is this the right log to look into?

    The last command you mentioned gives no output at all:

    
    [2.1.5-RELEASE][admin@pfsense.localdomain]/root(14): /etc/rc.prunecaptiveportal
    [2.1.5-RELEASE][admin@pfsense.localdomain]/root(15):
    
    

    I changed configure_cron()  in the  /etc/inc/services.inc before, following this posting :
    https://forum.pfsense.org/index.php?action=post;quote=433012;topic=69606.15;last_msg=446628.
    It is now like this:

    
            /* do a HUP kill to force sync changes */
            #       exec('/bin/pkill -HUP cron'); #### MIST
            sigkillbypid("{$g['varrun_path']}/cron.pid", "HUP");
            conf_mount_ro();
    }
    
    

    I rebooted and maybe (?) therefore it run one day without problems. But now the problems is as in the beginning: users get the timeout after a few seconds.

    I'm greatful for any hint!
    Michael



  • By the way: restrating squid and squidguard and saving the captive-portal-config-values doesn't change the phenomenon:

    
    Oct 25 12:38:13 pfsense logportalauth[56927]: LOGIN: gd, 9c:b6:54:0b:f0:37, 192.168.123.1
    Oct 25 12:38:32 pfsense logportalauth[48174]: TIMEOUT: gd, 9c:b6:54:0b:f0:37, 192.168.123.1
    Oct 25 13:03:22 pfsense squid[18640]: Squid Parent: child process 19059 exited with status 0
    Oct 25 13:03:30 pfsense squid[5423]: Squid Parent: child process 5661 started
    Oct 25 13:03:43 pfsense squid[5661]: The url_rewriter helpers are crashing too rapidly, need help!
    Oct 25 13:03:43 pfsense squid[5423]: Squid Parent: child process 5661 exited due to signal 6
    Oct 25 13:03:46 pfsense squid[5423]: Squid Parent: child process 12163 started
    Oct 25 13:04:35 pfsense logportalauth[65658]: LOGIN: gd, 9c:b6:54:0b:f0:37, 192.168.123.1
    Oct 25 13:04:37 pfsense logportalauth[42373]: TIMEOUT: gd, 9c:b6:54:0b:f0:37, 192.168.123.1
    Oct 25 13:04:45 pfsense logportalauth[56927]: LOGIN: gd, 9c:b6:54:0b:f0:37, 192.168.123.1
    Oct 25 13:05:37 pfsense logportalauth[67445]: TIMEOUT: gd, 9c:b6:54:0b:f0:37, 192.168.123.1
    Oct 25 13:06:57 pfsense logportalauth[73618]: Reconfiguring captive portal(Seminar).
    Oct 25 13:07:03 pfsense logportalauth[91946]: LOGIN: gd, 9c:b6:54:0b:f0:37, 192.168.123.1
    Oct 25 13:07:58 pfsense logportalauth[15269]: TIMEOUT: gd, 9c:b6:54:0b:f0:37, 192.168.123.1
    [2.1.5-RELEASE][admin@pfsense.localdomain]/root(88):
    
    


  • I'm confused. After a reboot everything seems ok:

    
    Oct 25 13:07:03 pfsense logportalauth[91946]: LOGIN: gd, 9c:b6:54:0b:f0:37, 192.168.123.1
    Oct 25 13:07:58 pfsense logportalauth[15269]: TIMEOUT: gd, 9c:b6:54:0b:f0:37, 192.168.123.1
    Oct 25 20:36:48 pfsense squid[50119]: Squid Parent: child process 78876 exited with status 0
    Oct 25 20:36:51 pfsense squid[22823]: Squid Parent: child process 23067 started
    Oct 25 20:38:35 pfsense logportalauth[51832]: LOGIN: gd, 9c:b6:54:0b:f0:37, 192.168.123.1
    [2.1.5-RELEASE][admin@pfsense.localdomain]/root(40): date
    Sat Oct 25 20:44:46 CEST 2014
    [2.1.5-RELEASE][admin@pfsense.localdomain]/root(41):
    
    

    Now I get the following minicron-processes:

    
    [2.1.5-RELEASE][admin@pfsense.localdomain]/root(37): ps axu | grep minicron
    root   48625  0.0  0.0  3264   972  ??  Is    8:36PM   0:00.00 /usr/local/bin/minicron 60 /var/run/cp_prunedb_seminar.pid /etc/rc.prunecaptiveportal seminar
    root   48780  0.0  0.0  3264  1016  ??  I     8:36PM   0:00.00 minicron: helper /etc/rc.prunecaptiveportal seminar (minicron)
    root   66477  0.0  0.0  3264   976  ??  Is    8:36PM   0:00.00 /usr/local/bin/minicron 240 /var/run/ping_hosts.pid /usr/local/bin/ping_hosts.sh
    root   67583  0.0  0.0  3264  1024  ??  I     8:36PM   0:00.00 minicron: helper /usr/local/bin/ping_hosts.sh  (minicron)
    root   67858  0.0  0.0  3264   976  ??  Is    8:36PM   0:00.00 /usr/local/bin/minicron 3600 /var/run/expire_accounts.pid /etc/rc.expireaccounts
    root   68232  0.0  0.0  3264  1024  ??  I     8:36PM   0:00.00 minicron: helper /etc/rc.expireaccounts  (minicron)
    root   68385  0.0  0.0  3264   976  ??  Is    8:36PM   0:00.00 /usr/local/bin/minicron 86400 /var/run/update_alias_url_data.pid /etc/rc.update_alias_url_data
    root   68980  0.0  0.0  3264  1024  ??  I     8:36PM   0:00.00 minicron: helper /etc/rc.update_alias_url_data  (minicron)
    root   13166  0.0  0.0  3468  1252   0  S+    8:42PM   0:00.00 grep minicron
    [2.1.5-RELEASE][admin@pfsense.localdomain]/root(38):
    
    

    Any ideas, please?



  • I'm kind of lost. I found out, that 30 min after a fresh reboot the first timeout happens. After that, the users get kicked in under 60 sec. and not within the regular idle time of 30 min as I configured (90 min hard idle time). Here is the proof with the auth-log:

    
    19:43 Fresh reboot the Pfsense
    
    

    The first login/logout works without problems:

    
    Oct 26 19:45:18 pfsense logportalauth[56225]: LOGIN: gd, 9c:b6:54:0b:f0:37, 192.168.123.1
    Oct 26 19:49:14 pfsense logportalauth[56225]: DISCONNECT: gd, 9c:b6:54:0b:f0:37, 192.168.123.1
    
    

    Here comes another login…

    
    Oct 26 19:49:26 pfsense logportalauth[56225]: LOGIN: gd, 9c:b6:54:0b:f0:37, 192.168.123.1
    
    

    … and exactly 30 min after the end of the reboot:

    
    Oct 26 20:13:42 pfsense logportalauth[50109]: TIMEOUT: gd, 9c:b6:54:0b:f0:37, 192.168.123.1
    
    

    … no chance for 30 minutes. Everytime I get kiced under 60 secs:

    
    Oct 26 20:22:27 pfsense logportalauth[56225]: LOGIN: gd, 9c:b6:54:0b:f0:37, 192.168.123.1
    Oct 26 20:22:44 pfsense logportalauth[90022]: TIMEOUT: gd, 9c:b6:54:0b:f0:37, 192.168.123.1
    
    

    The same with a voucher:

    
    Oct 26 20:27:45 pfsense logportalauth[56225]: Voucher login good for 269380 min.: m12345, 9c:b6:54:0b:f0:37, 192.168.123.1
    Oct 26 20:28:45 pfsense logportalauth[61339]: TIMEOUT: m12345, 9c:b6:54:0b:f0:37, 192.168.123.1
    
    

    I run out of ideas. Any helpful hint would be appreciated very much.
    Michael



  • An idea.

    You found the function captiveportal_prune_old() ?
    Based on logic in there, users (vouchers), are disconnected.
    Its rather easy that add you own portal log lines - add many of them, and remember: add as much variables as you can find.

    This will nail down the the point where and why users are disconnected.


  • Netgate

    I've been sort of racking my head trying to figure out what you could have done to make it do this and I come up empty. Thought maybe CP wanted expirations in seconds but nope.  I wonder if there's something missing in captiveportal.inc that is missing a multiplier for minutes to seconds (or something) in your specific use case.

    That's a good idea.  Search captiveportal.inc for that particular TIMEOUT log entry and toss some of the variables in there.  CP is just a bunch of tests for all sorts of different things.  It hasn't been uncommon for things to work great for almost everyone, but one guy adds, say, MAC Passthrough addition with username and it behaves completely differently.  I thought they were pretty much all ironed out though.

    Personally, I am using no authentication (just click through a terms page) with an 18-hour idle timeout on one and vouchers with MAC passthrough with username on another with no timeouts other than the voucher expiring and they both work flawlessly.

    What do you get when you test the voucher code that's getting immediately timed out in Services->CP->Test Vouchers??



  • @miichael  : in your previous message you mentioned some log lines.
    All the log lines have two thing in common: the same MAC and same IP.

    It look to me, when you user-name login times out here:

    Oct 26 20:13:42 pfsense logportalauth[50109]: TIMEOUT: gd, 9c:b6:54:0b:f0:37, 192.168.123.1
    

    a new try will result in an immediate logout.

    Its like: the reference of the session is still in the database that captiveportal_prune_old() (and more functions) uses to do their book-keeping.
    This would explain that
    => the user get logged out right away if a sessions is present for more then IDLE_TIMEOUT
    => user login or voucher, the start time will be the first occurrence of the login, so vouchers will time out also, because the sessions is more then 30 minutes (even when logged in a couple of seconds before (again))
    => when timed out, sessions isn't removed, so it will happen every time for that MAC /IP.
    => reboot will wipe database file, so when it boots, all will work a first time.
    => (check this) a portal reconfigure will flush the database also ? (I guess not)



  • Thank you very much for your suggestions. I'm going to take a close look onto your ideas.

    But first I have to give you my recent observation: As you can see in my logs, I logged every time onto the Pfsense-Server. I logged by klicking on the CP-Login-Page 192.168.123.1:8000 (using a SSH-tunnel to the Server). It resulted in a login in the auth.log. As you see, I was thrown out within 60 Sec. This was also mentioned in the log. Today I used the local computers.
    Result:

    
    Oct 28 08:00:02 pfsense logportalauth[723]: LOGIN: gd, 02:0f:b5:c8:2f:1f, 192.168.123.106
    Oct 28 08:32:01 pfsense logportalauth[55266]: TIMEOUT: gd, 02:0f:b5:c8:2f:1f, 192.168.123.106
    Oct 28 08:54:31 pfsense logportalauth[723]: Voucher login good for 269240 min.: xyxyxy, 84:a6:c8:38:26:ba, 192.168.123.147
    Oct 28 10:08:49 pfsense logportalauth[68280]: xyxyxy invalid: TYPO illegal character (U) found in 4U2RG8 !!
    Oct 28 10:08:49 pfsense logportalauth[68280]: FAILURE: xyxyxy, 5c:8d:4e:3b:c3:9d, 192.168.123.173
    Oct 28 10:09:18 pfsense logportalauth[68280]: Voucher login good for 269165 min.: xyxyxy, 5c:8d:4e:3b:c3:9d, 192.168.123.173
    Oct 28 10:20:36 pfsense logportalauth[7555]: Reconfiguring captive portal(Seminar).
    Oct 28 10:21:37 pfsense logportalauth[91985]: TIMEOUT: xyxyxy, 84:a6:c8:38:26:ba, 192.168.123.147
    Oct 28 10:54:43 pfsense logportalauth[81922]: TIMEOUT: xyxyxy, 5c:8d:4e:3b:c3:9d, 192.168.123.173
    Oct 28 11:19:44 pfsense logportalauth[23891]: Voucher login good for 269094 min.: xyxyxy, 84:a6:c8:38:26:ba, 192.168.123.147
    Oct 28 11:19:59 pfsense logportalauth[23891]: CONCURRENT LOGIN - REUSING OLD SESSION: xyxyxy, 84:a6:c8:38:26:ba, 192.168.123.147
    Oct 28 11:19:59 pfsense logportalauth[23891]: Voucher login good for 269094 min.: xyxyxy, 84:a6:c8:38:26:ba, 192.168.123.147
    Oct 28 12:04:56 pfsense logportalauth[80944]: TIMEOUT: xyxyxy, 84:a6:c8:38:26:ba, 192.168.123.147
    Oct 28 12:37:36 pfsense logportalauth[97699]: Voucher login good for 269017 min.: xyxyxy, 84:a6:c8:38:26:ba, 192.168.123.147
    Oct 28 13:23:11 pfsense logportalauth[43792]: TIMEOUT: xyxyxy, 84:a6:c8:38:26:ba, 192.168.123.147
    Oct 28 13:28:47 pfsense logportalauth[43520]: Reconfiguring captive portal(Seminar).
    Oct 28 14:12:04 pfsense logportalauth[43039]: Voucher login good for 268922 min.: xyxyxy, 84:a6:c8:38:26:ba, 192.168.123.147
    Oct 28 14:13:46 pfsense logportalauth[43039]: Voucher login good for 268920 min.: xyxyxy, 5c:8d:4e:3b:c3:9d, 192.168.123.173
    Oct 28 15:05:51 pfsense logportalauth[43039]: DISCONNECT: xyxyxy, 84:a6:c8:38:26:ba, 192.168.123.147
    Oct 28 15:34:11 pfsense logportalauth[27574]: TIMEOUT: xyxyxy, 5c:8d:4e:3b:c3:9d, 192.168.123.173
    Oct 28 15:34:44 pfsense logportalauth[43301]: LOGIN: gd, f0:de:f1:be:6f:f1, 192.168.123.108
    Oct 28 16:24:20 pfsense logportalauth[44795]: TIMEOUT: gd, f0:de:f1:be:6f:f1, 192.168.123.108
    
    

    Unbelievable, isn't it? It seems to work! Everywhere - except on the Pf-machine! Well, I searched the responsible inc-File to learn, why it is so. But this is goint to take longer. In the moment I'm just happy, that it works (and possibly worked before).

    Michael