Invalid compose ID in RC 1.3.0

[Fogelholk]

I saw a few closed issues about this error, but no open ones and no real solutions.

We are running three Nginx 1.12.1 + PHP-FPM 7.0.21 nodes with Roundcube 1.3.0 on them.

2017-07-17T22:10:21.193584+02:00 xxx roundcube: <r9iar6ie> PHP Error: Invalid compose ID in /xxx/roundcubemail-1.3.0/program/steps/mail/sendmail.inc on line 37 (POST /?_task=mail&_unlock=loading1500322761631&_lang=undefined&_framed=1&_action=send)

All nodes are running towards the same MySQL-server. This morning I changed the following options to run against 'memcache' instead of 'db': imap_cache, ldap_cache, session_storage.
But the error 'Invalid compose ID' still occurs, and those users are getting the message 'Internal error' in the Roundcube frontend.

We have the following plugins enabled in RC: jqueryui, database_attachments, login_lang.

[alecpl]

Do you have precise steps to reproduce the issue?

[Fogelholk]

Unfortunately not, we have had users reporting this issues since 1.2, and steps they are taking to have this error occur have not been reproducable by us.

I have tried for hours to make this error occur, but am unable myself.

The users that have reported the issue are "just writing a new email", and when they click Send the message 'Internal error' shows up for them, and in the logs I see "Invalid session ID". As far as I understand they have been using Roundcube in one tab/window only, not multiple tabs at the same time.

Sometimes they have been writing an email for just a minute, and sometimes for 10-15 minutes when it occurs.

Browsers have been ranging from Edge, Firefox and Chrome on different versions of Windows.

[alecpl]

What happens after the error? Can they continue to use Roundcube or are they logged off?

[Fogelholk]

It seems like the users are still logged in and can check their messages and such.
If they refresh the page, or go back to create a new message they are able to send the message successfully.

[alecpl]

I can only propose to add some debug logging for cases when this happens in https://github.com/roundcube/roundcubemail/blob/master/program/steps/mail/sendmail.inc#L34

rcube::console($_SERVER, $_COOKIE, $_GET, $_POST, $_SESSION);

[Fogelholk]

Thanks, I'll add the line on monday and send you a message if I get something interesting in the logs.

[alecpl]

$_GET = array (
'_token' => 'oGchKAin3HTIucUvzHMikZdCwSCyAnk7',
'_task' => 'mail',
'_action' => 'send',
'_id' => '1211545095597f0c2a612d1',

So, above the client decided to send a compose session with ID:1211545...

$_SESSION = array (
'compose_data_1211545095597f0c2a612d1' => NULL,
...
)

And here the compose session entry (in php session) exists but is empty. I don't know how's that possible. The entry if it's there, should be an array with some data. I don't see in the code where it could be set to NULL.

That makes me thinking that it might have been broken when storing/reading to/from session storage (memcache/db). Maybe there's a PHP bug, or a bug in our rcube_session::unserialize() method, but really I have no idea.

[dapphp]

@Fogelholk Did the users you have reporting this all say they were using Chrome?

I've had similar reports and after adding some additional debug information and logging, it looks (so far) like this is happening because they're sending the message twice in quick, rapid succession.

Sep  8 10:57:23 roundcube: <llorgall> Successful login for user@site.com (ID: 52813) from x.x.x.x in session llorgall5ed194gu5r5mltvot0
Sep  8 11:25:50 roundcube: <llorgall> User user@site.com [x.x.x.x]; Message for person@example.com; 250: 2.0.0 v88IPmu8014013 Message accepted for delivery
Sep  8 11:25:51 roundcube: <llorgall> PHP Error: Invalid compose ID in /nfs/webroot/html/program/steps/mail/sendmail.inc on line 37 (POST /?_task=mail&_unlock=loading1504895149939&_lang=en_US&_framed=1&_action=send)

From the log, you can see the message was sent at 11:25:50 and then a second request failed with this error at 11:25:51.

Now to determine if this is Chrome doing some prefetching or the user just pressing twice accidentally. I'm currently working with one person who's been experiencing it for several months (1.2.5 and 1.3.0) who's on Windows 10 using the latest Chrome 60.

They say it happens about 25-45% of the time they try to send new messages and continues to fail until they open a new compose window.

We've also had a few other reports prior to upgrading to 1.3.0 and it appears to still be an issue.

I will report back as soon as I have more information.

[Fogelholk]

@dapphp As far as I know we have had users with this issue using Firefox, Chrome and Internet Explorer alike, not confirmed to be the exact same issue for all those users, but their reports are the same; getting an error message on the front end, and we can see 'Invalid compose ID' in the logs.

The email is however Not able to be sent until the user either reloads the page, or logs out and in and then tries to send a message again.

Same here with users reporting this issue for a couple of months on prior Roundcube versions as well.

[dapphp]

I am working with a customer who runs into this fairly frequently. Today I got some helpful information that may help when I'm looking at the code.

Today, the user reported logging in, going to compose a message, and while typing the message, getting the error which was Invalid Compose ID. After digging through the logs, I believe this was because it tried to save the draft and got the error. He was of course, not able to send the message except for composing a new message. He was able to open and send a few other messages around the same time. The first failure happened exactly 3 minutes after starting the new message which he started composing 5 seconds after logging in.

07:55:55 -0700] "POST /?_task=login
07:56:00 -0700] "GET /?_task=mail&_mbox=INBOX&_action=compose&_extwin=1
07:56:00 -0700] "GET /?_task=mail&_action=compose&_id=156781513659b9470049ae2&_extwin=1

