A NOTE has been added to this issue. ====================================================================== http://www.dbmail.org/mantis/view.php?id=561 ====================================================================== Reported By: LordVan Assigned To: ====================================================================== Project: DBMail Issue ID: 561 Category: IMAP daemon Reproducibility: always Severity: major Priority: normal Status: new target: ====================================================================== Date Submitted: 04-Apr-07 14:17 CEST Last Modified: 30-Apr-07 12:13 CEST ====================================================================== Summary: dbmail-imap has lock error described in bug 0000525, and blocks delivery of new messages until stopped Description: dbmail-imap has lock error described in bug 0000525, and blocks delivery of new messages until stopped.
seems like because of that /tmp / lock problem it keeps a lock on the db or something. when i stop or restart it it delivers the messages in the queue immediately and when i start it again it works. ====================================================================== ---------------------------------------------------------------------- LordVan - 04-Apr-07 16:32 ---------------------------------------------------------------------- the patch i uploaded (which i got from svn according to someones suggestion) seems to help a bit (still no emails are delivered while my imap connection is open. though it seemed some of them got delivered when i logged out. still getting those errors: ** (process:9291): CRITICAL **: dbmail_imap_session_get_msginfo: assertion `ids && g_tree_nnodes(ids)>0' failed WARNING: there is already a transaction in progress WARNING: there is already a transaction in progress WARNING: there is already a transaction in progress WARNING: there is already a transaction in progress WARNING: there is already a transaction in progress WARNING: there is already a transaction in progress WARNING: there is already a transaction in progress WARNING: there is already a transaction in progress WARNING: there is already a transaction in progress WARNING: there is already a transaction in progress WARNING: there is already a transaction in progress Error Error setting lock. Trying again. Error Error setting lock. Trying again. ** (process:9298): CRITICAL **: dbmail_imap_session_get_msginfo: assertion `ids && g_tree_nnodes(ids)>0' failed any help would be greatly appreciated (imap server timeouts less but still there .. :( ) ---------------------------------------------------------------------- aaron - 04-Apr-07 18:17 ---------------------------------------------------------------------- Bug http://www.dbmail.org/mantis/view.php?id=525 actually had two bugs in one. We resolved the short writes error, and thought we'd gotten the locks. The patch you have is for additional short write errors, but still doesn't deal with the locks. You're actually seeing a problem in pool.c, set_lock. What filesystem type is your /tmp? ---------------------------------------------------------------------- aaron - 04-Apr-07 18:30 ---------------------------------------------------------------------- Some Googleage shows that this "WARNING: there is already a transaction in progress" comes from PostgreSQL. Do you have any corresponding PG log files that could help narrow down the source of the transaction errors? ---------------------------------------------------------------------- LordVan - 05-Apr-07 14:16 ---------------------------------------------------------------------- attached logs when postgres was on debug5 logging level .. don't see anything but maybe u can find sth out from it :) also, i just noticed something in my syslog: <FF>)<D0><C1><F8>^B<89>E<F0>t01<FF><89><U+058D><B6> Apr 5 11:06:43 lordvan dbmail/smtp[1577]: Warning 500 Permanent Failure <9C>=^R <8D><83><D8><FE><FF><FF><8D><93><D8><FE><FF> <FF>)<D0><C1><F8>^B<89>E<F0>t01<FF><89><U+058D><B6> Apr 5 11:07:12 lordvan dbmail/smtp[1581]: Warning 500 Permanent Failure <9C>=^R <8D><83><D8><FE><FF><FF><8D><93><D8><FE><FF> <FF>)<D0><C1><F8>^B<89>E<F0>t01<FF><89><U+058D><B6> Apr 5 11:07:37 lordvan spamd[24660]: spamd: connection from localhost [127.0.0.1] at port 57231 Apr 5 11:07:37 lordvan spamd[24660]: spamd: setuid to qscand succeeded Apr 5 11:07:37 lordvan spamd[24660]: spamd: checking message <[EMAIL PROTECTED]> for qscand :210 Apr 5 11:07:37 lordvan spamd[24660]: spamd: clean message (4.2/5.0) for qscand:210 in 0.5 seconds, 23114 bytes. Apr 5 11:07:37 lordvan spamd[24660]: spamd: result: . 4 - ADVANCE_FEE_1,ADVANCE_FEE_2,ADVANCE_FEE_3,HTML_FONT_BIG,HTML_MESSAG E,HTML_TAG_EXIST_TBODY,MAILTO_TO_SPAM_ADDR,MSGID_FROM_MTA_HEADER,SUBJ_ALL_CAPS,UNPARSEABLE_RELAY scantime=0.5,size=23114,user= qscand,uid=210,required_score=5.0,rhost=localhost,raddr=127.0.0.1,rport=57231,mid=<[EMAIL PROTECTED] mail.com>,autolearn=no Apr 5 11:07:37 lordvan spamd[11585]: prefork: child states: II Apr 5 11:07:37 lordvan dbmail/smtp[1597]: Message message id=6595, size=23690 is inserted Apr 5 11:08:40 lordvan dbmail/smtp[1610]: Warning 500 Permanent Failure <9C>=^R <8D><83><D8><FE><FF><FF><8D><93><D8><FE><FF> ---------------------------------------------------------------------- LordVan - 05-Apr-07 14:28 ---------------------------------------------------------------------- one other thing. the logs also include me using squirrelmail to do a search - and some other things. one important bit is when i used the search and tried to move mails to the Spam folder it gave me an error . this has happened before. it does apparently copy the mails but not delete them from my inbox. also had an imap connection timeout (squirrelmail on same server as dbmail) near end of the log. all in all the receiving works ok but when i try to use imap server it gives quite a few problems. oh and my /tmp is on a ext3 filesystem. ---------------------------------------------------------------------- LordVan - 05-Apr-07 17:08 ---------------------------------------------------------------------- by the wya .. those messages only happen when dbmail-imap is running (haven't tried it with sieve and other daemon yet as i don't need them right now) when dbmail-imap is off no errors appear.. last part of my current log(last line is from stopping dbmail-imap): WARNING: there is already a transaction in progress STATEMENT: BEGIN WARNING: there is already a transaction in progress STATEMENT: BEGIN WARNING: there is already a transaction in progress STATEMENT: BEGIN LOG: unexpected EOF on client connection ---------------------------------------------------------------------- LordVan - 10-Apr-07 13:42 ---------------------------------------------------------------------- an update with more details now: this is from the moment when i was trying to access mails/folders using squirrelmail: /var/log/dbmail.err: WARNING: there is already a transaction in progress WARNING: there is already a transaction in progress WARNING: there is already a transaction in progress WARNING: there is already a transaction in progress WARNING: there is already a transaction in progress WARNING: there is already a transaction in progress WARNING: there is already a transaction in progress WARNING: there is already a transaction in progress Error Error setting lock. Trying again. Error Error setting lock. Trying again. WARNING: there is already a transaction in progress WARNING: there is already a transaction in progress /var/log/qmail/qmail-send/current: @40000000461b76ba2d062174 delivery 36061: deferral: @40000000461b76ba2d06ec94 status: local 1/10 remote 0/20 @40000000461b76ba2d203924 delivery 36062: deferral: @40000000461b76ba2d20641c status: local 0/10 remote 0/20 @40000000461b76d62d5b138c starting delivery 36063: msg 111889 to local [EMAIL PROTECTED] @40000000461b76d62d5bbb84 status: local 1/10 remote 0/20 @40000000461b76d62d5cb19c starting delivery 36064: msg 111889 to local [EMAIL PROTECTED] @40000000461b76d62d5d3284 status: local 2/10 remote 0/20 @40000000461b76d632dc5ce4 delivery 36063: deferral: @40000000461b76d632dc689c status: local 1/10 remote 0/20 @40000000461b76d632f4ceb4 delivery 36064: deferral: @40000000461b76d632f4d684 status: local 0/10 remote 0/20 /var/log/qmail/qmail-smtpd/current: @40000000461b768c3087c26c tcpserver: status: 1/40 @40000000461b768c308a00a4 tcpserver: pid 21279 from 85.141.200.23 @40000000461b768c30ab6384 tcpserver: ok 21279 server88-208-201-184.live-servers.net:88.208.201.184:25 ppp85-141-200-23.pppoe .mtu-net.ru:85.141.200.23::3718 @40000000461b768c30bbda5c tcpserver: end 21279 status 256 @40000000461b768c30bbe22c tcpserver: status: 0/40 @40000000461b76a0005ca8b4 tcpserver: status: 1/40 @40000000461b76a00062230c tcpserver: pid 21292 from 210.221.74.60 @40000000461b76a0007827c4 tcpserver: ok 21292 server88-208-201-184.live-servers.net:88.208.201.184:25 :210.221.74.60::3543 @40000000461b76a20420e08c tcpserver: end 21292 status 0 @40000000461b76a20420f02c tcpserver: status: 0/40 /var/log/postgres/postgresql-2007-04-10_000000.log: "marilynmanson" "lordvan.com")(NIL NIL "nin" "lordvan.com")(NIL NIL "omi" "lordvan.com")) NIL NIL "<MAILSENDERNG3GKeD116941 [EMAIL PROTECTED]>")') ERROR: current transaction is aborted, commands ignored until end of transaction block STATEMENT: SELECT physmessage_id FROM dbmail_messages WHERE message_idnr = 37906 ERROR: current transaction is aborted, commands ignored until end of transaction block STATEMENT: SELECT physmessage_id FROM dbmail_messages WHERE message_idnr = 37908 WARNING: there is already a transaction in progress STATEMENT: BEGIN WARNING: there is already a transaction in progress STATEMENT: BEGIN LOG: unexpected EOF on client connection ---------------------------------------------------------------------- aaron - 10-Apr-07 15:38 ---------------------------------------------------------------------- About line 93 of the 2007-04-05 log files seems to be the first query gone wrong that might have caused the transaction to abort: Error query failed [INSERT INTO dbmail_headername (headername) VALUES ('cc')] : [ERROR: duplicate key violates unique constraint "dbmail_headername_1" ] Error query failed [INSERT INTO dbmail_tofield (physmessage_id, toname, toaddr) VALUES (213,'','[EMAIL PROTECTED]')] : [ERROR: current transaction is aborted, commands ignored until end of transaction block ] There were some earlier queries that died with this message: Error query failed [SELECT login, sock_allow, sock_deny, userid FROM dbmail_usermap WHERE login in ('lordvan','ANY') ORDER BY sock_allow, sock_deny] : [FATAL: terminating connection due to administrator command server closed the connection unexpectedly This probably means the server terminated abnormally before or while processing the request. ] That's definitely a new one around here! ---------------------------------------------------------------------- LordVan - 13-Apr-07 11:45 ---------------------------------------------------------------------- now that is not good for me :( here is a question then: how 'supported' is dbmail on postgresql ? as it seems to me it is not 100% tested ;( anyway .. i'm willing to help testing of course to get those problems fixed - i dont' really wanna try to swap to mysql now .. though i'm tempted as reading my emails is qutie a pain (i have to have imap server stopped most of the time..) ---------------------------------------------------------------------- froeske - 24-Apr-07 09:59 ---------------------------------------------------------------------- we have a similar Problem with dmbail-lmtp: ---- Maillog ---- Apr 23 20:46:49 pure08 dbmail/lmtpd[4305]: Error [Lock wait timeout exceeded; try restarting transaction] [UPDATE dbmail_users SET curmail_size = curmail_size + 1959 WHERE user_idnr = 198] Apr 23 20:46:49 pure08 dbmail/lmtpd[4305]: Error error setting the new quotum used value for user [198] Apr 23 20:46:49 pure08 dbmail/lmtpd[4305]: Error error copying message to user [198] Apr 23 20:46:49 pure08 dbmail/lmtpd[4305]: Error unknown temporary failure in sort_and_deliver for useridnr [198] Apr 23 20:46:49 pure08 postfix/lmtp[25617]: C4A9DC3486C: to=<[EMAIL PROTECTED]>, relay=localhost[127.0.0.1], delay=51, status=bounced (host localhost[127.0.0.1] said: 511 Recipient <[EMAIL PROTECTED]> Permanent Failure Address Status Bad destination mailbox address (in reply to end of DATA command)) ---- The Problem here is, that the eMails are rejected with Code 511, instead of a 4xx Error Message. After restarting the dbmail-Subsystem (dbmail-lmtp, dbmail-imapd, dbmail-pop3d) everything works fine again. We are using dbmail with mysql InnoDB ---------------------------------------------------------------------- LordVan - 24-Apr-07 11:30 ---------------------------------------------------------------------- I found out that if i use evolution imap client instead of squirrelmail emails do get delivered, so it has to do somehow with how squirrelmail handles connections probably. though i get some other errors when using evolution. - and the same errors when i try to move / delete a number of messages. will attach logs shortly. ---------------------------------------------------------------------- LordVan - 24-Apr-07 12:42 ---------------------------------------------------------------------- Uploaded the logs on my webpage/blog as the file is just too big for here... http://www.lordvan.com/drupal/node/13 ---------------------------------------------------------------------- aaron - 25-Apr-07 09:33 ---------------------------------------------------------------------- Your most recent logs indicate that you're not running latest SVN. We can't know if we've already fixed this bug if you're not testing the latest code. ---------------------------------------------------------------------- LordVan - 25-Apr-07 14:36 ---------------------------------------------------------------------- hmm ok will do that then (though i'jm not keen on running svn latest on live server but i dont' have a choice really do i? ;) which svn module shall i get ? dbmail_2_2 branch or trunk? ---------------------------------------------------------------------- paul - 25-Apr-07 16:50 ---------------------------------------------------------------------- LordVan, debian packages for 2.2.5-rc1 are available deb http://debian.nfgd.net/debian unstable main ---------------------------------------------------------------------- LordVan - 25-Apr-07 16:54 ---------------------------------------------------------------------- hehe doubt that'll work on my gentoo box without fiddling about with it ;) i don't mind making myself a little svn snapshot build (am a gentoo dev after all hehe) but i'd like to know if i should use the branch or trunk :) ---------------------------------------------------------------------- aaron - 25-Apr-07 17:30 ---------------------------------------------------------------------- dbmail_2_2_branch. ---------------------------------------------------------------------- LordVan - 26-Apr-07 10:07 ---------------------------------------------------------------------- i just tried running it with svn branch and got errors about it not being able to load libpgsql. problem was that the compiled in library directory did not work (probably because of gentoo's sandbox). -- i didn't check, but can the compiled in lib directory be specified to configure? if not it'd be handy ... that or un-comment the library_directory default in config.. ---------------------------------------------------------------------- LordVan - 26-Apr-07 11:00 ---------------------------------------------------------------------- got a new error message in logs now (under the transaction in progess ones..) when imap server is on mostly. will investigate more later but too busy now :( WARNING: there is already a transaction in progress WARNING: there is already a transaction in progress WARNING: there is already a transaction in progress WARNING: there is already a transaction in progress Apr 26 09:13:45 Error:[server] pool.c,set_lock(+65): Error setting lock. Trying again. Apr 26 09:42:40 Error:[server] pool.c,set_lock(+65): Error setting lock. Trying again. Apr 26 09:44:51 Error:[server] pool.c,set_lock(+65): Error setting lock. Trying again. Apr 26 09:46:37 Error:[server] pool.c,set_lock(+65): Error setting lock. Trying again. Apr 26 09:47:04 Error:[server] pool.c,set_lock(+65): Error setting lock. Trying again. Apr 26 09:53:54 Error:[server] pool.c,set_lock(+65): Error setting lock. Trying again. Apr 26 09:56:15 Error:[server] pool.c,set_lock(+65): Error setting lock. Trying again. Apr 26 09:56:29 Error:[server] pool.c,set_lock(+65): Error setting lock. Trying again. Apr 26 09:57:32 Error:[server] pool.c,set_lock(+65): Error setting lock. Trying again. Apr 26 09:57:45 Error:[server] pool.c,set_lock(+65): Error setting lock. Trying again. ---------------------------------------------------------------------- aaron - 26-Apr-07 18:46 ---------------------------------------------------------------------- The lock messages aren't severe, they just indicate that there's some contention on the locks. The time between those messages are long enough to indicate that nobody is caught in a tight loop or needing to try to get the lock more than twice (try once - fail, try again - succeed). These are also only scoreboard locks, used to coordinate between the child processes at startup, connection accept and finish, and when signal USR1 is received. I am still concerned about the transaction errors. Backing up to the original bug report, I want to see where we are with respect to these items... start dbmail-imap receive mails (check qmail-send log and see they are there in the queue) stop dbmail-imap qmail-send delivers the mails using dbmail-send start dbmail-imap new mails now in inbox dbmail-imapd has nothing to do with message delivery, and I can't see how any problems with dbmail-imapd would prevent message delivery. If there's a table lock being taken out by dbmail-imapd that is preventing dbmail-smtp/lmtp from delivering messages, that would not be good. We have seen client side issues with 2.2.4 where the client would not see new messages unless it disconnected and reconnected. Restarting the imap daemon out from under the client would have the same effect. This was due to incorrect imap replies from dbmail. Does this sound like it describes your situation? Are you seeing improvement now with dbmail_2_2_branch? using squirrelmail to read mails at the moment. - also seems to drop the imap connection from time to time - probably related too. Do you have SM configured to use a persistent IMAP connection? Otherwise it's connections are very short-lived, so it should be hard to see them dropped halfway. Hmm. We've done a lot of work on other mail clients getting angry at some of the imap responses in 2.2.4. Are you seeeing improvement now? ---------------------------------------------------------------------- LordVan - 30-Apr-07 12:13 ---------------------------------------------------------------------- I'll check those things later. one thing i noticed with 2.2.4 release was that when i used imap to connect to one mailbox another mailbox could still receive mails using dbmail-smtp but only the same one gave problems. - and it still happens from what i could see from a quick test earlier - will try to do more testing later of course. coudl it be that dbmail-imap puts a lock on a user related table? (some size table or quota?) Issue History Date Modified Username Field Change ====================================================================== 04-Apr-07 14:17 LordVan New Issue 04-Apr-07 16:31 LordVan File Added: dbmail-2.2.4-r1.patch 04-Apr-07 16:32 LordVan Note Added: 0002003 04-Apr-07 18:17 aaron Note Added: 0002004 04-Apr-07 18:30 aaron Note Added: 0002005 05-Apr-07 14:16 LordVan File Added: dbmail_and_postgres_log 2007-04-05 1300 passwords replaced.tar.bz2 05-Apr-07 14:16 LordVan Note Added: 0002012 05-Apr-07 14:28 LordVan Note Added: 0002013 05-Apr-07 17:08 LordVan Note Added: 0002014 10-Apr-07 13:42 LordVan Note Added: 0002023 10-Apr-07 15:38 aaron Note Added: 0002024 10-Apr-07 16:21 LordVan Note Added: 0002025 12-Apr-07 16:33 nethzt Issue Monitored: nethzt 13-Apr-07 11:45 LordVan Note Edited: 0002025 24-Apr-07 09:49 froeske Issue Monitored: froeske 24-Apr-07 09:53 froeske Note Added: 0002084 24-Apr-07 09:54 froeske Note Edited: 0002084 24-Apr-07 09:59 froeske Note Edited: 0002084 24-Apr-07 11:30 LordVan Note Added: 0002085 24-Apr-07 12:42 LordVan Note Added: 0002086 25-Apr-07 09:33 aaron Note Added: 0002088 25-Apr-07 13:37 LordVan Note Added: 0002091 25-Apr-07 14:36 LordVan Note Edited: 0002091 25-Apr-07 16:50 paul Note Added: 0002092 25-Apr-07 16:54 LordVan Note Added: 0002093 25-Apr-07 17:30 aaron Note Added: 0002094 26-Apr-07 10:07 LordVan Note Added: 0002099 26-Apr-07 11:00 LordVan Note Added: 0002100 26-Apr-07 18:46 aaron Note Added: 0002101 30-Apr-07 12:13 LordVan Note Added: 0002112 ====================================================================== _______________________________________________ Dbmail-dev mailing list Dbmail-dev@dbmail.org http://twister.fastxs.net/mailman/listinfo/dbmail-dev
