InvalidToken error at login for v2.36.1+ with "Custom Login Mapping" extension #1706

ervee · 2024-08-13T11:39:57Z

Describe the bug
After update to 2.37.2 over a known-good working 2.33.0 test install I get an [object Object] error at login and get thrown back at the login screen.

To Reproduce
Steps to reproduce the behavior:

I removed my snappymail-test folder.
Created a 1-on-1 copy of my known good 2.33.0 installation to a new snappymail-test folder.
Login to /snappymail-test/ to be sure it works.
Unpacked snappymail-2.37.2.tar.gz in a temporary folder and chmod directories to 755, files to 644, chown all files to www-data:www-data and copy files over existing (new) snappymail-test folder.
Change index and fast_cache_index caching keys in application.ini
Reload nginx and PHP fpm services.
Login the admin URL and check if version is 2.37.2.
Update Extensions ("Avatars", "Custom Login Mapping" and "Contacts suggestions (IMAP folder)") if needed.
Check a domain and test it.
Go to Config menu and save at the bottom for good measure.
Logout and change URL back to normal (non-admin) URL.
Login as normal user.

Expected behavior
See my mailbox :)

Screenshots

Please complete the following information:

Browser: Multiple, does not matter.
IMAP daemon: Dovecot 2.3.13
PHP version: 8.1
SnappyMail Version: 2.37.2
Mode: Standalone

Debug/logging information
Read here how to log

I've placed them here (few lines) or as attachments (many lines)

[2024-08-13 11:30:53.007][31fee4a4] SERVICE[WARNING]: InvalidToken[101] (HTTP Token mismatch)
/srv/www/vhosts/mydomain.tld/htdocs/webmail/snappymail-test/snappymail/v/2.37.2/app/libraries/RainLoop/ServiceActions.php#100
#0 /srv/www/vhosts/mydomain.tld/htdocs/webmail/snappymail-test/snappymail/v/2.37.2/app/libraries/RainLoop/Service.php(132): RainLoop\ServiceActions->ServiceJson()
#1 /srv/www/vhosts/mydomain.tld/htdocs/webmail/snappymail-test/snappymail/v/2.37.2/app/libraries/RainLoop/Service.php(14): RainLoop\Service::RunResult()
#2 /srv/www/vhosts/mydomain.tld/htdocs/webmail/snappymail-test/snappymail/v/2.37.2/include.php(137): RainLoop\Service::Handle()
#3 /srv/www/vhosts/mydomain.tld/htdocs/webmail/snappymail-test/index.php(11): include('...')
#4 {main}

Additional context
None

The text was updated successfully, but these errors were encountered:

the-djmaze · 2024-08-13T15:59:19Z

GET /?/AppData/0/[0-9]+/ response contains a token.
The value is from \RainLoop\Utils::GetConnectionToken().
There are 2 types of values.

When it starts with 2- it is an active account
Else it is a sha1()

Login screen:

When login action, the request headers contains a header named X-SM-Token
Login action response:

Can you analyze which tokens are send/received?

ervee · 2024-08-13T17:34:53Z

On the login screen there is this:

Then after login attempt there are 3 of those /?/Json/&q[]=/0/ POST events:

POST Action "Login":

POST Action "Folders":

POST Action "Logout":

the-djmaze · 2024-08-13T19:10:41Z

The POST Action "Login" reponse data should also have a token.
That token is used in the POST "Folders".

Can you check that?

If it is different, i might know where the problem is.
You might have an additional account cookie that shouldn't be there.
If so, i will change the code in an attempt to solve it.

ervee · 2024-08-24T09:21:20Z

Hi, sorry I didn't mean to not respond. Life got in the way!

I notice that I can login with a test account, but not my main account. My main account has 2 extra accounts configured. Could that be the problem? I'll check if I can remove these accounts from my test setup.

ervee · 2024-08-26T17:52:03Z

Hi, should adding the 1 line change from daf02e5 fix the issue?
I just added the line to ./snappymail/v/2.37.2/app/libraries/RainLoop/Actions/UserAuth.php but perhaps it needs to compile? I'm not that good at this :)

the-djmaze · 2024-08-26T18:51:02Z

Just adding the line should be sufficient.
Next release will show more details why a token fails.

ervee · 2024-08-27T17:57:18Z

The manual edit didn't seem to work, but I updated to v2.37.3 and this build works without issues, also on logins with multiple accounts. Great! Too bad I can't donate on GitHub, so I donated via PayPal :)

ervee · 2024-08-27T17:59:51Z

I spoke to soon I guess. I now get "Folders error: Call to a member function Email() on null".

ervee · 2024-08-27T18:15:30Z

Even if I remove the entire data/_data_/_default_/storage/mydomain.fqdn/myuser folder I still get this error.

PS: I tested the update on my test install and I thought the login went find but I didn't correctly used my test URL which redirected my to my production version so I thought it worked and updated my production too. Woops.

ervee · 2024-08-27T18:18:27Z

This is the log now:

[2024-08-27 18:13:05.011][e38c2f9e] SERVICE[WARNING]: Error: Call to a member function Email() on null in /srv/www/vhosts/mydomain.fqdn/htdocs/webmaeActions.php:101
Stack trace:
#0 /srv/www/vhosts/mydomain.fqdn/htdocs/webmail/snappymail-test/snappymail/v/2.37.3/app/libraries/RainLoop/Service.php(132): RainLoop\ServiceActions
#1 /srv/www/vhosts/mydomain.fqdn/htdocs/webmail/snappymail-test/snappymail/v/2.37.3/app/libraries/RainLoop/Service.php(14): RainLoop\Service::RunRes
#2 /srv/www/vhosts/mydomain.fqdn/htdocs/webmail/snappymail-test/snappymail/v/2.37.3/include.php(137): RainLoop\Service::Handle()
#3 /srv/www/vhosts/mydomain.fqdn/htdocs/webmail/snappymail-test/index.php(11): include('...')
#4 {main}

the-djmaze · 2024-08-27T19:35:23Z

Oh great! Now we atleast have progress with a different error.
I will look into it!

Thanks for the donation.

the-djmaze · 2024-08-27T21:40:27Z

Ok the error resolved.
But it seems your token is from a logged in use, while SnappyMail thinks you are not logged in.

the-djmaze · 2024-09-17T10:56:12Z

Reopened as token mismatch still occurs for ervee

ervee · 2024-09-17T20:07:54Z

As #1754 is closed. I'll just post here that there is another user without multiple accounts configured with login problems.

I just got a message from another user with a "Folders error: HTTP Token mismatch" and not being able to login.
This user does not have multiple accounts configured and it might be totally unrelated anyway.

logs:

[2024-09-17 19:54:52.141][fbe7af77] Crypt[WARNING]: Decrypt() invalid $data or $key
[2024-09-17 19:54:52.143][fbe7af77] SERVICE[WARNING]: InvalidToken[101]
#0 /srv/www/vhosts/mydomain.tld/htdocs/webmail/snappymail/snappymail/v/2.33.0/app/libraries/RainLoop/Service.php(132): RainLoop\ServiceActions->ServiceJson()
#1 /srv/www/vhosts/mydomain.tld/htdocs/webmail/snappymail/snappymail/v/2.33.0/app/libraries/RainLoop/Service.php(14): RainLoop\Service::RunResult()
#2 /srv/www/vhosts/mydomain.tld/htdocs/webmail/snappymail/snappymail/v/2.33.0/include.php(127): RainLoop\Service::Handle()
#3 /srv/www/vhosts/mydomain.tld/htdocs/webmail/snappymail/index.php(11): include('...')
#4 {main}
[2024-09-17 19:54:55.902][c75ce0c0] Crypt[WARNING]: Decrypt() invalid $data or $key
[2024-09-17 19:54:55.903][c75ce0c0] SERVICE[WARNING]: InvalidToken[101]
#0 /srv/www/vhosts/mydomain.tld/htdocs/webmail/snappymail/snappymail/v/2.33.0/app/libraries/RainLoop/Service.php(132): RainLoop\ServiceActions->ServiceJson()
#1 /srv/www/vhosts/mydomain.tld/htdocs/webmail/snappymail/snappymail/v/2.33.0/app/libraries/RainLoop/Service.php(14): RainLoop\Service::RunResult()
#2 /srv/www/vhosts/mydomain.tld/htdocs/webmail/snappymail/snappymail/v/2.33.0/include.php(127): RainLoop\Service::Handle()
#3 /srv/www/vhosts/mydomain.tld/htdocs/webmail/snappymail/index.php(11): include('...')
#4 {main}
[2024-09-17 19:55:00.654][615ea92d] Crypt[WARNING]: Decrypt() invalid $data or $key
[2024-09-17 19:55:00.745][00c5c828] Crypt[WARNING]: Decrypt() invalid $data or $key
[2024-09-17 19:55:05.295][7a196e2a] Crypt[WARNING]: Decrypt() invalid $data or $key
[2024-09-17 19:55:10.724][c5bd29d6] IMAP[WARNING]: MailSo\Imap\Exceptions\NegativeResponseException: CANNOT Invalid mailbox name: Name is empty (0.001 + 0.000 secs). in /srv/www/vhosts/mydomain.tld/htdocs/webmail/snappymail/snappymail/v/2.33.0/app/libraries/MailSo/Imap/ResponseCollection.php:46
Stack trace:
#0 /srv/www/vhosts/mydomain.tld/htdocs/webmail/snappymail/snappymail/v/2.33.0/app/libraries/MailSo/Imap/ImapClient.php(542): MailSo\Imap\ResponseCollection->validate()
#1 /srv/www/vhosts/mydomain.tld/htdocs/webmail/snappymail/snappymail/v/2.33.0/app/libraries/MailSo/Imap/ImapClient.php(465): MailSo\Imap\ImapClient->getResponse()
#2 /srv/www/vhosts/mydomain.tld/htdocs/webmail/snappymail/snappymail/v/2.33.0/app/libraries/MailSo/Imap/Commands/Folders.php(270): MailSo\Imap\ImapClient->SendRequestGetResponse()
#3 /srv/www/vhosts/mydomain.tld/htdocs/webmail/snappymail/snappymail/v/2.33.0/app/libraries/MailSo/Imap/Commands/Folders.php(192): MailSo\Imap\ImapClient->FolderUnselect()
#4 /srv/www/vhosts/mydomain.tld/htdocs/webmail/snappymail/snappymail/v/2.33.0/app/libraries/MailSo/Mail/MailClient.php(397): MailSo\Imap\ImapClient->FolderStatus()
#5 /srv/www/vhosts/mydomain.tld/htdocs/webmail/snappymail/snappymail/v/2.33.0/app/libraries/RainLoop/Actions/Messages.php(550): MailSo\Mail\MailClient->FolderHash()
#6 /srv/www/vhosts/mydomain.tld/htdocs/webmail/snappymail/snappymail/v/2.33.0/app/libraries/RainLoop/ServiceActions.php(142): RainLoop\Actions->DoMessageMove()
#7 /srv/www/vhosts/mydomain.tld/htdocs/webmail/snappymail/snappymail/v/2.33.0/app/libraries/RainLoop/Service.php(132): RainLoop\ServiceActions->ServiceJson()
#8 /srv/www/vhosts/mydomain.tld/htdocs/webmail/snappymail/snappymail/v/2.33.0/app/libraries/RainLoop/Service.php(14): RainLoop\Service::RunResult()
#9 /srv/www/vhosts/mydomain.tld/htdocs/webmail/snappymail/snappymail/v/2.33.0/include.php(127): RainLoop\Service::Handle()
#10 /srv/www/vhosts/mydomain.tld/htdocs/webmail/snappymail/index.php(11): include('...')
#11 {main}
[2024-09-17 19:55:15.433][84b585a5] PdoAddressBook[WARNING]: Sync() invalid DavClient
[2024-09-17 19:55:15.433][84b585a5] SERVICE[WARNING]: ContactsSyncError[140]
#0 /srv/www/vhosts/mydomain.tld/htdocs/webmail/snappymail/snappymail/v/2.33.0/app/libraries/RainLoop/ServiceActions.php(142): RainLoop\Actions->DoContactsSync()
#1 /srv/www/vhosts/mydomain.tld/htdocs/webmail/snappymail/snappymail/v/2.33.0/app/libraries/RainLoop/Service.php(132): RainLoop\ServiceActions->ServiceJson()
#2 /srv/www/vhosts/mydomain.tld/htdocs/webmail/snappymail/snappymail/v/2.33.0/app/libraries/RainLoop/Service.php(14): RainLoop\Service::RunResult()
#3 /srv/www/vhosts/mydomain.tld/htdocs/webmail/snappymail/snappymail/v/2.33.0/include.php(127): RainLoop\Service::Handle()
#4 /srv/www/vhosts/mydomain.tld/htdocs/webmail/snappymail/index.php(11): include('...')
#5 {main}
[2024-09-17 19:55:15.628][969d9167] PdoAddressBook[WARNING]: Sync() invalid DavClient
[2024-09-17 19:55:15.629][969d9167] SERVICE[WARNING]: ContactsSyncError[140]
#0 /srv/www/vhosts/mydomain.tld/htdocs/webmail/snappymail/snappymail/v/2.33.0/app/libraries/RainLoop/ServiceActions.php(142): RainLoop\Actions->DoContactsSync()
#1 /srv/www/vhosts/mydomain.tld/htdocs/webmail/snappymail/snappymail/v/2.33.0/app/libraries/RainLoop/Service.php(132): RainLoop\ServiceActions->ServiceJson()
#2 /srv/www/vhosts/mydomain.tld/htdocs/webmail/snappymail/snappymail/v/2.33.0/app/libraries/RainLoop/Service.php(14): RainLoop\Service::RunResult()
#3 /srv/www/vhosts/mydomain.tld/htdocs/webmail/snappymail/snappymail/v/2.33.0/include.php(127): RainLoop\Service::Handle()
#4 /srv/www/vhosts/mydomain.tld/htdocs/webmail/snappymail/index.php(11): include('...')
#5 {main}

Not sure if this is related. I can create a new bug for it if you want.

I could work-around the update to 2.38 for myself, but this user relies on webmail so I had to revert back to 2.33 (known good for me). Given the security announcement I hope you can get me on 2.38 back soon. Please ask if you need anything from me.

the-djmaze · 2024-09-17T21:02:22Z

I don't get it.
Even between SnappyMail v2.33 and v2.34 there is no difference in the code regarding tokens and encryption.

So v2.34 should also work on your instance.

Please check each version until it fails.

Secondly, v2.38 should provide way more log info then "Crypt[WARNING]: Decrypt() invalid $data or $key".
Now it should also show you the whole back-trace.

Maybe:

PHP is mixing different SnappyMail source codes?
a load balancer and 1 server uses v2.33 and the other v2.38?
Multiple versions on 1 server and PHP OPCache is mixing them?
Other conflict?

ervee · 2024-09-18T09:48:44Z

I'll get my test setup on 2.33 and upgrade upward from that. It is very possible I did skip a couple of versions. So I'll get back on that.

I'll also enable debug on the test setup.

Answers:

Unlikely. That would have caused more issues for a lot more people running PHP code.
I'm not running a load balancer. I do run a WAF in between client and server, but that's only for internet clients. I can replicate all these login issues from internal clients not passing the WAF.
Isn't that what the caching key is supposed to prevent? Even if they are the same, OPCache should see that the files are from a different path. The config option "opcache.use_cwd" is 1 (so ON and is also the default) which states "When this directive is enabled, the OPcache appends the current working directory to the script key, thus eliminating possible collisions between files with the same name (basename)"
I don't know :(

ervee · 2024-09-18T14:16:46Z

I have iterated trough all updates and this is what I get:

v2.33.0 works
v2.34.2 works
v2.35.0 works
v2.35.1 works
v2.35.2 works
v2.35.3 works
v2.35.4 works
v2.36.0 works
v2.36.1 works
v2.36.2 The "Password" box changes to "Passphrase". Test user works fine, my users fails to login without error in the browser. Debug logs sows an IMAP login/logout success and after that all kinds of token errors.
v2.36.3 Test user works fine, my users fails to login without error in the browser. Debug logs sohw an IMAP login/logout success and after that all kinds of token errors.
v2.36.4 Same
v2.37.0 Same
v2.37.2 Same but browser shows "[object Object]" error.
v2.37.3 Same but browser shows "Folders error: Call to a member function Email() on null" error.
v2.38.0 Same but browser shows "Folders error: Undefined constant "LOG_ERROR"" error.
v2.38.0 with ERROR->ERR fix I now get the "Folders error: HTTP Token mismatch" error.