07:59:00 -0700] "POST /?_task=mail&_unlock=loading1505314739540&_lang=en_US&_framed=1
07:59:00 roundcube: <qb949m6k> PHP Error: Invalid compose ID
07:59:00 roundcube: <qb949m6k> PHP Error: Compose ID = '156781513659b9470049ae2';

Looking at the session information for him in the database, I see:

compose_data_156781513659b9470049ae2|N;

So somewhere, perhaps upon creation, the compose_data for that compose ID became NULL when it should be an array. When sending, if $_SESSION['compose_data' . $COMPOSE_ID]['id'] is not set, it will throw Invalid Compose ID.

If helpful I've saved a full set of access logs surrounding this session so we can see the full timeline and set of actions. It was pretty straight forward though, log in, start a message, no activity except refreshes of the inbox, then the error when it tried to save the draft after 3 minutes.

[alecpl]

@dapphp Does it happen only for users that use external window for message compose screen? See my last comment for possible reasons, we'd need to track what's written to the session database, e.g. log $newvars in rcube_session_db::update().

[dapphp]

@alecpl It appears this happens to users who are using external window, or framed. I am seeing log entries showing both compose types for people who are getting this error message.

• Not isolated to any particular browser.
• Can happen when saving draft, or before a draft has had a chance to save
• Seen instances where a person has sent multiple messages before the failure
• Seen it happen within minutes after login, but also 8 hours after login in the same session
• After checking the logs for multiple days, it seems to happen mostly with the same set of users (maybe explains why we can't replicate it easily)

I added some debugging code to rcube_session::unserialize and rcube_session::serialize to try to see if $_SESSION['compose_data' . $COMPOSE_ID] was !empty in the current request and the value of serialization/unserialzation would trash that value. The code never triggers.

I'm now wondering if this is possibly a race condition of some sort. The only thing that makes me think otherwise is how/why the compose_data is NULL rather than disappearing.

We're also using MySQL for session storage ($config['session_storage'] = 'db') and have db_persistent = true.

When using this setup, are DB backed sessions read locked per request? Is there anything that would prevent a long running request (prior to having compose_data set) overwrite session vars in the DB containing compose_data that was set in a later request (the way PHP's filesystem sessions would lock the session file for read/write blocking concurrent requests)? Need to do more experimentation with this and find out more from some users about their connections and if the problem happens in multiple locations (at least one person has the error at home, but possibly not at work). One person who experiences it frequently mentioned they recently saw a Connection Error message as well.

For no good reason, I'm also going to try to turn db persistent off to see if anything changes.

Since I added an additional log line recording the compose ID in the error, here are the exact number of unique occurrences per day we're seeing:

Today (so far): 13
Yesterday: 42
Y-1: 16
Y-2: 17
Y-3: 44
Y-4: 45
Y-5: 40
Y-6: 54
Y-7: 37
Y-8: 17
Y-9: 8
Y-10: 15
Wasn't recording compose ID prior to this date.

Contrast that with the # of messages sent per day:

Today (so far): 2258
Yesterday: 6973
Y-1: 3027
Y-2: 2690
Y-3: 5644
Y-4: 6577
Y-5: 6543
Y-6: 7013
Y-7: 7149
Y-8: 3166
Y-9: 2934
Y-10: 5795

So it's occurring for roughly 0.6% of messages sent, very low, yet consistent every day for a long time.

[magusz]

Hello,
I get the same error (PHP Error: Invalid compose ID in /svr/webmail/program/steps/mail/sendmail.inc on line 37 (POST /?_task=mail&_unlock=loading1509374477380&_lang=pl&_framed=1&_action=send))
every time when i try to send empty email (only recipient and subject fields are fill).

Roundcube Webmail 1.3.1
filesystem_attachments | 1.0 | GPLv3+
jqueryui | 1.12.0 | GPLv3+
password | 4.2 | GPLv3+
vcard_attachments | 4.0 | GPLv3+
PHP 5.6.32

[dapphp]

Last week I turned $config['session_storage'] to php from db and the Invalid Compose ID problem went away. Since extensive debugging and changes to code to try to trap where the compose ID turned to null yielded nothing, this was the next best thing I could think to try.

Since PHP file sessions use real locking, there can't be a race condition or the possibility for some other request to stomp over the compose_data (I still can't really explain why it became null and not completely gone) but after 6 days of native PHP sessions, I have not seen this occur where previously it would happen at least 10 times a day for the last 6 months since I started noticing.

If you're users are experiencing it, try editing the config to use PHP sessions and not the DB (we use NFS to store sessions so load balancing and multiple servers still work). This does bring up another issue where the PHP session driver never calls session_destroy() so we end up with tons of leftover garbage files from before users log in since they're not cleaned up properly. I'm trying to fix this because having literally 16,000+ useless session files hanging around just slows things down a bit.

[dapphp]

@magusz See my previous post, and try the PHP based sessions; does that solve it for you?

[magusz]

@dapphp I have changed $config['session_storage'] to php from db and it works fine. Thanks for advice.

[Fogelholk]

Just to pitch in, I am unable to change this setting to 'php' due to our loadbalancing setup, so this issue must be solved for the db/memcache option! :)

