Bug #8136: Session Timeout because of chromes "Throttle Javascript timers in background." - Wt - Redmine

Actions

Copy link

Bug #8136

open

Session Timeout because of chromes "Throttle Javascript timers in background."

Added by Markus S over 3 years ago. Updated over 3 years ago.

Status:

New

Priority:

High

Assignee:

Target version:

Start date:

02/24/2021

Due date:

% Done:

Estimated time:

Description

Recently customers started complaining about being logged out automatically without doing anything. (it started about 3 weeks ago)
I started searching for similar problems and found the chrome feature "Throttle Javascript timers in background.".
chrome://flags/#intensive-wake-up-throttling
https://www.chromestatus.com/feature/4718288976216064

It appears the new feature was activated with the latest update.
Chrome changelog: 88.0.4324 -> Heavy throttling of chained JavaScript timers (https://en.wikipedia.org/wiki/Google_Chrome_version_history)

Forcing this setting disabled fixed the issue in every case we had.
So it is a workaround, but telling all users to set the flag is not a very good solution.

The session-timeout is set to 2 minutes, I am not sure if it would make a difference if it would be longer.
I tried to replicate the issue on my machine but I failed to do so.

The log just shows:

[2021-Feb-17 10:18:30.619] 21604 [/ VqHlxUqKF7iyiTvT] [info] "WebController: timeout: expiring"
[2021-Feb-17 10:18:30.625] 21604 [/ VqHlxUqKF7iyiTvT] [info] "Wt: session destroyed (#sessions = 0)"

I am not sure this can be "fixed" from your end, but maybe I am wrong?

Actions

Copy link

Updated by Korneel Dumon over 3 years ago

Can you say a bit more about the circumstances? Are you using a lot of WTimers? Or is it just Wt's internal use of timers?

It would be helpful if you have an example to reproduce this.

Actions

Copy link

Updated by Markus S over 3 years ago

Korneel Dumon wrote in #note-1:

Can you say a bit more about the circumstances? Are you using a lot of WTimers? Or is it just Wt's internal use of timers?

It would be helpful if you have an example to reproduce this.

Thank you for the quick response!

Our application only has one additional timer(also on a one minute interval) to WTs session "keep-alive" timer(As I understand it WTs timer runs every minute for a two minute session-timeout).
We noticed the problem on an different application too we only use in house, this app has only the session "keep-alive" timer.

I will try again to find steps to reproduce the issue.

Actions

Copy link

Updated by Markus S over 3 years ago

I have an example(But I guess any app would do):

class TestSessionTimeout : public Wt::WApplication
{
public:
    TestSessionTimeout( const Wt::WEnvironment& env )
        : Wt::WApplication( env )
    {
        auto c = root()->addNew< Wt::WContainerWidget >();
        auto l = c->setLayout( std::make_unique< Wt::WVBoxLayout >() );
        auto t = l->addWidget( std::make_unique< Wt::WText >( "Status: Loaded fresh at: " + Wt::WTime::currentTime().toString() ) );
        auto b = l->addWidget( std::make_unique< Wt::WPushButton >( "Change state" ), 0, Wt::AlignmentFlag::Left );
        b->clicked().connect([=]{ t->setText( "Status: Active session" ); });
    }
};

Run this example with a session-timeout of 120.
chrome://flags/#intensive-wake-up-throttling set to Enabled 10 Seconds after a tab is hidden (saves time)
restart chrome
open test app and click the button
open a new tab and got to some page (I tried with our company page www.bitfactory.at, likely not relevant)
minimize chrome (not sure if relevant)
Wait for about 10 minutes (if you enable logging for chrome you can spot it in the file, example follows) - Textfield will indicate page was reloaded

chrome_debug.log

[23092:32572:0224/163337.818:VERBOSE1:network_delegate.cc(32)] NetworkDelegate::NotifyBeforeURLRequest: http://127.0.0.1:9999/TestSimple   <- Page first loaded!
[23092:32572:0224/163337.841:VERBOSE1:network_delegate.cc(32)] NetworkDelegate::NotifyBeforeURLRequest: http://127.0.0.1:9999/TestSimple?wtd=Wz5kASIyGtfL9Vui&request=style&page=1
[23092:32572:0224/163337.863:VERBOSE1:network_delegate.cc(32)] NetworkDelegate::NotifyBeforeURLRequest: http://127.0.0.1:9999/TestSimple?wtd=Wz5kASIyGtfL9Vui&sid=126089462&webGL=true&scrW=1920&scrH=1080&tz=60&tzS=Europe%2FBerlin&htmlHistory=true&deployPath=%2FTestSimple&request=script&rand=68721485
[23092:32572:0224/163337.932:VERBOSE1:network_delegate.cc(32)] NetworkDelegate::NotifyBeforeURLRequest: http://127.0.0.1:9999/TestSimple?wtd=Wz5kASIyGtfL9Vui
[23092:32572:0224/163340.947:VERBOSE1:network_delegate.cc(32)] NetworkDelegate::NotifyBeforeURLRequest: http://127.0.0.1:9999/TestSimple?wtd=Wz5kASIyGtfL9Vui
[23092:32572:0224/163439.172:VERBOSE1:network_delegate.cc(32)] NetworkDelegate::NotifyBeforeURLRequest: http://127.0.0.1:9999/TestSimple?wtd=Wz5kASIyGtfL9Vui <- Session keep alive
[23092:32572:0224/163539.179:VERBOSE1:network_delegate.cc(32)] NetworkDelegate::NotifyBeforeURLRequest: http://127.0.0.1:9999/TestSimple?wtd=Wz5kASIyGtfL9Vui <- Session keep alive - 60 seconds later
[23092:32572:0224/163639.174:VERBOSE1:network_delegate.cc(32)] NetworkDelegate::NotifyBeforeURLRequest: http://127.0.0.1:9999/TestSimple?wtd=Wz5kASIyGtfL9Vui <- Session keep alive - 60 seconds later
[23092:32572:0224/163739.165:VERBOSE1:network_delegate.cc(32)] NetworkDelegate::NotifyBeforeURLRequest: http://127.0.0.1:9999/TestSimple?wtd=Wz5kASIyGtfL9Vui <- Session keep alive - 60 seconds later
[23092:32572:0224/163908.173:VERBOSE1:network_delegate.cc(32)] NetworkDelegate::NotifyBeforeURLRequest: http://127.0.0.1:9999/TestSimple?wtd=Wz5kASIyGtfL9Vui <- Session keep alive - 89 seconds later
[23092:32572:0224/164108.167:VERBOSE1:network_delegate.cc(32)] NetworkDelegate::NotifyBeforeURLRequest: http://127.0.0.1:9999/TestSimple?wtd=Wz5kASIyGtfL9Vui <- Session keep alive - 120 seconds later
[23092:32572:0224/164108.169:VERBOSE1:network_delegate.cc(32)] NetworkDelegate::NotifyBeforeURLRequest: http://127.0.0.1:9999/TestSimple?wtd=Wz5kASIyGtfL9Vui <- ?
[23092:32572:0224/164308.176:VERBOSE1:network_delegate.cc(32)] NetworkDelegate::NotifyBeforeURLRequest: http://127.0.0.1:9999/TestSimple?wtd=Wz5kASIyGtfL9Vui <- Session keep alive - 120 seconds later
[23092:32572:0224/164308.178:VERBOSE1:network_delegate.cc(32)] NetworkDelegate::NotifyBeforeURLRequest: http://127.0.0.1:9999/TestSimple?wtd=Wz5kASIyGtfL9Vui <- ?
[23092:32572:0224/164508.167:VERBOSE1:network_delegate.cc(32)] NetworkDelegate::NotifyBeforeURLRequest: http://127.0.0.1:9999/TestSimple?wtd=Wz5kASIyGtfL9Vui <- Session keep alive - 120 seconds later
[23092:32572:0224/164508.172:VERBOSE1:network_delegate.cc(32)] NetworkDelegate::NotifyBeforeURLRequest: http://127.0.0.1:9999/TestSimple   <- Page reload!
[23092:32572:0224/164508.180:VERBOSE1:network_delegate.cc(32)] NetworkDelegate::NotifyBeforeURLRequest: http://127.0.0.1:9999/TestSimple?wtd=cyYGWzrk2bWvuGH6&request=style&page=1
[23092:32572:0224/164508.190:VERBOSE1:network_delegate.cc(32)] NetworkDelegate::NotifyBeforeURLRequest: http://127.0.0.1:9999/TestSimple?wtd=cyYGWzrk2bWvuGH6&sid=1334707410&webGL=true&scrW=1920&scrH=1080&tz=60&tzS=Europe%2FBerlin&htmlHistory=true&deployPath=%2FTestSimple&request=script&rand=1739969676
[23092:32572:0224/164509.175:VERBOSE1:network_delegate.cc(32)] NetworkDelegate::NotifyBeforeURLRequest: http://127.0.0.1:9999/TestSimple?wtd=cyYGWzrk2bWvuGH6

It looks like the throttling affects 1 minute timers badly.
Seems like events for two "keep alives" are collected and fired together at the next possible point.
This will clash with the 2 minute session timeout eventuelly and kill the session.

I suppose setting the session-timeout to just 5 minutes could fix the problem.

Actions

Copy link

Updated by Markus S over 3 years ago

It is also visible in the output of the running program:

127.0.0.1 - - [2021-Feb-24 16:33:37.820] "GET /TestSimple HTTP/1.1" 200 2308
127.0.0.1 - - [2021-Feb-24 16:33:37.865] "GET /TestSimple?wtd=Wz5kASIyGtfL9Vui&request=style&page=1 HTTP/1.1" 200 91
127.0.0.1 - - [2021-Feb-24 16:33:37.868] "GET /resources/themes/default/wt.css HTTP/1.1" 200 20924
127.0.0.1 - - [2021-Feb-24 16:33:37.868] "GET /resources/webkit-transitions.css HTTP/1.1" 200 6814
127.0.0.1 - - [2021-Feb-24 16:33:37.869] "GET /TestSimple?wtd=Wz5kASIyGtfL9Vui&sid=126089462&webGL=true&scrW=1920&scrH=1080&tz=60&tzS=Europe%2FBerlin&htmlHistory=true&deployPath=%2FTestSimple&request=script&rand=68721485 HTTP/1.1" 200 38459127.0.0.1 - - [2021-Feb-24 16:33:37.897] "GET /favicon.ico HTTP/1.1" 200 32038
127.0.0.1 - - [2021-Feb-24 16:33:37.933] "POST /TestSimple?wtd=Wz5kASIyGtfL9Vui HTTP/1.1" 200 49
127.0.0.1 - - [2021-Feb-24 16:33:41.910] "POST /TestSimple?wtd=Wz5kASIyGtfL9Vui HTTP/1.1" 200 158
127.0.0.1 - - [2021-Feb-24 16:34:39.173] "POST /TestSimple?wtd=Wz5kASIyGtfL9Vui HTTP/1.1" 200 49
127.0.0.1 - - [2021-Feb-24 16:35:39.180] "POST /TestSimple?wtd=Wz5kASIyGtfL9Vui HTTP/1.1" 200 49
127.0.0.1 - - [2021-Feb-24 16:36:39.175] "POST /TestSimple?wtd=Wz5kASIyGtfL9Vui HTTP/1.1" 200 49
127.0.0.1 - - [2021-Feb-24 16:37:39.165] "POST /TestSimple?wtd=Wz5kASIyGtfL9Vui HTTP/1.1" 200 49
127.0.0.1 - - [2021-Feb-24 16:39:08.174] "POST /TestSimple?wtd=Wz5kASIyGtfL9Vui HTTP/1.1" 200 49
127.0.0.1 - - [2021-Feb-24 16:41:08.168] "POST /TestSimple?wtd=Wz5kASIyGtfL9Vui HTTP/1.1" 200 49
127.0.0.1 - - [2021-Feb-24 16:41:08.169] "POST /TestSimple?wtd=Wz5kASIyGtfL9Vui HTTP/1.1" 200 49
127.0.0.1 - - [2021-Feb-24 16:43:08.176] "POST /TestSimple?wtd=Wz5kASIyGtfL9Vui HTTP/1.1" 200 49
127.0.0.1 - - [2021-Feb-24 16:43:08.178] "POST /TestSimple?wtd=Wz5kASIyGtfL9Vui HTTP/1.1" 200 49
127.0.0.1 - - [2021-Feb-24 16:45:08.169] "POST /TestSimple?wtd=Wz5kASIyGtfL9Vui HTTP/1.1" 200 76
127.0.0.1 - - [2021-Feb-24 16:45:08.173] "GET /TestSimple HTTP/1.1" 200 2311

Actions

Copy link

Updated by Markus S over 3 years ago

As suspected did changing the session-timeout to 5 minutes solves the issue.

It still funny, in the beginning the keep alive time is 150 seconds then it changes to toggling between 180 and 120 seconds.

127.0.0.1 - - [2021-Feb-24 17:16:30.017] "GET /TestSimple HTTP/1.1" 200 2312
127.0.0.1 - - [2021-Feb-24 17:16:30.021] "POST /TestSimple?wtd=U2MdZ0SUDEqCDg9y HTTP/1.1" 200 76
127.0.0.1 - - [2021-Feb-24 17:16:30.037] "GET /TestSimple?wtd=Rxu8FUEV1All3TRd&request=style&page=1 HTTP/1.1" 200 91
127.0.0.1 - - [2021-Feb-24 17:16:30.041] "GET /TestSimple?wtd=Rxu8FUEV1All3TRd&sid=693424232&webGL=true&scrW=1920&scrH=1080&tz=60&tzS=Europe%2FBerlin&htmlHistory=true&deployPath=%2FTestSimple&request=script&rand=3408945103 HTTP/1.1" 200 38457
127.0.0.1 - - [2021-Feb-24 17:16:30.055] "GET /favicon.ico HTTP/1.1" 200 32038
127.0.0.1 - - [2021-Feb-24 17:16:30.104] "POST /TestSimple?wtd=Rxu8FUEV1All3TRd HTTP/1.1" 200 49
127.0.0.1 - - [2021-Feb-24 17:16:32.680] "POST /TestSimple?wtd=Rxu8FUEV1All3TRd HTTP/1.1" 200 158
127.0.0.1 - - [2021-Feb-24 17:19:01.173] "POST /TestSimple?wtd=Rxu8FUEV1All3TRd HTTP/1.1" 200 49 //- 150 seconds
127.0.0.1 - - [2021-Feb-24 17:21:31.176] "POST /TestSimple?wtd=Rxu8FUEV1All3TRd HTTP/1.1" 200 49 //- 150 seconds
127.0.0.1 - - [2021-Feb-24 17:24:01.181] "POST /TestSimple?wtd=Rxu8FUEV1All3TRd HTTP/1.1" 200 49 //- 150 seconds
127.0.0.1 - - [2021-Feb-24 17:26:31.177] "POST /TestSimple?wtd=Rxu8FUEV1All3TRd HTTP/1.1" 200 49 //- 150 seconds
127.0.0.1 - - [2021-Feb-24 17:29:08.168] "POST /TestSimple?wtd=Rxu8FUEV1All3TRd HTTP/1.1" 200 47 //- 150 seconds
127.0.0.1 - - [2021-Feb-24 17:32:08.170] "POST /TestSimple?wtd=Rxu8FUEV1All3TRd HTTP/1.1" 200 47 //- 180 seconds
127.0.0.1 - - [2021-Feb-24 17:34:08.171] "POST /TestSimple?wtd=Rxu8FUEV1All3TRd HTTP/1.1" 200 46 //- 120 seconds
127.0.0.1 - - [2021-Feb-24 17:37:08.173] "POST /TestSimple?wtd=Rxu8FUEV1All3TRd HTTP/1.1" 200 47 //- 180 seconds
127.0.0.1 - - [2021-Feb-24 17:39:08.180] "POST /TestSimple?wtd=Rxu8FUEV1All3TRd HTTP/1.1" 200 47 //- 120 seconds
127.0.0.1 - - [2021-Feb-24 17:42:08.175] "POST /TestSimple?wtd=Rxu8FUEV1All3TRd HTTP/1.1" 200 47 //- 180 seconds
127.0.0.1 - - [2021-Feb-24 17:44:08.171] "POST /TestSimple?wtd=Rxu8FUEV1All3TRd HTTP/1.1" 200 47 //- 120 seconds
127.0.0.1 - - [2021-Feb-24 17:47:08.172] "POST /TestSimple?wtd=Rxu8FUEV1All3TRd HTTP/1.1" 200 47 //- 180 seconds
127.0.0.1 - - [2021-Feb-24 17:49:08.176] "POST /TestSimple?wtd=Rxu8FUEV1All3TRd HTTP/1.1" 200 47 //- 120 seconds
127.0.0.1 - - [2021-Feb-24 17:52:08.166] "POST /TestSimple?wtd=Rxu8FUEV1All3TRd HTTP/1.1" 200 47 //- ...
127.0.0.1 - - [2021-Feb-24 17:54:08.173] "POST /TestSimple?wtd=Rxu8FUEV1All3TRd HTTP/1.1" 200 49
127.0.0.1 - - [2021-Feb-24 17:57:08.178] "POST /TestSimple?wtd=Rxu8FUEV1All3TRd HTTP/1.1" 200 49
127.0.0.1 - - [2021-Feb-24 17:59:08.169] "POST /TestSimple?wtd=Rxu8FUEV1All3TRd HTTP/1.1" 200 49
127.0.0.1 - - [2021-Feb-24 18:02:08.177] "POST /TestSimple?wtd=Rxu8FUEV1All3TRd HTTP/1.1" 200 49
127.0.0.1 - - [2021-Feb-24 18:04:08.168] "POST /TestSimple?wtd=Rxu8FUEV1All3TRd HTTP/1.1" 200 49
127.0.0.1 - - [2021-Feb-24 18:07:08.171] "POST /TestSimple?wtd=Rxu8FUEV1All3TRd HTTP/1.1" 200 49
127.0.0.1 - - [2021-Feb-24 18:09:08.171] "POST /TestSimple?wtd=Rxu8FUEV1All3TRd HTTP/1.1" 200 49
127.0.0.1 - - [2021-Feb-24 18:12:08.167] "POST /TestSimple?wtd=Rxu8FUEV1All3TRd HTTP/1.1" 200 49
127.0.0.1 - - [2021-Feb-24 18:14:08.168] "POST /TestSimple?wtd=Rxu8FUEV1All3TRd HTTP/1.1" 200 49
127.0.0.1 - - [2021-Feb-24 18:17:08.180] "POST /TestSimple?wtd=Rxu8FUEV1All3TRd HTTP/1.1" 200 49
127.0.0.1 - - [2021-Feb-24 18:19:08.167] "POST /TestSimple?wtd=Rxu8FUEV1All3TRd HTTP/1.1" 200 49
127.0.0.1 - - [2021-Feb-24 18:22:08.173] "POST /TestSimple?wtd=Rxu8FUEV1All3TRd HTTP/1.1" 200 49
127.0.0.1 - - [2021-Feb-24 18:24:08.168] "POST /TestSimple?wtd=Rxu8FUEV1All3TRd HTTP/1.1" 200 49
127.0.0.1 - - [2021-Feb-24 18:27:08.169] "POST /TestSimple?wtd=Rxu8FUEV1All3TRd HTTP/1.1" 200 49
127.0.0.1 - - [2021-Feb-24 18:29:08.167] "POST /TestSimple?wtd=Rxu8FUEV1All3TRd HTTP/1.1" 200 49
127.0.0.1 - - [2021-Feb-24 18:32:08.168] "POST /TestSimple?wtd=Rxu8FUEV1All3TRd HTTP/1.1" 200 49
127.0.0.1 - - [2021-Feb-24 18:34:08.178] "POST /TestSimple?wtd=Rxu8FUEV1All3TRd HTTP/1.1" 200 49

Actions

Copy link

Updated by Korneel Dumon over 3 years ago

Thanks for all the experiments! It's very helpful.

We set the keepAlive request to half of the session timeout. It is scheduled using setInterval().
Apparently, chrome will align the timer on the minute after a while (https://www.chromestatus.com/feature/4718288976216064). I think this explains the switching between 120 and 180, since the request are scheduled every 2.5 minutes.

Your fix for increasing the session-timeout seems right. Perhaps we will increase the default and/or add some comments.

Actions

Copy link

Updated by Markus S over 3 years ago

I believe the default in Wt for the session-timeout is 600 seconds, so it should be fine.
I think we lowered it in the past to get rid of inactive sessions faster.

Actions

Copy link

Also available in: Atom PDF

Project

General

Profile

Wt

Bug #8136

Session Timeout because of chromes "Throttle Javascript timers in background."

Updated by Korneel Dumon over 3 years ago

Updated by Markus S over 3 years ago

Updated by Markus S over 3 years ago

Updated by Markus S over 3 years ago

Updated by Markus S over 3 years ago

Updated by Korneel Dumon over 3 years ago

Updated by Markus S over 3 years ago