Occasional blackholes when sending a PM

[Guybrush88]

I just tried to reply to a PM I received and I just got the message that the request got blackholed, and the PM wasn't sent. I remember getting the same issue almost a couple of weeks ago.
EDIT = I noticed that sending PMs is pretty slow now, loading other Tatoeba pages is fine, though
NEW EDIT = now PMs are fine

[agrodet]

Related : #1955, #1809
Especially concerning 1809, did you do something similar to what Yorwba described there? Taking a long time to write it, opening other tabs, or anything that you may think relevant?

[Guybrush88]

well, it took no more than five minutes to write the message, I think, and I didn't send the message right away, but I took a couple of minutes to check what I wrote to avoid mistakes.
I had also other Tatoeba tabs open while sending the PM (such as the homepage and a couple of advanced search queries)

[jiru]

Finally found a way to reproduce this!

Steps to reproduce

1. Open a private browser window.
2. Go to http://localhost:8080/fr/user/profile/contributor
3. Click "Contact contributor" button. You’re being redirected to the login page.
4. Login. You’re being redirected to the "Write new message" page.
5. Ctrl+Click on the browser’s Back button. This will open a new tab that will briefly show "login" as title and directly redirect to the "Write new message" page.
6. Close that new tab and send your PM from the original tab.
7. The server returns a "Bad Request" error, which is what can be seen in place of the black hole error when Config.debug is enabled.

Analysis

Relevant nginx logs (formatted as timedate, request line, server response code, response length, referer)

[28/May/2023:16:37:54 +0000] "POST /fr/users/check_login?redirect=%2Ffr%2Fprivate_messages%2Fwrite%2Fcontributor HTTP/1.1" 302 5 "http://localhost:8080/fr/users/login?redirect=%2Ffr%2Fprivate_messages%2Fwrite%2Fcontributor" 
[28/May/2023:16:37:54 +0000] "GET /fr/private_messages/write/contributor HTTP/1.1" 200 12172 "http://localhost:8080/fr/users/login?redirect=%2Ffr%2Fprivate_messages%2Fwrite%2Fcontributor"
[28/May/2023:16:37:54 +0000] "GET /css/private_messages/write.css?1601855983 HTTP/1.1" 200 863 "http://localhost:8080/fr/private_messages/write/contributor"
[28/May/2023:16:37:54 +0000] "GET /img/profiles_36/unknown-avatar.png?1601855986 HTTP/1.1" 200 6811 "http://localhost:8080/fr/private_messages/write/contributor"
[28/May/2023:16:38:47 +0000] "GET /fr/users/login?redirect=%2Ffr%2Fprivate_messages%2Fwrite%2Fcontributor HTTP/1.1" 302 5 "http://localhost:8080/fr/user/profile/contributor"
[28/May/2023:16:38:47 +0000] "GET /fr/private_messages/write/contributor HTTP/1.1" 200 12173 "http://localhost:8080/fr/user/profile/contributor"
[28/May/2023:16:40:23 +0000] "POST /fr/private_messages/send HTTP/1.1" 400 306760 "http://localhost:8080/fr/private_messages/write/contributor"

This error happens because a security check fails on one of these data changing between form creation and form submission:

• Target of the form (such as /fr/private_messages/send in the example above)
• List of fields without unlocked fields, serialized in PHP, var_dump of this value shows:

  array(4) {
    [0]=>
    string(7) "content"
    [1]=>
    string(10) "recipients"
    [2]=>
    string(5) "title"
    ["messageId"]=>
    string(0) ""
  }

• Unlocked fields, which is always "submitType" for PMs
• Session id

The only thing that can possibly trigger the error here is the session id. Session ids can be renewed in some specific cases, mainly everywhere we call $this->Auth->setUser(...), in particular here:

tatoeba2/src/Controller/AppController.php

Lines 151 to 158 in f5378fe

	public function beforeRender(Event $event)
	{
	$current_user = CurrentUser::get('User');
	$auth_user = $this->Auth->user();
	if ($auth_user && $current_user && $auth_user != $current_user) {
	// User data changed, tell the Auth component about it.
	$this->Auth->setUser($current_user);
	}

In the example above, Ctrl+click makes a GET request to the login page /fr/users/login, as a result this updates the user data last_time_active:

tatoeba2/src/Controller/UsersController.php

Lines 241 to 244 in f5378fe

	// update the last login time
	$user = $this->Users->get($userId);
	$user->last_time_active = time();
	$this->Users->save($user);

which, as a result, triggers a session id renewal.

Basically updating your profile while sending a PM also triggers the error. As far as I can tell, the "remember me" auto-login feature also renews the session id, but that’s not very relevant to this issue.

So this call to setUser() was introduced by PR #2901 for good reasons; maybe there are some better ways to deal with the issues that PR solves. And maybe there are other causes of session id renewal I haven’t thought about.

[Yorwba]

In #2820, I simply disabled Form Tampering Protection for the sentence comment form, so that the changed session ID doesn't cause any issues.

At the time, I planned to do something similar for the private message form, but I didn't get around to thoroughly checking the security implications to make sure that that change is harmless.

[jiru]

@Yorwba Maybe we could just stop storing the whole user record in the Auth component, so that most changes to a user profile/settings/last-login-time do not require calling Auth->setUser(). As far as I can see, the only fields that we actually read from the Auth component are id and username. I mean these reads:

tatoeba2/src/Controller/WallController.php

Line 91 in e8e7e16

$userId = $this->Auth->user('id');

tatoeba2/src/Controller/SentencesController.php

Line 302 in e8e7e16

$userName = $this->Auth->user('username');

Although I suspect that most of these could be replaced by calls to the CurrentUser model.

I suppose we should only be storing users fields that are relevant to login and permissions in the Auth component. Like id, username, password and role fields. Then it would make sense that any change to these fields (and these fields only!) would result in a session renewal.