[vbuscemi]

Hello,
I get the same error (PHP Error: Invalid compose ID in /repository/GCloud-WebRoot/webmail/gcloud-webmail/roundcube/program/steps/mail/sendmail.inc on line 37 (POST /?_task=mail&_unlock=loading1510131081645&_lang=en&_framed=1&_action=send)).

I have:
Roundcube Webmail 1.3.2

[dapphp]

@vbuscemi Roughly how often does this happen for you? Is the database local or on another host?

[vbuscemi]

Sometimes the error appears, I don't have precise steps to reproduce the issue.
The database is on another host

[harski]

I am experiencing this too on 1.3.0. After switching session storage to php as @dapphp suggested the error rate went from ~20 errors per day to only one or two per day. So it got reduced significantly, but it's not gone completely.

[dapphp]

@harski I found that the remaining Invalid Compose ID errors we see are not the same issue. Instead they appear to be the Send button clicked more than once in rapid succession.

For those cases, do you see that a message was sent successfully right before the Invalid compose message? Usually right before it either 1 second before or on the same second I see a log entry saying the user successfully sent a message.

I was able to replicate it after a few tries by pressing Send several times in a row very fast. In my experience, the invalid compose ID message didn't stop the client because it got back the message sent successfully error and the error was completely transparent.

[harski]

Great point @dapphp, you are absolutely correct. The Invalid compose ID error I see now are always a few seconds after a mail was succesfully sent.

So changing the session storage to php got rid of the error in my case, too.

[Fogelholk]

After setting Roundcubes $config['session_storage'] to 'php' and also changing PHPs session.save_handler to 'memcached' these errors have decreased from about 5000/day to about 30/day.

However the original bug still remains, where Roundcubes memcache session handling doesn't seem to work correctly :)

[mary-pe]

Hello,
I am experiencing the invalid compose ID error.
The error occurs when the user presses the compose button after the first login and then tries to send a mail. As reported in the others comments is not possible to send mail until the user either reloads the page, or logs out and in and then tries to send a message again.
After some tests we have reduced the compose ID error of about 70% just commenting the following line of code in the app.js file:
this.http_request('getunread', {_page: this.env.current_page});
Could this change have a side effect in the Roundcube behaviour?
Thanks in advance
Mary

[Snowmanko]

Same issue here - running 1.3.6, do we have any solution ?

[robin-thoni]

Same here on 1.3.6

[thardie]

I upgraded to 1.4.10 and the issue is now resolved for me.

[mattfbacon]

Same issue persists on 1.5.0

[nlfx]

Increasing the FastCGI timeout of my web server seems to have solved the issue for me. I'm not familiar with Roundcube code, and only quickly glanced over the send.php file, but is it possible that something like this would create this bug?

• User sends an e-mail.
• The SMTP server takes longer than the web server CGI timeout to send this e-mail.
• The web server sends back a 500 error to the client because the request took longer than the CGI timeout.
• Email is still sent by the SMTP server and Roundcube deletes the corresponding compose_data_... session.
• From the client point of view, the e-mail was not sent (because the web server returned a 500 error due to CGI timeout), so they try to send the e-mail again which creates this error?

[jeversen]

We also started to experience this behaviour when we moved our roundcube (1.4.13) installation behind cloudflare. When removing cloudflare it works like expected.

We're using a loadbalanced setup so sessions are stored in the db. Moving the session-storage to php is not an option to solve this. Anyone had this same experience with rouncube and cloudflare?