Session is being destroyed when opening this message

[sim]

As subject the session is being destroyed when opening attached message.

In log I can find this report:

apache2: MDB2 Error: constraint violation (-3): _doQuery: [Error message: Could not execute statement] [Last executed query: EXECUTE mdb2_statement_mysql_32498d4dec1c65c2f5cd5a582df5c236cd462dd4b USING @0, @1, @2] [Native code: 1062] [Native message: Duplicate entry 'e55b085ff0cfbb3d5ca9005d18e49375' for key 1]

Caching is off and I have alredy tried to truncate "cache" and "message" table.

You can reproduce this problem every opening of email

[alec]

Works for me, so we need more info about your environment.

[sim]

our environment is Ubuntu 8.04 + apache + mysql. Roundcube has been upgraded from 0.2 to 0.4. The only problem during update was given by queries which were dropping foreign keys because we haven't had them in the tables, for the rest everything was fine.

We have tried to copy attached message inside mailbox of another user and behavior was the same (with IE and FF).

I think that at this point we will wait a bit and see if problem will return with some another message, and in that case will debug a bit better the problem.

p.s. is there any mode to log all executed queries in roundcubemail (without attaching phpdebugger?) Thx

[alec]

Enable sql_debug option. Show "SHOW CREATE TABLE session".

[rosali]

[13-Sep-2010 12:18:04] MDB2 Error: constraint violation (-3): _doQuery: [Error message: Could not execute statement]
[Last executed query: EXECUTE mdb2_statement_mysql_35676f5b33ff7982a29ea862f79d4602bd0bf9301 USING @0, @1, @2]
[Native code: 1062]
[Native message: Duplicate entry '5062dc48af48c63961f6f7700c5f7cdb' for key 'PRIMARY']

[14-Sep-2010 05:51:53] MDB2 Error: constraint violation (-3): _doQuery: [Error message: Could not execute statement]
[Last executed query: EXECUTE mdb2_statement_mysql_3ad352ed7a8ea94022df4e84c0c7b4c8b1ff9abb8 USING @0, @1, @2]
[Native code: 1062]
[Native message: Duplicate entry '2f66cae05529aded38d3a41ca70ef102' for key 'PRIMARY']

I see these error logs aswell. But I can't reproduce the issue with the attached message.

[simvirus]

Hello!
I've attached sql log file.
Thanks

[simvirus]

p.s. i'm not sure if this is relevant to the issue, but i've noticed following strange entry in error log:

PHP Error: Could not convert string from 136 to UTF-8. Make sure iconv/mbstring is installed or lib/utf8.class is available. in /var/www/roundcubemail-0.4/program/include/main.inc on line 308 (GET /?_task=mail&_action=list&_mbox=INBOX&_refresh=1&_remote=1&_=1284559703982&_unlock=1)

Right now I have the same problem with another emails too

Thanks again

[alec]

I think it's not related. What about "SHOW CREATE TABLE session"?

[umount]

I have this error too in log

[15-Sep-2010 14:00:37] MDB2 Error: constraint violation (-3): _doQuery: [Error message: Could not execute statement]
[Last executed query: EXECUTE mdb2_statement_pgsql_63ed6370a9421c165c2a204d57cbc031cd4b18186 ('5sm74kmc79rut1d193km3rmup3', 'l
anguage|s:5:"ru_RU";auth_time|i:1284544837;temp|b:1;request_tokens|a:1:{s:5:"login";s:32:"332d23d2c6eda19b8787ca44a604c770";}'
, '84.242.214.204')]
[Native message: ERROR: duplicate key value violates unique constraint "session_pkey"]

[umount]

And I have error
PHP Error: Could not convert string from UTF-8 to KOI8-R. Make sure iconv/mbstring is installed
or lib/utf8.class is available. in roundcubemail/program/include/main.inc on line 308

but I think it is a different situation :)

[alekc]

Hello I'm sim's colleague.

About db structure, after some verification we've seen that ER of our db was different from official ones, so we have created a new db using mysql.initial.sql and copying inside our data (so the structure should be ok)

SHOW CREATE TABLE session = 
CREATE TABLE `session` (
  `sess_id` varchar(40) NOT NULL,
  `created` datetime NOT NULL default '1000-01-01 00:00:00',
  `changed` datetime NOT NULL default '1000-01-01 00:00:00',
  `ip` varchar(40) NOT NULL,
  `vars` mediumtext NOT NULL,
  PRIMARY KEY  (`sess_id`),
  KEY `changed_index` (`changed`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8

After some digging I think that I've found a problem (but i'm not sure what is causing it). When I open email with attached images, in debug i can see a call to url
/?_task=mail&_action=get&_uid=26104&_mbox=INBOX&_part=3

Then in func.inc on line 37 there is the following block which is causing my problem.

if (!in_array($RCMAIL->action, $NOIMAP_ACTIONS) && !$RCMAIL->imap_connect()) {
  $RCMAIL->kill_session();

  if ($OUTPUT->ajax_call)
    $OUTPUT->redirect(array(), 2000);

  $OUTPUT->set_env('task', 'login');
  $OUTPUT->send('login');
}

Inside imap_connect() function i get "return false" sometimes with error $this->imap->error_code = -2 (IMAP Error: Empty startup greeting (mx.domain.com:143))

We have not had any issue with Roundcubemail, but with 0.4, when there are email attached objects (i.e. images), sometimes download of these images is failing with imap error, and as conseguense sessions is destroyed and user is kicked out.

I'd suggest to make some change to the block

if (!in_array($RCMAIL->action, $NOIMAP_ACTIONS) && !$RCMAIL->imap_connect()) {

in mode that if the request has _part variable and imap connection is failing it doesn't kill the session.

Do you have any suggestion/advice?

[alec]

Good investigation. I assume your IMAP server/host has some simultaneous connection limit or something. You're probably right that we don't need to kill session in get action. I'll look at this.

[alekc]

For now I've patched this issue in this mode:
in func.inc on line 37

if (!in_array($RCMAIL->action, $NOIMAP_ACTIONS) && !$RCMAIL->imap_connect()) {
  //Alekc ()
  if (isset($_GET['_part']) && !isset($_GET['is_already_redirected'])){
    header('Location: ' . $_SERVER['REQUEST_URI'] . '&is_already_redirected=1');
    exit();
  }
  //end of Alekc
  $RCMAIL->kill_session();

I admit that it's not elegant but it fixed my issue for now and give me possibility to search for the error's cause without worrying about complaining users.

'is_already_redirected' parameter is used for avoiding infinite loop and for now 1 redirect is enough for downloading with success image without destroying my session.

[alekc]

If in the future someone will have the same issue:
In imapd configuration we had MAXPERIP settings setted to 4 (max 4 simultaneous connections from ip), raising it to 40 solved problem with empty greetings.

[alec]

Fixed in [43123453] with some performance improvement and sleep(2) addition.

[alekc]

About your note in patch:

  // Note: When message contains more inline parts and the server limit is low
  // this stil maybe the issue, while we're using the same sleep interval, but
  // I didn't found better solution.

Maybe we can use something like
usleep(rand(1,2000)*1000);
instead of sleep(2);

In this mode it should be possible to difference timing of requests.
Following code

<?php
for ($i = 0;$i<10;$i++){
    echo rand(1,2000)*1000 . "<br>";
}
?>

gave this result

529000
1009000
116000
1302000
789000
1839000
1652000
1090000
1395000
796000

So in theory eventual redirects will have different timings.

[alec]

Good idea, but I think interval should be at least 1 second. A little modified version applied in [b8d96f6e].