This is a debug log from v2.36.2 where the problem started:

[2024-09-18 13:19:30.391][2fe194a3] [INFO]: [SM:2.36.2][IP:fdea:dbee:f:1:ec4:7aff:fe79:d67e][PID:175548][nginx/1.18.0][fpm-fcgi][Streams:tcp,udp,unix,udg,ssl,tls,tlsv1.0,tlsv1.1,tlsv1.2,tlsv1.3][POST https://mydomain.tld/webmail/snappymail-test/?/Json/&q[]=/0/]
[2024-09-18 13:19:30.395][2fe194a3] JSON[INFO]: Action: DoLogin
[2024-09-18 13:19:30.396][2fe194a3] POST[INFO]: {"Email":"[email protected]","Password":"*******","language":"","signMe":"0","Action":"Login"}
[2024-09-18 13:19:30.398][2fe194a3] PLUGIN[INFO]: Hook: login.credentials
[2024-09-18 13:19:30.399][2fe194a3] IMAP[INFO]: Start connection to "tcp://email.mydomain.tld:143"
[2024-09-18 13:19:30.400][2fe194a3] IMAP[INFO]: Connect (success)
[2024-09-18 13:19:30.404][2fe194a3] IMAP[DEBUG]: 0.0043070316314697 (raw connection)
[2024-09-18 13:19:30.406][2fe194a3] IMAP[INFO]: < * OK [CAPABILITY IMAP4rev1 SASL-IR LOGIN-REFERRALS ID ENABLE IDLE LITERAL+ STARTTLS LOGINDISABLED] Dovecot (Debian) ready.\r\n
[2024-09-18 13:19:30.407][2fe194a3] IMAP[DEBUG]: 0.0071461200714111 (*)
[2024-09-18 13:19:30.407][2fe194a3] IMAP[INFO]: > TAG1 STARTTLS\r\n
[2024-09-18 13:19:30.407][2fe194a3] IMAP[INFO]: < TAG1 OK Begin TLS negotiation now.\r\n
[2024-09-18 13:19:30.408][2fe194a3] IMAP[DEBUG]: 0.00086808204650879 (TAG1)
[2024-09-18 13:19:30.421][2fe194a3] IMAP[INFO]: > TAG2 CAPABILITY\r\n
[2024-09-18 13:19:30.421][2fe194a3] IMAP[INFO]: < * CAPABILITY IMAP4rev1 SASL-IR LOGIN-REFERRALS ID ENABLE IDLE LITERAL+ AUTH=PLAIN\r\n
[2024-09-18 13:19:30.422][2fe194a3] IMAP[INFO]: < TAG2 OK Pre-login capabilities listed, post-login capabilities have more.\r\n
[2024-09-18 13:19:30.422][2fe194a3] IMAP[DEBUG]: 0.0015311241149902 (TAG2)
[2024-09-18 13:19:30.423][2fe194a3] IMAP[INFO]: > TAG3 AUTHENTICATE PLAIN *******\r\n
[2024-09-18 13:19:30.464][2fe194a3] IMAP[INFO]: < TAG3 OK [CAPABILITY IMAP4rev1 SASL-IR LOGIN-REFERRALS ID ENABLE IDLE SORT SORT=DISPLAY THREAD=REFERENCES THREAD=REFS THREAD=ORDEREDSUBJECT MULTIAPPEND URL-PARTIAL CATENATE UNSELECT CHILDREN NAMESPACE UIDPLUS LIST-EXTENDED I18NLEVEL=1 CONDSTORE QRESYNC ESEARCH ESORT SEARCHRES WITHIN CONTEXT=SEARCH LIST-STATUS BINARY MOVE SNIPPET=FUZZY PREVIEW=FUZZY STATUS=SIZE SAVEDATE LITERAL+ NOTIFY SPECIAL-USE QUOTA] Logged in\r\n
[2024-09-18 13:19:30.467][2fe194a3] IMAP[DEBUG]: 0.044969081878662 (TAG3)
[2024-09-18 13:19:30.477][2fe194a3] COOKIE[DEBUG]: set smaccount
[2024-09-18 13:19:30.482][2fe194a3] SQL[INFO]: SELECT MAX(value_int) FROM rainloop_system WHERE sys_name = ?
[2024-09-18 13:19:30.482][2fe194a3] SQL[INFO]: SELECT id_user FROM rainloop_users WHERE rl_email = :rl_email
[2024-09-18 13:19:30.484][2fe194a3] JSON[INFO]: {"Action":"Login","Result":{"Auth":true,"title":"WebMail","loadingDescription":"WebMail","Plugins":{"avatars":{"service":true,"delay":true}},"System":{"version":"2.36.2","token":"6d82e4d3561ab6830029df02d7a720735ca16400","languages":["ar","be","bg","cs","da","de","el","en","eo","es","et","eu","f...
[2024-09-18 13:19:30.484][2fe194a3] [INFO]: Memory peak usage: 2MB
[2024-09-18 13:19:30.485][2fe194a3] [INFO]: Time delta: 0.097775936126709
[2024-09-18 13:19:30.485][2fe194a3] IMAP[INFO]: > TAG4 LOGOUT\r\n
[2024-09-18 13:19:30.487][2fe194a3] IMAP[INFO]: < * BYE Logging out\r\n
[2024-09-18 13:19:30.487][2fe194a3] IMAP[INFO]: < TAG4 OK Logout completed (0.001 + 0.000 secs).\r\n
[2024-09-18 13:19:30.488][2fe194a3] IMAP[DEBUG]: 0.0025482177734375 (TAG4)
[2024-09-18 13:19:30.488][2fe194a3] IMAP[INFO]: Disconnected from "tcp://email.mydomain.tld:143" (success)
[2024-09-18 13:19:30.489][2fe194a3] IMAP[DEBUG]: 0.089160203933716 (net session)
[2024-09-18 13:19:30.542][7459cae6] [INFO]: [SM:2.36.2][IP:fdea:dbee:f:1:ec4:7aff:fe79:d67e][PID:175517][nginx/1.18.0][fpm-fcgi][Streams:tcp,udp,unix,udg,ssl,tls,tlsv1.0,tlsv1.1,tlsv1.2,tlsv1.3][POST https://mydomain.tld/webmail/snappymail-test/?/Json/&q[]=/0/]
[2024-09-18 13:19:30.547][7459cae6] TOKENS[NOTICE]: AUTH_SPEC_TOKEN_KEY invalid
[2024-09-18 13:19:30.548][7459cae6] SERVICE[WARNING]: InvalidToken[101]
#0 /srv/www/vhosts/mydomain.tld/htdocs/webmail/snappymail-test/snappymail/v/2.36.2/app/libraries/RainLoop/Service.php(132): RainLoop\ServiceActions->ServiceJson()
#1 /srv/www/vhosts/mydomain.tld/htdocs/webmail/snappymail-test/snappymail/v/2.36.2/app/libraries/RainLoop/Service.php(14): RainLoop\Service::RunResult()
#2 /srv/www/vhosts/mydomain.tld/htdocs/webmail/snappymail-test/snappymail/v/2.36.2/include.php(136): RainLoop\Service::Handle()
#3 /srv/www/vhosts/mydomain.tld/htdocs/webmail/snappymail-test/index.php(11): include('...')
#4 {main}
[2024-09-18 13:19:30.548][7459cae6] [NOTICE]: RainLoop\Exceptions\ClientException: InvalidToken[101] in /srv/www/vhosts/mydomain.tld/htdocs/webmail/snappymail-test/snappymail/v/2.36.2/app/libraries/RainLoop/ServiceActions.php:104
Stack trace:
#0 /srv/www/vhosts/mydomain.tld/htdocs/webmail/snappymail-test/snappymail/v/2.36.2/app/libraries/RainLoop/Service.php(132): RainLoop\ServiceActions->ServiceJson()
#1 /srv/www/vhosts/mydomain.tld/htdocs/webmail/snappymail-test/snappymail/v/2.36.2/app/libraries/RainLoop/Service.php(14): RainLoop\Service::RunResult()
#2 /srv/www/vhosts/mydomain.tld/htdocs/webmail/snappymail-test/snappymail/v/2.36.2/include.php(136): RainLoop\Service::Handle()
#3 /srv/www/vhosts/mydomain.tld/htdocs/webmail/snappymail-test/index.php(11): include('...')
#4 {main}
[2024-09-18 13:19:30.549][7459cae6] JSON[INFO]: {"Action":"Folders","Result":false,"ErrorCode":101,"ErrorMessage":"InvalidToken[101]","ErrorMessageAdditional":"Token mismatch","ExceptionCode":0,"epoch":1726665570}
[2024-09-18 13:19:30.549][7459cae6] [INFO]: Memory peak usage: 2MB
[2024-09-18 13:19:30.550][7459cae6] [INFO]: Time delta: 0.012119054794312
[2024-09-18 13:19:30.603][3dcc34bf] [INFO]: [SM:2.36.2][IP:fdea:dbee:f:1:ec4:7aff:fe79:d67e][PID:175519][nginx/1.18.0][fpm-fcgi][Streams:tcp,udp,unix,udg,ssl,tls,tlsv1.0,tlsv1.1,tlsv1.2,tlsv1.3][POST https://mydomain.tld/webmail/snappymail-test/?/Json/&q[]=/0/]
[2024-09-18 13:19:30.607][3dcc34bf] SERVICE[WARNING]: InvalidToken[101]
#0 /srv/www/vhosts/mydomain.tld/htdocs/webmail/snappymail-test/snappymail/v/2.36.2/app/libraries/RainLoop/Service.php(132): RainLoop\ServiceActions->ServiceJson()
#1 /srv/www/vhosts/mydomain.tld/htdocs/webmail/snappymail-test/snappymail/v/2.36.2/app/libraries/RainLoop/Service.php(14): RainLoop\Service::RunResult()
#2 /srv/www/vhosts/mydomain.tld/htdocs/webmail/snappymail-test/snappymail/v/2.36.2/include.php(136): RainLoop\Service::Handle()
#3 /srv/www/vhosts/mydomain.tld/htdocs/webmail/snappymail-test/index.php(11): include('...')
#4 {main}
[2024-09-18 13:19:30.608][3dcc34bf] [NOTICE]: RainLoop\Exceptions\ClientException: InvalidToken[101] in /srv/www/vhosts/mydomain.tld/htdocs/webmail/snappymail-test/snappymail/v/2.36.2/app/libraries/RainLoop/ServiceActions.php:104
Stack trace:
#0 /srv/www/vhosts/mydomain.tld/htdocs/webmail/snappymail-test/snappymail/v/2.36.2/app/libraries/RainLoop/Service.php(132): RainLoop\ServiceActions->ServiceJson()
#1 /srv/www/vhosts/mydomain.tld/htdocs/webmail/snappymail-test/snappymail/v/2.36.2/app/libraries/RainLoop/Service.php(14): RainLoop\Service::RunResult()
#2 /srv/www/vhosts/mydomain.tld/htdocs/webmail/snappymail-test/snappymail/v/2.36.2/include.php(136): RainLoop\Service::Handle()
#3 /srv/www/vhosts/mydomain.tld/htdocs/webmail/snappymail-test/index.php(11): include('...')
#4 {main}
[2024-09-18 13:19:30.609][3dcc34bf] JSON[INFO]: {"Action":"Logout","Result":false,"ErrorCode":101,"ErrorMessage":"InvalidToken[101]","ErrorMessageAdditional":"Token mismatch","ExceptionCode":0,"epoch":1726665570}
[2024-09-18 13:19:30.609][3dcc34bf] [INFO]: Memory peak usage: 2MB
[2024-09-18 13:19:30.609][3dcc34bf] [INFO]: Time delta: 0.010727167129517
[2024-09-18 13:19:30.729][a774f29e] [INFO]: [SM:2.36.2][IP:fdea:dbee:f:1:ec4:7aff:fe79:d67e][PID:176978][nginx/1.18.0][fpm-fcgi][Streams:tcp,udp,unix,udg,ssl,tls,tlsv1.0,tlsv1.1,tlsv1.2,tlsv1.3][GET https://mydomain.tld/webmail/snappymail-test/]
[2024-09-18 13:19:30.736][a774f29e] [INFO]: Memory peak usage: 2MB
[2024-09-18 13:19:30.737][a774f29e] [INFO]: Time delta: 0.011996984481812
[2024-09-18 13:19:30.804][cc2aab82] [INFO]: [SM:2.36.2][IP:fdea:dbee:f:1:ec4:7aff:fe79:d67e][PID:175516][nginx/1.18.0][fpm-fcgi][Streams:tcp,udp,unix,udg,ssl,tls,tlsv1.0,tlsv1.1,tlsv1.2,tlsv1.3][GET https://mydomain.tld/webmail/snappymail-test/]
[2024-09-18 13:19:30.812][cc2aab82] [INFO]: Memory peak usage: 2MB
[2024-09-18 13:19:30.812][cc2aab82] [INFO]: Time delta: 0.01283597946167
[2024-09-18 13:19:30.963][6bf42200] [INFO]: [SM:2.36.2][IP:fdea:dbee:f:1:ec4:7aff:fe79:d67e][PID:175518][nginx/1.18.0][fpm-fcgi][Streams:tcp,udp,unix,udg,ssl,tls,tlsv1.0,tlsv1.1,tlsv1.2,tlsv1.3][GET https://mydomain.tld/webmail/snappymail-test/?/AppData/0/9493237082059865/]
[2024-09-18 13:19:30.966][6bf42200] APPDATA[INFO]: {"Auth":false,"title":"WebMail","loadingDescription":"WebMail","Plugins":{"avatars":{"service":true,"delay":true}},"System":{"version":"2.36.2","token":"35b8260a7a19e098f914886094d12a9a35b55f44","languages":["ar","be","bg","cs","da","de","el","en","eo","es","et","eu","fa","fi","fr","hu","id","is","it","ja","ko","lt","lv","nb","nl","pl","pt","pt-BR","ro","ru","sk","sl","sv","tr","uk","vi","zh","zh-TW"],"webPath":"\/webmail\/snappymail-test\/","webVersionPath":"\/webmail\/snappymail-test\/snappymail\/v\/2.36.2\/"},"allowLanguagesOnLogin":true,"DevEmail":"","DevPassword":"","signMe":0,"Theme":"SquaresDark","language":"en","clientLanguage":"en","PluginsLink":"Plugins\/0\/User\/6a3ddc108db9864198704165b0725866\/","StaticLibsJs":"\/webmail\/snappymail-test\/snappymail\/v\/2.36.2\/static\/js\/libs.js"}
[2024-09-18 13:19:30.967][6bf42200] [INFO]: Memory peak usage: 2MB
[2024-09-18 13:19:30.967][6bf42200] [INFO]: Time delta: 0.0097930431365967

And a debug log from v2.38.0 (with ERROR->ERR fix):

[2024-09-18 13:31:53.723][aad90881] [INFO]: [SM:2.38.0][IP:fdea:dbee:f:1:ec4:7aff:fe79:d67e][PID:175517][nginx/1.18.0][fpm-fcgi][Streams:tcp,udp,unix,udg,ssl,tls,tlsv1.0,tlsv1.1,tlsv1.2,tlsv1.3][POST https://mydomain.tld/webmail/snappymail-test/?/Json/&q[]=/0/]
[2024-09-18 13:31:53.725][aad90881] JSON[INFO]: Action: DoLogin
[2024-09-18 13:31:53.725][aad90881] POST[INFO]: {"Email":"[email protected]","Password":"*******","language":"","signMe":"0","Action":"Login"}
[2024-09-18 13:31:53.727][aad90881] PLUGIN[INFO]: Hook: login.credentials
[2024-09-18 13:31:53.728][aad90881] IMAP[INFO]: Start connection to "tcp://email.mydomain.tld:143"
[2024-09-18 13:31:53.729][aad90881] IMAP[INFO]: Connect (success)
[2024-09-18 13:31:53.729][aad90881] IMAP[DEBUG]: 0.001227855682373 (raw connection)
[2024-09-18 13:31:53.734][aad90881] IMAP[INFO]: < * OK [CAPABILITY IMAP4rev1 SASL-IR LOGIN-REFERRALS ID ENABLE IDLE LITERAL+ STARTTLS LOGINDISABLED] Dovecot (Debian) ready.\r\n
[2024-09-18 13:31:53.735][aad90881] IMAP[DEBUG]: 0.0071690082550049 (*)
[2024-09-18 13:31:53.735][aad90881] IMAP[INFO]: > TAG1 STARTTLS\r\n
[2024-09-18 13:31:53.736][aad90881] IMAP[INFO]: < TAG1 OK Begin TLS negotiation now.\r\n
[2024-09-18 13:31:53.736][aad90881] IMAP[DEBUG]: 0.00079011917114258 (TAG1)
[2024-09-18 13:31:53.750][aad90881] IMAP[INFO]: > TAG2 CAPABILITY\r\n
[2024-09-18 13:31:53.751][aad90881] IMAP[INFO]: < * CAPABILITY IMAP4rev1 SASL-IR LOGIN-REFERRALS ID ENABLE IDLE LITERAL+ AUTH=PLAIN\r\n
[2024-09-18 13:31:53.751][aad90881] IMAP[INFO]: < TAG2 OK Pre-login capabilities listed, post-login capabilities have more.\r\n
[2024-09-18 13:31:53.751][aad90881] IMAP[DEBUG]: 0.0012731552124023 (TAG2)
[2024-09-18 13:31:53.752][aad90881] IMAP[INFO]: > TAG3 AUTHENTICATE PLAIN *******\r\n
[2024-09-18 13:31:53.792][aad90881] IMAP[INFO]: < TAG3 OK [CAPABILITY IMAP4rev1 SASL-IR LOGIN-REFERRALS ID ENABLE IDLE SORT SORT=DISPLAY THREAD=REFERENCES THREAD=REFS THREAD=ORDEREDSUBJECT MULTIAPPEND URL-PARTIAL CATENATE UNSELECT CHILDREN NAMESPACE UIDPLUS LIST-EXTENDED I18NLEVEL=1 CONDSTORE QRESYNC ESEARCH ESORT SEARCHRES WITHIN CONTEXT=SEARCH LIST-STATUS BINARY MOVE SNIPPET=FUZZY PREVIEW=FUZZY STATUS=SIZE SAVEDATE LITERAL+ NOTIFY SPECIAL-USE QUOTA] Logged in\r\n
[2024-09-18 13:31:53.793][aad90881] IMAP[DEBUG]: 0.041218042373657 (TAG3)
[2024-09-18 13:31:53.797][aad90881] TOKENS[DEBUG]: New SESSION_TOKEN
[2024-09-18 13:31:53.797][aad90881] COOKIE[DEBUG]: set smsession
[2024-09-18 13:31:53.799][aad90881] COOKIE[DEBUG]: set smaccount
[2024-09-18 13:31:53.806][aad90881] SQL[INFO]: SELECT MAX(value_int) FROM rainloop_system WHERE sys_name = ?
[2024-09-18 13:31:53.807][aad90881] SQL[INFO]: SELECT id_user FROM rainloop_users WHERE rl_email = :rl_email
[2024-09-18 13:31:53.809][aad90881] JSON[INFO]: {"Action":"Login","Result":{"Auth":true,"title":"WebMail","loadingDescription":"WebMail","Plugins":{"avatars":{"service":true,"delay":true}},"System":{"version":"2.38.0","token":"1-86d6a736041c4d7d597ca501b064e4648956c218","languages":["ar","be","bg","cs","da","de","el","en","eo","es","et","eu",...
[2024-09-18 13:31:53.809][aad90881] [INFO]: Memory peak usage: 2MB
[2024-09-18 13:31:53.809][aad90881] [INFO]: Time delta: 0.094933986663818
[2024-09-18 13:31:53.810][aad90881] IMAP[INFO]: > TAG4 LOGOUT\r\n
[2024-09-18 13:31:53.810][aad90881] IMAP[INFO]: < * BYE Logging out\r\n
[2024-09-18 13:31:53.810][aad90881] IMAP[INFO]: < TAG4 OK Logout completed (0.001 + 0.000 secs).\r\n
[2024-09-18 13:31:53.811][aad90881] IMAP[DEBUG]: 0.0012078285217285 (TAG4)
[2024-09-18 13:31:53.811][aad90881] IMAP[INFO]: Disconnected from "tcp://email.mydomain.tld:143" (success)
[2024-09-18 13:31:53.812][aad90881] IMAP[DEBUG]: 0.08373498916626 (net session)
[2024-09-18 13:31:53.866][9884f57b] [INFO]: [SM:2.38.0][IP:fdea:dbee:f:1:ec4:7aff:fe79:d67e][PID:175518][nginx/1.18.0][fpm-fcgi][Streams:tcp,udp,unix,udg,ssl,tls,tlsv1.0,tlsv1.1,tlsv1.2,tlsv1.3][POST https://mydomain.tld/webmail/snappymail-test/?/Json/&q[]=/0/]
[2024-09-18 13:31:53.871][9884f57b] TOKENS[NOTICE]: AUTH_SPEC_TOKEN_KEY invalid
[2024-09-18 13:31:53.872][9884f57b] Token[ERROR]: 1-86d6a736041c4d7d597ca501b064e4648956c218 !== 0-5580b052010aa823a792ff9698946198cee7d642 for guest
[2024-09-18 13:31:53.872][9884f57b] SERVICE[WARNING]: InvalidToken[101] (HTTP Token mismatch)
/srv/www/vhosts/mydomain.tld/htdocs/webmail/snappymail-test/snappymail/v/2.38.0/app/libraries/RainLoop/ServiceActions.php#104
#0 /srv/www/vhosts/mydomain.tld/htdocs/webmail/snappymail-test/snappymail/v/2.38.0/app/libraries/RainLoop/Service.php(132): RainLoop\ServiceActions->ServiceJson()
#1 /srv/www/vhosts/mydomain.tld/htdocs/webmail/snappymail-test/snappymail/v/2.38.0/app/libraries/RainLoop/Service.php(14): RainLoop\Service::RunResult()
#2 /srv/www/vhosts/mydomain.tld/htdocs/webmail/snappymail-test/snappymail/v/2.38.0/include.php(137): RainLoop\Service::Handle()
#3 /srv/www/vhosts/mydomain.tld/htdocs/webmail/snappymail-test/index.php(11): include('...')
#4 {main}
[2024-09-18 13:31:53.873][9884f57b] [NOTICE]: InvalidToken[101] (HTTP Token mismatch)
/srv/www/vhosts/mydomain.tld/htdocs/webmail/snappymail-test/snappymail/v/2.38.0/app/libraries/RainLoop/ServiceActions.php#104
#0 /srv/www/vhosts/mydomain.tld/htdocs/webmail/snappymail-test/snappymail/v/2.38.0/app/libraries/RainLoop/Service.php(132): RainLoop\ServiceActions->ServiceJson()
#1 /srv/www/vhosts/mydomain.tld/htdocs/webmail/snappymail-test/snappymail/v/2.38.0/app/libraries/RainLoop/Service.php(14): RainLoop\Service::RunResult()
#2 /srv/www/vhosts/mydomain.tld/htdocs/webmail/snappymail-test/snappymail/v/2.38.0/include.php(137): RainLoop\Service::Handle()
#3 /srv/www/vhosts/mydomain.tld/htdocs/webmail/snappymail-test/index.php(11): include('...')
#4 {main}
[2024-09-18 13:31:53.873][9884f57b] JSON[INFO]: {"Action":"Folders","Result":false,"code":101,"message":"InvalidToken[101]","messageAdditional":"HTTP Token mismatch","ExceptionCode":0,"epoch":1726666313}
[2024-09-18 13:31:53.874][9884f57b] [INFO]: Memory peak usage: 2MB
[2024-09-18 13:31:53.874][9884f57b] [INFO]: Time delta: 0.014010906219482
[2024-09-18 13:31:53.979][adf472b9] [INFO]: [SM:2.38.0][IP:fdea:dbee:f:1:ec4:7aff:fe79:d67e][PID:175568][nginx/1.18.0][fpm-fcgi][Streams:tcp,udp,unix,udg,ssl,tls,tlsv1.0,tlsv1.1,tlsv1.2,tlsv1.3][POST https://mydomain.tld/webmail/snappymail-test/?/Json/&q[]=/0/]
[2024-09-18 13:31:53.982][adf472b9] JSON[INFO]: Action: DoLogout
[2024-09-18 13:31:53.983][adf472b9] POST[INFO]: {"Action":"Logout"}
[2024-09-18 13:31:53.984][adf472b9] JSON[INFO]: {"Action":"Logout","Result":true,"epoch":1726666313}
[2024-09-18 13:31:53.985][adf472b9] [INFO]: Memory peak usage: 2MB
[2024-09-18 13:31:53.985][adf472b9] [INFO]: Time delta: 0.01071310043335
[2024-09-18 13:31:55.746][121314f9] [INFO]: [SM:2.38.0][IP:fdea:dbee:f:1:ec4:7aff:fe79:d67e][PID:175548][nginx/1.18.0][fpm-fcgi][Streams:tcp,udp,unix,udg,ssl,tls,tlsv1.0,tlsv1.1,tlsv1.2,tlsv1.3][GET https://mydomain.tld/webmail/snappymail-test/]
[2024-09-18 13:31:55.750][121314f9] [INFO]: Memory peak usage: 2MB
[2024-09-18 13:31:55.751][121314f9] [INFO]: Time delta: 0.012338876724243
[2024-09-18 13:31:55.898][e82ad17e] [INFO]: [SM:2.38.0][IP:fdea:dbee:f:1:ec4:7aff:fe79:d67e][PID:175519][nginx/1.18.0][fpm-fcgi][Streams:tcp,udp,unix,udg,ssl,tls,tlsv1.0,tlsv1.1,tlsv1.2,tlsv1.3][GET https://mydomain.tld/webmail/snappymail-test/?/AppData/0/05171234121362578/]
[2024-09-18 13:31:55.901][e82ad17e] [INFO]: Memory peak usage: 4MB
[2024-09-18 13:31:55.901][e82ad17e] [INFO]: Time delta: 0.011547088623047
[2024-09-18 13:31:56.071][c0a94fc3] [INFO]: [SM:2.38.0][IP:fdea:dbee:f:1:ec4:7aff:fe79:d67e][PID:175516][nginx/1.18.0][fpm-fcgi][Streams:tcp,udp,unix,udg,ssl,tls,tlsv1.0,tlsv1.1,tlsv1.2,tlsv1.3][GET https://mydomain.tld/webmail/snappymail-test/?/Plugins/0/User/05761f72d8fe07360d02bf60e83c2538/]
[2024-09-18 13:31:56.075][c0a94fc3] [INFO]: Memory peak usage: 2MB
[2024-09-18 13:31:56.075][c0a94fc3] [INFO]: Time delta: 0.011351108551025

the-djmaze · 2024-09-18T22:16:10Z

Thanks for your amazing test result!
#1729 is related but mentions that 2.36.4 works.

TOKENS[NOTICE]: AUTH_SPEC_TOKEN_KEY invalid
Token[ERROR]: 1-86d6a736041c4d7d597ca501b064e4648956c218 !== 0-5580b052010aa823a792ff9698946198cee7d642 for guest

This means that MainAccount::NewInstanceFromTokenArray fails.
But comparing 2.36.2 with 2.36.1 source, i see no difference in the used code.
So this is still very strange.

So maybe PLUGIN[INFO]: Hook: login.credentials could be an issue?

ervee · 2024-09-19T07:22:08Z

I did some some testing (more logins/logouts) around version v2.36.2 and I'm able to break it now with v2.36.1 too. Perhaps I was too fast with my test methodology. After changing from v2.36.0 to v2.36.1 and logging in/out a couple of times with a test account and my own account suddenly the Password" box changes to "Passphrase" and then it fails. I retested it all with changing the "APP_VERSION" in index.php and then restarting nginx and php8.1-fpm and that helps. I can now consistently break and fix it when switching between v2.36.0 and v2.36.1.

I got the changes from 16cc17a in Account.php to my v2.38.0 folder, set this version in index.php, restarted nginx and php8.1-fpm, refreshed and logged in with my test user (works) and then my own user and this is the log produced:

[2024-09-19 07:13:20.595][6cc2ce14] [INFO]: [SM:2.38.0][IP:fdea:dbee:f:1:ec4:7aff:fe79:d67e][PID:199155][nginx/1.18.0][fpm-fcgi][Streams:tcp,udp,unix,udg,ssl,tls,tlsv1.0,tlsv1.1,tlsv1.2,tlsv1.3][POST https://mydomain.tld/webmail/snappymail-test/?/Json/&q[]=/0/]
[2024-09-19 07:13:20.599][6cc2ce14] JSON[INFO]: Action: DoLogin
[2024-09-19 07:13:20.600][6cc2ce14] POST[INFO]: {"Email":"[email protected]","Password":"*******","language":"","signMe":"0","Action":"Login"}
[2024-09-19 07:13:20.602][6cc2ce14] PLUGIN[INFO]: Hook: login.credentials
[2024-09-19 07:13:20.603][6cc2ce14] IMAP[INFO]: Start connection to "tcp://email.mydomain.tld:143"
[2024-09-19 07:13:20.605][6cc2ce14] IMAP[INFO]: Connect (success)
[2024-09-19 07:13:20.605][6cc2ce14] IMAP[DEBUG]: 0.0021448135375977 (raw connection)
[2024-09-19 07:13:20.610][6cc2ce14] IMAP[INFO]: < * OK [CAPABILITY IMAP4rev1 SASL-IR LOGIN-REFERRALS ID ENABLE IDLE LITERAL+ STARTTLS LOGINDISABLED] Dovecot (Debian) ready.\r\n
[2024-09-19 07:13:20.611][6cc2ce14] IMAP[DEBUG]: 0.0075538158416748 (*)
[2024-09-19 07:13:20.611][6cc2ce14] IMAP[INFO]: > TAG1 STARTTLS\r\n
[2024-09-19 07:13:20.612][6cc2ce14] IMAP[INFO]: < TAG1 OK Begin TLS negotiation now.\r\n
[2024-09-19 07:13:20.612][6cc2ce14] IMAP[DEBUG]: 0.00069308280944824 (TAG1)
[2024-09-19 07:13:20.623][6cc2ce14] IMAP[INFO]: > TAG2 CAPABILITY\r\n
[2024-09-19 07:13:20.624][6cc2ce14] IMAP[INFO]: < * CAPABILITY IMAP4rev1 SASL-IR LOGIN-REFERRALS ID ENABLE IDLE LITERAL+ AUTH=PLAIN\r\n
[2024-09-19 07:13:20.624][6cc2ce14] IMAP[INFO]: < TAG2 OK Pre-login capabilities listed, post-login capabilities have more.\r\n
[2024-09-19 07:13:20.625][6cc2ce14] IMAP[DEBUG]: 0.0014708042144775 (TAG2)
[2024-09-19 07:13:20.625][6cc2ce14] IMAP[INFO]: > TAG3 AUTHENTICATE PLAIN *******\r\n
[2024-09-19 07:13:20.659][6cc2ce14] IMAP[INFO]: < TAG3 OK [CAPABILITY IMAP4rev1 SASL-IR LOGIN-REFERRALS ID ENABLE IDLE SORT SORT=DISPLAY THREAD=REFERENCES THREAD=REFS THREAD=ORDEREDSUBJECT MULTIAPPEND URL-PARTIAL CATENATE UNSELECT CHILDREN NAMESPACE UIDPLUS LIST-EXTENDED I18NLEVEL=1 CONDSTORE QRESYNC ESEARCH ESORT SEARCHRES WITHIN CONTEXT=SEARCH LIST-STATUS BINARY MOVE SNIPPET=FUZZY PREVIEW=FUZZY STATUS=SIZE SAVEDATE LITERAL+ NOTIFY SPECIAL-USE QUOTA] Logged in\r\n
[2024-09-19 07:13:20.660][6cc2ce14] IMAP[DEBUG]: 0.034584999084473 (TAG3)
[2024-09-19 07:13:20.662][6cc2ce14] COOKIE[DEBUG]: set smaccount
[2024-09-19 07:13:20.668][6cc2ce14] SQL[INFO]: SELECT MAX(value_int) FROM rainloop_system WHERE sys_name = ?
[2024-09-19 07:13:20.669][6cc2ce14] SQL[INFO]: SELECT id_user FROM rainloop_users WHERE rl_email = :rl_email
[2024-09-19 07:13:20.673][6cc2ce14] JSON[INFO]: {"Action":"Login","Result":{"Auth":true,"title":"WebMail","loadingDescription":"WebMail","Plugins":{"avatars":{"service":true,"delay":true}},"System":{"version":"2.38.0","token":"1-86d6a736041c4d7d597ca501b064e4648956c218","languages":["ar","be","bg","cs","da","de","el","en","eo","es","et","eu",...
[2024-09-19 07:13:20.673][6cc2ce14] [INFO]: Memory peak usage: 2MB
[2024-09-19 07:13:20.674][6cc2ce14] [INFO]: Time delta: 0.084504127502441
[2024-09-19 07:13:20.674][6cc2ce14] IMAP[INFO]: > TAG4 LOGOUT\r\n
[2024-09-19 07:13:20.675][6cc2ce14] IMAP[INFO]: < * BYE Logging out\r\n
[2024-09-19 07:13:20.675][6cc2ce14] IMAP[INFO]: < TAG4 OK Logout completed (0.001 + 0.000 secs).\r\n
[2024-09-19 07:13:20.675][6cc2ce14] IMAP[DEBUG]: 0.0011630058288574 (TAG4)
[2024-09-19 07:13:20.675][6cc2ce14] IMAP[INFO]: Disconnected from "tcp://email.mydomain.tld:143" (success)
[2024-09-19 07:13:20.676][6cc2ce14] IMAP[DEBUG]: 0.072517871856689 (net session)
[2024-09-19 07:13:20.721][2dd99ef2] [INFO]: [SM:2.38.0][IP:fdea:dbee:f:1:ec4:7aff:fe79:d67e][PID:199127][nginx/1.18.0][fpm-fcgi][Streams:tcp,udp,unix,udg,ssl,tls,tlsv1.0,tlsv1.1,tlsv1.2,tlsv1.3][POST https://mydomain.tld/webmail/snappymail-test/?/Json/&q[]=/0/]
[2024-09-19 07:13:20.723][2dd99ef2] ACCOUNT[DEBUG]: Class "RainLoop\Providers\ClientException" not found
[2024-09-19 07:13:20.723][2dd99ef2] TOKENS[NOTICE]: AUTH_SPEC_TOKEN_KEY invalid
[2024-09-19 07:13:20.724][2dd99ef2] Token[ERROR]: 1-86d6a736041c4d7d597ca501b064e4648956c218 !== 0-5580b052010aa823a792ff9698946198cee7d642 for guest
[2024-09-19 07:13:20.724][2dd99ef2] SERVICE[WARNING]: InvalidToken[101] (HTTP Token mismatch)
/srv/www/vhosts/mydomain.tld/htdocs/webmail/snappymail-test/snappymail/v/2.38.0/app/libraries/RainLoop/ServiceActions.php#104
#0 /srv/www/vhosts/mydomain.tld/htdocs/webmail/snappymail-test/snappymail/v/2.38.0/app/libraries/RainLoop/Service.php(132): RainLoop\ServiceActions->ServiceJson()
#1 /srv/www/vhosts/mydomain.tld/htdocs/webmail/snappymail-test/snappymail/v/2.38.0/app/libraries/RainLoop/Service.php(14): RainLoop\Service::RunResult()
#2 /srv/www/vhosts/mydomain.tld/htdocs/webmail/snappymail-test/snappymail/v/2.38.0/include.php(137): RainLoop\Service::Handle()
#3 /srv/www/vhosts/mydomain.tld/htdocs/webmail/snappymail-test/index.php(11): include('...')
#4 {main}
[2024-09-19 07:13:20.724][2dd99ef2] [NOTICE]: InvalidToken[101] (HTTP Token mismatch)
/srv/www/vhosts/mydomain.tld/htdocs/webmail/snappymail-test/snappymail/v/2.38.0/app/libraries/RainLoop/ServiceActions.php#104
#0 /srv/www/vhosts/mydomain.tld/htdocs/webmail/snappymail-test/snappymail/v/2.38.0/app/libraries/RainLoop/Service.php(132): RainLoop\ServiceActions->ServiceJson()
#1 /srv/www/vhosts/mydomain.tld/htdocs/webmail/snappymail-test/snappymail/v/2.38.0/app/libraries/RainLoop/Service.php(14): RainLoop\Service::RunResult()
#2 /srv/www/vhosts/mydomain.tld/htdocs/webmail/snappymail-test/snappymail/v/2.38.0/include.php(137): RainLoop\Service::Handle()
#3 /srv/www/vhosts/mydomain.tld/htdocs/webmail/snappymail-test/index.php(11): include('...')
#4 {main}
[2024-09-19 07:13:20.725][2dd99ef2] JSON[INFO]: {"Action":"Folders","Result":false,"code":101,"message":"InvalidToken[101]","messageAdditional":"HTTP Token mismatch","ExceptionCode":0,"epoch":1726730000}
[2024-09-19 07:13:20.725][2dd99ef2] [INFO]: Memory peak usage: 6MB
[2024-09-19 07:13:20.725][2dd99ef2] [INFO]: Time delta: 0.0072140693664551
[2024-09-19 07:13:20.860][e1795eb6] [INFO]: [SM:2.38.0][IP:fdea:dbee:f:1:ec4:7aff:fe79:d67e][PID:199128][nginx/1.18.0][fpm-fcgi][Streams:tcp,udp,unix,udg,ssl,tls,tlsv1.0,tlsv1.1,tlsv1.2,tlsv1.3][POST https://mydomain.tld/webmail/snappymail-test/?/Json/&q[]=/0/]
[2024-09-19 07:13:20.862][e1795eb6] JSON[INFO]: Action: DoLogout
[2024-09-19 07:13:20.862][e1795eb6] POST[INFO]: {"Action":"Logout"}
[2024-09-19 07:13:20.863][e1795eb6] JSON[INFO]: {"Action":"Logout","Result":true,"epoch":1726730000}
[2024-09-19 07:13:20.863][e1795eb6] [INFO]: Memory peak usage: 2MB
[2024-09-19 07:13:20.864][e1795eb6] [INFO]: Time delta: 0.011647939682007
[2024-09-19 07:13:23.611][2fdbc86d] [INFO]: [SM:2.38.0][IP:fdea:dbee:f:1:ec4:7aff:fe79:d67e][PID:199155][nginx/1.18.0][fpm-fcgi][Streams:tcp,udp,unix,udg,ssl,tls,tlsv1.0,tlsv1.1,tlsv1.2,tlsv1.3][GET https://mydomain.tld/webmail/snappymail-test/]
[2024-09-19 07:13:23.616][2fdbc86d] [INFO]: Memory peak usage: 2MB
[2024-09-19 07:13:23.616][2fdbc86d] [INFO]: Time delta: 0.013238906860352
[2024-09-19 07:13:23.826][812957c7] [INFO]: [SM:2.38.0][IP:fdea:dbee:f:1:ec4:7aff:fe79:d67e][PID:199127][nginx/1.18.0][fpm-fcgi][Streams:tcp,udp,unix,udg,ssl,tls,tlsv1.0,tlsv1.1,tlsv1.2,tlsv1.3][GET https://mydomain.tld/webmail/snappymail-test/?/AppData/0/4621711814292976/]
[2024-09-19 07:13:23.828][812957c7] [INFO]: Memory peak usage: 4MB
[2024-09-19 07:13:23.829][812957c7] [INFO]: Time delta: 0.0089218616485596
[2024-09-19 07:13:23.946][5c769929] [INFO]: [SM:2.38.0][IP:fdea:dbee:f:1:ec4:7aff:fe79:d67e][PID:199128][nginx/1.18.0][fpm-fcgi][Streams:tcp,udp,unix,udg,ssl,tls,tlsv1.0,tlsv1.1,tlsv1.2,tlsv1.3][GET https://mydomain.tld/webmail/snappymail-test/?/Plugins/0/User/05761f72d8fe07360d02bf60e83c2538/]
[2024-09-19 07:13:23.949][5c769929] [INFO]: Memory peak usage: 2MB
[2024-09-19 07:13:23.951][5c769929] [INFO]: Time delta: 0.012120962142944

the-djmaze · 2024-09-20T21:37:15Z

v2.36.1 uses SensitiveString and a different login.credentials hook.

So maybe "Custom Login Mapping" extension is failing.
Get the updated custom-login-mapping-2.2

ervee · 2024-09-21T08:51:38Z

I use these:

My test user does not need a login mapping (and can login) but my own user and the other user that reported the error do (and can't login).

So maybe you are onto something here!

the-djmaze · 2024-09-21T16:57:27Z

My server does not use the plugin.
It is like this:

[email protected] use full address as login
foo resolves to [email protected] and logs in as foo
[email protected] logs in as foo

But yours is probably different and uses the extension.
So i will use the plugin to try something 😉

the-djmaze · 2024-09-21T18:18:16Z

I've just tested the new v2.3 Custom Login Mapping like this:
[email protected]:user1:user2

This changed the login for imap to be user1 and for smtp user2.
The password for user1 and user2 is the same so i can read and send mail.
So it works as expected now.

I've updated the extensions README with:
https://github.com/the-djmaze/snappymail/tree/master/plugins#logincredentials

So basically speaking:
The first parameter, before the colon relies on:

So when you login as USER, it will be lowercase like [email protected] or [email protected] (depending on the checkbox).

ervee · 2024-09-22T08:12:30Z

In my custom login mapping I have:
[email protected]:myusername
[email protected]:john

So I never used a secon colon (:). Is that mandatory?

My setup with the plugin is as follows:
User logs in with email address. When no mapping exists the part before the @ is the IMAP login. When there is a mapping for the email address then it uses that.

I have "Use short login" and "Lowercase login" enabled on both IMAP and SMTP domain settings.

the-djmaze · 2024-09-22T08:51:29Z

Aha, we are on to something.
I will try to replicate the issue.

ervee · 2024-10-03T20:44:06Z

Did you manage to get anywhere with this?

the-djmaze · 2024-10-07T10:20:37Z

It seems to be an issue with domain resolving.

Do you have Admin -> Domains -> mydomain.tld for [email protected]?
If so, what settings does it have?

ervee · 2024-10-07T11:19:34Z

Yes I have a domain.tld for the user logging in with the email address. But maybe I found the issue...

When investigating another issue I was drawn to the Admin -> Domains -> mydomain.tld > White List configuration. In that list I configure the users that are allowed for that domain only. In that list is the username that is passed to IMAP login. So for users that have a mapping in the custom login mapping pluging there is the mapped user specified. So in case of "[email protected]:john" there is an entry "john".
When I change "john" to "johndoe" I can login again.

Now changing the whitelist is not that hard so I'll just add both for now :)

Is this an intended change? Or did some check before the plugin got moved to after the plugin or something?

the-djmaze · 2024-10-07T16:09:47Z

Aha! That explains why i could not replicate the issue.
Will ad logging for it and see if something has to be done about it.

the-djmaze · 2024-10-08T11:39:54Z

Fixed the logging and added a missing one on account switching.

Yes the whitelist was "fixed" as it has nothing to do with imap login but with email addresses.
Because the domain is hooked to email addresses, not imap/sieve/smtp logins.

ervee · 2024-10-08T12:23:37Z

Okay. Then this is fixed. Using a name not in the whitelist result in the same nondescript error so I hope you can fix that if you have not already.

the-djmaze pushed a commit that referenced this issue Aug 16, 2024

Change handling of (token) errors due to #1706

d00c953

the-djmaze mentioned this issue Aug 20, 2024

Can't login after update to 2.36.4 #1653

Closed

1 task

the-djmaze changed the title ~~[object Object] error at login after update to 2.37.2~~ [object Object] InvalidToken error at login after update to 2.37.2 Aug 20, 2024

the-djmaze closed this as completed in daf02e5 Aug 26, 2024

the-djmaze pushed a commit that referenced this issue Aug 27, 2024

Bugfix: Call to a member function Email() on null #1706

082dd3a

the-djmaze mentioned this issue Sep 17, 2024

Folders error: Undefined constant "LOG_ERROR" #1754

Closed

1 task

the-djmaze reopened this Sep 17, 2024

the-djmaze pushed a commit that referenced this issue Sep 18, 2024

Change for #1706 to debug more

16cc17a

the-djmaze pushed a commit that referenced this issue Sep 20, 2024

Bugfix: ClientException #1706

5056ecf

the-djmaze added bug Something isn't working extensions (plugin) labels Sep 21, 2024

the-djmaze changed the title ~~[object Object] InvalidToken error at login after update to 2.37.2~~ InvalidToken error at login for v2.36.1+ with "Custom Login Mapping" extension Sep 21, 2024

the-djmaze pushed a commit that referenced this issue Sep 21, 2024

Changes for #1706

d3ecfdc

ervee closed this as completed Oct 8, 2024

the-djmaze pushed a commit that referenced this issue Oct 8, 2024

Added the proper logging for #1706

28a8e3c

the-djmaze pushed a commit that referenced this issue Oct 8, 2024

Resolve #1706

b86743d

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

InvalidToken error at login for v2.36.1+ with "Custom Login Mapping" extension #1706

InvalidToken error at login for v2.36.1+ with "Custom Login Mapping" extension #1706

ervee commented Aug 13, 2024 •

edited

Loading

the-djmaze commented Aug 13, 2024 •

edited

Loading

ervee commented Aug 13, 2024

the-djmaze commented Aug 13, 2024

ervee commented Aug 24, 2024

ervee commented Aug 26, 2024

the-djmaze commented Aug 26, 2024

ervee commented Aug 27, 2024

ervee commented Aug 27, 2024

ervee commented Aug 27, 2024 •

edited

Loading

ervee commented Aug 27, 2024

the-djmaze commented Aug 27, 2024

the-djmaze commented Aug 27, 2024

the-djmaze commented Sep 17, 2024

ervee commented Sep 17, 2024 •

edited by the-djmaze

Loading

the-djmaze commented Sep 17, 2024 •

edited

Loading

ervee commented Sep 18, 2024

ervee commented Sep 18, 2024

the-djmaze commented Sep 18, 2024

ervee commented Sep 19, 2024

the-djmaze commented Sep 20, 2024 •

edited

Loading

ervee commented Sep 21, 2024

the-djmaze commented Sep 21, 2024

the-djmaze commented Sep 21, 2024 •

edited

Loading

ervee commented Sep 22, 2024

the-djmaze commented Sep 22, 2024

ervee commented Oct 3, 2024

the-djmaze commented Oct 7, 2024

ervee commented Oct 7, 2024

the-djmaze commented Oct 7, 2024

the-djmaze commented Oct 8, 2024 •

edited

Loading

ervee commented Oct 8, 2024

InvalidToken error at login for v2.36.1+ with "Custom Login Mapping" extension #1706

InvalidToken error at login for v2.36.1+ with "Custom Login Mapping" extension #1706

Comments

ervee commented Aug 13, 2024 • edited Loading

the-djmaze commented Aug 13, 2024 • edited Loading

ervee commented Aug 13, 2024

the-djmaze commented Aug 13, 2024

ervee commented Aug 24, 2024

ervee commented Aug 26, 2024

the-djmaze commented Aug 26, 2024

ervee commented Aug 27, 2024

ervee commented Aug 27, 2024

ervee commented Aug 27, 2024 • edited Loading

ervee commented Aug 27, 2024

the-djmaze commented Aug 27, 2024

the-djmaze commented Aug 27, 2024

the-djmaze commented Sep 17, 2024

ervee commented Sep 17, 2024 • edited by the-djmaze Loading

the-djmaze commented Sep 17, 2024 • edited Loading

ervee commented Sep 18, 2024

ervee commented Sep 18, 2024

the-djmaze commented Sep 18, 2024

ervee commented Sep 19, 2024

the-djmaze commented Sep 20, 2024 • edited Loading

ervee commented Sep 21, 2024

the-djmaze commented Sep 21, 2024

the-djmaze commented Sep 21, 2024 • edited Loading

ervee commented Sep 22, 2024

the-djmaze commented Sep 22, 2024

ervee commented Oct 3, 2024

the-djmaze commented Oct 7, 2024

ervee commented Oct 7, 2024

the-djmaze commented Oct 7, 2024

the-djmaze commented Oct 8, 2024 • edited Loading

ervee commented Oct 8, 2024

ervee commented Aug 13, 2024 •

edited

Loading

the-djmaze commented Aug 13, 2024 •

edited

Loading

ervee commented Aug 27, 2024 •

edited

Loading

ervee commented Sep 17, 2024 •

edited by the-djmaze

Loading

the-djmaze commented Sep 17, 2024 •

edited

Loading

the-djmaze commented Sep 20, 2024 •

edited

Loading

the-djmaze commented Sep 21, 2024 •

edited

Loading

the-djmaze commented Oct 8, 2024 •

edited

Loading