Roundcube Community Forum

Release Support => Pending Issues => Topic started by: mjnewton on April 23, 2021, 07:18:13 AM

Title: Session auth check failed / Send new auth cookie
Post by: mjnewton on April 23, 2021, 07:18:13 AM

Environment: Roundcube v1.4.11 (all plugins disabled) running on Raspbian 10 (Debian Buster), Apache 2.4.38, PHP 7.3, SQLite3 DB, Chrome 90.0.4430.85 / Firefox 87.0 browsers

Hi everyone,

I recently noticed that my session.log is full of these entries occurring every 5 minutes continuously during an active user sessions (two users in this case):

Code: [Select]

[23-Apr-2021 11:45:00 +0100]: <f8tuvr6s> Session auth check failed for f8tuvr6snu194rbb25l4tc9mbk; timeslot = 2021-04-23 11:45:00
[23-Apr-2021 11:45:00 +0100]: <f8tuvr6s> Send new auth cookie for f8tuvr6snu194rbb25l4tc9mbk: y8WmBhx2n96UuIJ4gcou3FBrkA-1619174400
[23-Apr-2021 11:45:39 +0100]: <dlgl7kkf> Session auth check failed for dlgl7kkf2gecnlbkn0ioqq25q3; timeslot = 2021-04-23 11:45:00
[23-Apr-2021 11:45:39 +0100]: <dlgl7kkf> Send new auth cookie for dlgl7kkf2gecnlbkn0ioqq25q3: CiGJ51TRyYjR23O8sGOjFNDk3Z-1619174400
[23-Apr-2021 11:50:00 +0100]: <f8tuvr6s> Session auth check failed for f8tuvr6snu194rbb25l4tc9mbk; timeslot = 2021-04-23 11:50:00
[23-Apr-2021 11:50:00 +0100]: <f8tuvr6s> Send new auth cookie for f8tuvr6snu194rbb25l4tc9mbk: y8WmBhx2n96UuIJ4gcou3FBrkA-1619174700
[23-Apr-2021 11:50:39 +0100]: <dlgl7kkf> Session auth check failed for dlgl7kkf2gecnlbkn0ioqq25q3; timeslot = 2021-04-23 11:50:00
[23-Apr-2021 11:50:39 +0100]: <dlgl7kkf> Send new auth cookie for dlgl7kkf2gecnlbkn0ioqq25q3: CiGJ51TRyYjR23O8sGOjFNDk3Z-1619174700
[23-Apr-2021 11:55:00 +0100]: <f8tuvr6s> Session auth check failed for f8tuvr6snu194rbb25l4tc9mbk; timeslot = 2021-04-23 11:55:00
[23-Apr-2021 11:55:00 +0100]: <f8tuvr6s> Send new auth cookie for f8tuvr6snu194rbb25l4tc9mbk: y8WmBhx2n96UuIJ4gcou3FBrkA-1619175000
[23-Apr-2021 11:55:39 +0100]: <dlgl7kkf> Session auth check failed for dlgl7kkf2gecnlbkn0ioqq25q3; timeslot = 2021-04-23 11:55:00
[23-Apr-2021 11:55:39 +0100]: <dlgl7kkf> Send new auth cookie for dlgl7kkf2gecnlbkn0ioqq25q3: CiGJ51TRyYjR23O8sGOjFNDk3Z-1619175000
[23-Apr-2021 12:00:00 +0100]: <f8tuvr6s> Session auth check failed for f8tuvr6snu194rbb25l4tc9mbk; timeslot = 2021-04-23 12:00:00
[23-Apr-2021 12:00:00 +0100]: <f8tuvr6s> Send new auth cookie for f8tuvr6snu194rbb25l4tc9mbk: y8WmBhx2n96UuIJ4gcou3FBrkA-1619175300
[23-Apr-2021 12:00:39 +0100]: <dlgl7kkf> Session auth check failed for dlgl7kkf2gecnlbkn0ioqq25q3; timeslot = 2021-04-23 12:00:00
[23-Apr-2021 12:00:39 +0100]: <dlgl7kkf> Send new auth cookie for dlgl7kkf2gecnlbkn0ioqq25q3: CiGJ51TRyYjR23O8sGOjFNDk3Z-1619175300
[23-Apr-2021 12:05:00 +0100]: <f8tuvr6s> Session auth check failed for f8tuvr6snu194rbb25l4tc9mbk; timeslot = 2021-04-23 12:05:00
[23-Apr-2021 12:05:00 +0100]: <f8tuvr6s> Send new auth cookie for f8tuvr6snu194rbb25l4tc9mbk: y8WmBhx2n96UuIJ4gcou3FBrkA-1619175600
[23-Apr-2021 12:05:39 +0100]: <dlgl7kkf> Session auth check failed for dlgl7kkf2gecnlbkn0ioqq25q3; timeslot = 2021-04-23 12:05:00
[23-Apr-2021 12:05:39 +0100]: <dlgl7kkf> Send new auth cookie for dlgl7kkf2gecnlbkn0ioqq25q3: CiGJ51TRyYjR23O8sGOjFNDk3Z-1619175600
Notwithstanding these entries (which I am assuming are an 'error' of some sort given the 'fail' terminology?) everything appears to be working perfectly fine with no issues whatsoever. I was however wondering:

1) Do others with a working system also see these entries. The reason I say 'working' is because I've seen lots of references to these entries in other threads but it has always been in relation, and a slight aside, to some very real problem the a solution is being sought. Such threads have either not concluded or have ended up with a fix for the main problem but no mention as to whether these log entries went away as a result.

2) Is it an issue? As I say, everything appears to be working just fine so if it wasn't for the logging I doubt I'd be any the wiser about them.

Something of interest, and potential relevance, is that as you can see the timestamps are always consistent - they are always at ~5 minute intervals and always at whole 5 minute past the hour (e.g. xx:00, xx:05, xx:10 etc). Could this be a clue as to what's responsible for the 'session auth check fail[ure]'? I'm wondering if there's a system activity that's behind it i.e. Roundcube is the 'victim' rather than the 'cause', if you see what I mean.

Grateful to hear your thoughts...

Title: Re: Session auth check failed / Send new auth cookie
Post by: mjnewton on April 24, 2021, 06:59:39 AM

To follow-up; having reached the point where I was reasonably satisfied I didn't have a system installation/configuration problem I raised an issue (https://github.com/roundcube/roundcubemail/issues/8024) and it's been confirmed that the entries are actually expected behaviour, which would explain why everything appeared to be working fine. Obviously if others entries appear alongside them then that's a different issue.