The following issue has been RESOLVED.
======================================================================
http://www.dbmail.org/mantis/view.php?id=535
======================================================================
Reported By: paul
Assigned To: paul
======================================================================
Project: DBMail
Issue ID: 535
Category: IMAP daemon
Reproducibility: always
Severity: minor
Priority: normal
Status: resolved
target:
Resolution: fixed
Fixed in Version: 2.2.5
======================================================================
Date Submitted: 14-Mar-07 09:38 CET
Last Modified: 05-Apr-07 09:46 CEST
======================================================================
Summary: EXPUNGE response is incorrect
Description:
The EXPUNGE response doesn't return the correct response if the Deleted
flag was stored silently
======================================================================
----------------------------------------------------------------------
idk - 15-Mar-07 10:37
----------------------------------------------------------------------
I don't know if the condition is setting deleted flag silently, but I found
this incorrect behaviour of EXPUNGE command:
000R UID STORE 542930,542932,542934,542936,542939,542941 +FLAGS.SILENT
(\Deleted \Seen)
000R OK UID STORE completed
000S EXPUNGE
* 87 EXPUNGE
* 88 EXPUNGE
* 89 EXPUNGE
* 90 EXPUNGE
* 91 EXPUNGE
* 92 EXPUNGE
000S OK EXPUNGE completed
The problem is in invalid order of * EXPUNGE messages. By the RFC for this
example there is two choices: send this messages in reverse order or six
time send the same * 87 EXPUNGE.
I thought over my problem with expunging more messages (in SquirrelMail as
well as Outlook Express, the most popular IMAP clients of my users) by
studying MSOE log files. Then I found inconsistency between MSOE log and
packet capture out (in test reported above MSOE logged only last messsage
OK EXPUNGE). Till now I'll belive packet sniffer only.
But I don't understand this: in db_expunge is SELECT message_idnr FROM
messages ORDER BY message_idnr DESC, so near right for report (report
should has not UID), but after returning of fetched ids back into
_ic_expunge ones are destroyed (dm_free(msgids)) and then is called
dbmail_imap_session_mailbox_status which prints via imap_msginfo_notify "*
%llu EXPUNGE\r\n" out in g_tree_foreach loop for oldmsginfo =
self->msginfo. From where is self->msginfo filled? db_expunge has no ref
parameter to self...
----------------------------------------------------------------------
paul - 16-Mar-07 15:07
----------------------------------------------------------------------
Please test the latest SVN revisions in the 2.2. branch.
----------------------------------------------------------------------
jasb - 16-Mar-07 20:14
----------------------------------------------------------------------
Paul,
Sometimes, not always this also happens...
Want a level5 debug log right?
----------------------------------------------------------------------
idk - 16-Mar-07 22:40
----------------------------------------------------------------------
Hmm, the latest trunk (2470) works for me fine. Thanks. I believe my note
about result discarding was helpful :) (I saw diffs).
----------------------------------------------------------------------
jasb - 17-Mar-07 13:43
----------------------------------------------------------------------
Hum... still didn't get the logs, but it seams to me that it happens in
this way.
I'm connected to imap (using OE), i let the connection reach it's timeout,
then i delete some messages, i can see that outlook reconnect to the imapd,
and then i expunge them, and it doesn't work.
If i login to the imapd, delete messages and expunge them right after it
works perfecly.
I'm trying to catch this to provide you logs.
----------------------------------------------------------------------
jasb - 27-Mar-07 23:58
----------------------------------------------------------------------
Paul,
I have news about this.
After the fix you did that resolved the most, i noticed for several days
the folowing:
I stay connected at my account, deleted some messages, about 10, still
connected to the account, the timeout reach it's end, i received another
message, waited till timeout reach its end again, and then deleted the
message i received after i deleted the other 10 +-, clicked the expunge
button, and, the first 10 messages disapear, but the last message i
deleted don't!
below, log sinse when i deleted the last message and clicked the expunge
button:
Mar 27 22:27:33 lira dbmail/imap4d[22141]: Info:[imap]
imap4.c,IMAPClientHandler(+178): COMMAND: [14bx UID STORE 1039031
+FLAGS.SILENT (\Deleted \Seen)]
Mar 27 22:27:33 lira dbmail/imap4d[22141]: Debug:[imapsession]
dbmail-imapsession.c,build_args_array_ext(+2250): arg[0]: 'STORE'
Mar 27 22:27:33 lira dbmail/imap4d[22141]: Debug:[imapsession]
dbmail-imapsession.c,build_args_array_ext(+2250): arg[1]: '1039031'
Mar 27 22:27:33 lira dbmail/imap4d[22141]: Debug:[imapsession]
dbmail-imapsession.c,build_args_array_ext(+2250): arg[2]: '+FLAGS.SILENT'
Mar 27 22:27:33 lira dbmail/imap4d[22141]: Debug:[imapsession]
dbmail-imapsession.c,build_args_array_ext(+2250): arg[3]: '('
Mar 27 22:27:33 lira dbmail/imap4d[22141]: Debug:[imapsession]
dbmail-imapsession.c,build_args_array_ext(+2250): arg[4]: '\Deleted'
Mar 27 22:27:33 lira dbmail/imap4d[22141]: Debug:[imapsession]
dbmail-imapsession.c,build_args_array_ext(+2250): arg[5]: '\Seen'
Mar 27 22:27:33 lira dbmail/imap4d[22141]: Debug:[imapsession]
dbmail-imapsession.c,build_args_array_ext(+2250): arg[6]: ')'
Mar 27 22:27:33 lira dbmail/imap4d[22141]: Info:[imap]
imap4.c,IMAPClientHandler(+292): Executing command uid...
Mar 27 22:27:33 lira dbmail/imap4d[22141]: Debug:[sql]
dbmysql.c,db_query(+286): query [SELECT
permission,seen_flag,answered_flag,deleted_flag,flagged_flag,recent_flag,draft_flag
FROM dbmail_mailboxes WHERE mailbox_idnr = 507]
Mar 27 22:27:33 lira dbmail/imap4d[22141]: Debug:[db]
db.c,db_acl_has_right(+4022): checking ACL [seen_flag] for user [235] on
mailbox [507]
Mar 27 22:27:33 lira dbmail/imap4d[22141]: Debug:[db]
db.c,db_acl_has_right(+4032): mailbox [507] is owned by user [235], is
that also [235]?
Mar 27 22:27:33 lira dbmail/imap4d[22141]: Debug:[db]
db.c,db_acl_has_right(+4036): mailbox [507] is owned by user [235], giving
all rights
Mar 27 22:27:33 lira dbmail/imap4d[22141]: Debug:[sql]
dbmysql.c,db_query(+286): query [SELECT
permission,seen_flag,answered_flag,deleted_flag,flagged_flag,recent_flag,draft_flag
FROM dbmail_mailboxes WHERE mailbox_idnr = 507]
Mar 27 22:27:33 lira dbmail/imap4d[22141]: Debug:[db]
db.c,db_acl_has_right(+4022): checking ACL [delete_flag] for user [235] on
mailbox [507]
Mar 27 22:27:33 lira dbmail/imap4d[22141]: Debug:[db]
db.c,db_acl_has_right(+4032): mailbox [507] is owned by user [235], is
that also [235]?
Mar 27 22:27:33 lira dbmail/imap4d[22141]: Debug:[db]
db.c,db_acl_has_right(+4036): mailbox [507] is owned by user [235], giving
all rights
Mar 27 22:27:33 lira dbmail/imap4d[22141]: Debug:[sql]
dbmysql.c,db_query(+286): query [SELECT message_idnr FROM dbmail_messages
WHERE mailbox_idnr = 507 AND status IN (0,1) ORDER BY message_idnr]
Mar 27 22:27:33 lira dbmail/imap4d[22141]: Debug:[mailbox]
dbmail-mailbox.c,mailbox_build_uid_map(+162): ids [1635], msn [1635]
Mar 27 22:27:33 lira dbmail/imap4d[22141]: Debug:[mailbox]
dbmail-mailbox.c,dbmail_mailbox_get_set(+1288): [1039031]
Mar 27 22:27:33 lira dbmail/imap4d[22141]: Debug:[misc]
misc.c,g_tree_merge(+1250): a[0] [OR] b[1] -> a[1]
Mar 27 22:27:33 lira dbmail/imap4d[22141]: Debug:[sql]
dbmysql.c,db_query(+286): query [UPDATE dbmail_messages SET
recent_flag=0,seen_flag=1,deleted_flag=1 WHERE message_idnr = 1039031 AND
status < 2 AND mailbox_idnr = 507]
Mar 27 22:27:33 lira dbmail/imap4d[22141]: Debug:[imapsession]
dbmail-imapsession.c,dbmail_imap_session_printf(+1335): RESPONSE: [14bx OK
UID STORE completed^M ]
Mar 27 22:27:33 lira dbmail/imap4d[22141]: Info:[imap]
imap4.c,IMAPClientHandler(+309): Finished command uid [0]
Mar 27 22:27:35 lira dbmail/imap4d[22141]: Info:[imap]
imap4.c,IMAPClientHandler(+178): COMMAND: [iqzq EXPUNGE]
Mar 27 22:27:35 lira dbmail/imap4d[22141]: Info:[imap]
imap4.c,IMAPClientHandler(+292): Executing command expunge...
Mar 27 22:27:35 lira dbmail/imap4d[22141]: Debug:[sql]
dbmysql.c,db_query(+286): query [SELECT
permission,seen_flag,answered_flag,deleted_flag,flagged_flag,recent_flag,draft_flag
FROM dbmail_mailboxes WHERE mailbox_idnr = 507]
Mar 27 22:27:35 lira dbmail/imap4d[22141]: Debug:[db]
db.c,db_acl_has_right(+4022): checking ACL [delete_flag] for user [235] on
mailbox [507]
Mar 27 22:27:35 lira dbmail/imap4d[22141]: Debug:[db]
db.c,db_acl_has_right(+4032): mailbox [507] is owned by user [235], is
that also [235]?
Mar 27 22:27:35 lira dbmail/imap4d[22141]: Debug:[db]
db.c,db_acl_has_right(+4036): mailbox [507] is owned by user [235], giving
all rights
Mar 27 22:27:35 lira dbmail/imap4d[22141]: Debug:[sql]
dbmysql.c,db_query(+286): query [SELECT sum(pm.messagesize) FROM
dbmail_messages msg, dbmail_physmessage pm WHERE msg.physmessage_id =
pm.id AND msg.mailbox_idnr = 507 AND msg.status < 2 AND msg.deleted_flag =
1]
Mar 27 22:27:35 lira dbmail/imap4d[22141]: Debug:[sql]
dbmysql.c,db_query(+286): query [SELECT message_idnr FROM dbmail_messages
WHERE mailbox_idnr = 507 AND deleted_flag=1 AND status < 2 ORDER BY
message_idnr DESC]
Mar 27 22:27:35 lira dbmail/imap4d[22141]: Debug:[sql]
dbmysql.c,db_query(+286): query [UPDATE dbmail_messages SET status=2 WHERE
mailbox_idnr = 507 AND deleted_flag=1 AND status < 2]
Mar 27 22:27:35 lira dbmail/imap4d[22141]: Debug:[db]
db.c,user_idnr_is_delivery_user_idnr(+4410): no need to look up user_idnr
for [EMAIL PROTECTED]@__]
Mar 27 22:27:35 lira dbmail/imap4d[22141]: Debug:[db]
db.c,user_quotum_dec(+389): subtracting 45577 from mailsize
Mar 27 22:27:35 lira dbmail/imap4d[22141]: Debug:[sql]
dbmysql.c,db_query(+286): query [UPDATE dbmail_users SET curmail_size =
curmail_size - 45577 WHERE user_idnr = 235]
Mar 27 22:27:35 lira dbmail/imap4d[22141]: Debug:[imapsession]
dbmail-imapsession.c,dbmail_imap_session_printf(+1335): RESPONSE: [* 1635
EXPUNGE^M ]
Mar 27 22:27:35 lira dbmail/imap4d[22141]: Debug:[imapsession]
dbmail-imapsession.c,dbmail_imap_session_printf(+1335): RESPONSE: [* 1634
EXPUNGE^M ]
Mar 27 22:27:35 lira dbmail/imap4d[22141]: Debug:[imapsession]
dbmail-imapsession.c,dbmail_imap_session_printf(+1335): RESPONSE: [* 1633
EXPUNGE^M ]
Mar 27 22:27:35 lira dbmail/imap4d[22141]: Debug:[imapsession]
dbmail-imapsession.c,dbmail_imap_session_printf(+1335): RESPONSE: [* 1632
EXPUNGE^M ]
Mar 27 22:27:35 lira dbmail/imap4d[22141]: Debug:[imapsession]
dbmail-imapsession.c,dbmail_imap_session_printf(+1335): RESPONSE: [* 1630
EXPUNGE^M ]
Mar 27 22:27:35 lira dbmail/imap4d[22141]: Debug:[imapsession]
dbmail-imapsession.c,dbmail_imap_session_printf(+1335): RESPONSE: [* 1629
EXPUNGE^M ]
Mar 27 22:27:35 lira dbmail/imap4d[22141]: Debug:[imapsession]
dbmail-imapsession.c,dbmail_imap_session_printf(+1335): RESPONSE: [* 1628
EXPUNGE^M ]
Mar 27 22:27:35 lira dbmail/imap4d[22141]: Debug:[sql]
dbmysql.c,db_query(+286): query [SELECT message_idnr FROM dbmail_messages
WHERE mailbox_idnr = 507 AND status IN (0,1) ORDER BY message_idnr]
Mar 27 22:27:35 lira dbmail/imap4d[22141]: Debug:[mailbox]
dbmail-mailbox.c,mailbox_build_uid_map(+162): ids [1628], msn [1628]
Mar 27 22:27:35 lira dbmail/imap4d[22141]: Debug:[imapsession]
dbmail-imapsession.c,dbmail_imap_session_printf(+1335): RESPONSE: [iqzq OK
EXPUNGE completed^M ]
Mar 27 22:27:35 lira dbmail/imap4d[22141]: Info:[imap]
imap4.c,IMAPClientHandler(+309): Finished command expunge [0]
And next it's the log when i click the expunge button to try to delete
that last message, but she doesn't go away!!! she's only going to disapear
if i logoff and login again
Mar 27 22:38:06 lira dbmail/imap4d[22141]: Info:[imap]
imap4.c,IMAPClientHandler(+178): COMMAND: [ewm7 EXPUNGE]
Mar 27 22:38:06 lira dbmail/imap4d[22141]: Info:[imap]
imap4.c,IMAPClientHandler(+292): Executing command expunge...
Mar 27 22:38:06 lira dbmail/imap4d[22141]: Debug:[sql]
dbmysql.c,db_query(+286): query [SELECT
permission,seen_flag,answered_flag,deleted_flag,flagged_flag,recent_flag,draft_flag
FROM dbmail_mailboxes WHERE mailbox_idnr = 507]
Mar 27 22:38:06 lira dbmail/imap4d[22141]: Debug:[db]
db.c,db_acl_has_right(+4022): checking ACL [delete_flag] for user [235] on
mailbox [507]
Mar 27 22:38:06 lira dbmail/imap4d[22141]: Debug:[db]
db.c,db_acl_has_right(+4032): mailbox [507] is owned by user [235], is
that also [235]?
Mar 27 22:38:06 lira dbmail/imap4d[22141]: Debug:[db]
db.c,db_acl_has_right(+4036): mailbox [507] is owned by user [235], giving
all rights
Mar 27 22:38:06 lira dbmail/imap4d[22141]: Debug:[sql]
dbmysql.c,db_query(+286): query [SELECT sum(pm.messagesize) FROM
dbmail_messages msg, dbmail_physmessage pm WHERE msg.physmessage_id =
pm.id AND msg.mailbox_idnr = 507 AND msg.status < 2 AND msg.deleted_flag =
1]
Mar 27 22:38:06 lira dbmail/imap4d[22141]: Debug:[sql]
dbmysql.c,db_get_result(+244): result is null
Mar 27 22:38:06 lira dbmail/imap4d[22141]: Debug:[sql]
dbmysql.c,db_query(+286): query [SELECT message_idnr FROM dbmail_messages
WHERE mailbox_idnr = 507 AND deleted_flag=1 AND status < 2 ORDER BY
message_idnr DESC]
Mar 27 22:38:06 lira dbmail/imap4d[22141]: Debug:[imapsession]
dbmail-imapsession.c,dbmail_imap_session_printf(+1335): RESPONSE: [ewm7 OK
EXPUNGE completed^M ]
Mar 27 22:38:06 lira dbmail/imap4d[22141]: Info:[imap]
imap4.c,IMAPClientHandler(+309): Finished command expunge [1]
----------------------------------------------------------------------
jasb - 27-Mar-07 23:59
----------------------------------------------------------------------
Attached there the file with the log when i logged off and logged in.
I cutted some text in the midle, hope i didn't cut anything important for
you.
Issue History
Date Modified Username Field Change
======================================================================
14-Mar-07 09:38 paul New Issue
14-Mar-07 10:01 paul Description Updated
14-Mar-07 13:53 jasb Issue Monitored: jasb
15-Mar-07 10:37 idk Note Added: 0001900
15-Mar-07 10:38 idk Issue Monitored: idk
16-Mar-07 15:07 paul Note Added: 0001909
16-Mar-07 20:14 jasb Note Added: 0001912
16-Mar-07 22:40 idk Note Added: 0001913
17-Mar-07 13:43 jasb Note Added: 0001918
27-Mar-07 23:49 jasb Note Added: 0001982
27-Mar-07 23:57 jasb File Added: logff and login.zip
27-Mar-07 23:58 jasb Note Edited: 0001982
27-Mar-07 23:59 jasb Note Added: 0001983
05-Apr-07 09:46 paul Assigned To => paul
05-Apr-07 09:46 paul Status new => resolved
05-Apr-07 09:46 paul Resolution open => fixed
05-Apr-07 09:46 paul Fixed in Version => 2.2.5
======================================================================
_______________________________________________
Dbmail-dev mailing list
[email protected]
http://twister.fastxs.net/mailman/listinfo/dbmail-dev
