The following issue has been RESOLVED. ====================================================================== http://www.dbmail.org/mantis/view.php?id=581 ====================================================================== Reported By: niki Assigned To: aaron ====================================================================== Project: DBMail Issue ID: 581 Category: LMTP daemon Reproducibility: always Severity: minor Priority: normal Status: resolved target: Resolution: fixed Fixed in Version: 2.2.5 ====================================================================== Date Submitted: 05-May-07 09:24 CEST Last Modified: 15-May-07 23:07 CEST ====================================================================== Summary: lmtp locking issue Description: I just noticed this in my logs:
May 5 01:47:14 [postfix/qmgr] 5BD1E9B9D1E: from=<[EMAIL PROTECTED]>, size=2689, nrcpt=1 (queue active) May 5 01:47:14 [dbmail/lmtpd] Error Error setting lock. Trying again. May 5 01:47:14 [dbmail/lmtpd] Message incoming connection from [127.0.0.1] by pid [9633] May 5 01:47:14 [dbmail/lmtpd] Error Short write [0 < 3], is your /tmp filesystem full? May 5 01:47:14 [dbmail/lmtpd] Error dbmail_message_new_from_stream() failed May 5 01:50:00 [fcron] Job /usr/bin/test -x /usr/sbin/run-crons && /usr/sbin/run-crons started for user systab (pid 6195) May 5 01:50:02 [fcron] Job /usr/bin/test -x /usr/sbin/run-crons && /usr/sbin/run-crons completed May 5 01:57:14 [postfix/lmtp] 5BD1E9B9D1E: to=<[EMAIL PROTECTED]>, orig_to=<[EMAIL PROTECTED]>, relay=localhost[127.0.0.1]:24, delay=9436, delays=8836/0.02/0.05/600, dsn=4.4.2, status=deferred (conversation with localhost[127.0.0.1] timed out while sending end of data -- message may be sent more than once) May 5 01:57:14 [dbmail/lmtpd] Error unexpected EOF from stdio (client hangup?) I don't know if this is related to http://www.dbmail.org/mantis/view.php?id=561 ====================================================================== ---------------------------------------------------------------------- niki - 05-May-07 12:01 ---------------------------------------------------------------------- I have now tried to log what happens with lmtp with log level 5 May 5 10:35:34 [postfix/qmgr] 5BD1E9B9D1E: from=<[EMAIL PROTECTED]>, size=2689, nrcpt=1 (queue active) May 5 10:35:34 [dbmail/lmtpd] Info:[serverchild] serverchild.c,select_and_accept(+252): received connection - Last output repeated twice - May 5 10:35:34 [dbmail/lmtpd] Info:[serverchild] serverchild.c,select_and_accept(+275): connection accepted May 5 10:35:34 [dbmail/lmtpd] Info:[serverchild] serverchild.c,select_and_accept(+223): waiting for connection May 5 10:35:34 [dbmail/lmtpd] Message:[serverchild] serverchild.c,PerformChildTask(+342): incoming connection from [127.0.0.1] by pid [18772] May 5 10:35:34 [dbmail/lmtpd] Debug:[serverchild] serverchild.c,PerformChildTask(+365): client info init complete, calling client handler May 5 10:35:34 [dbmail/lmtpd] Debug:[lmtp] lmtp.c,lmtp(+255): incoming buffer: [LHLO niki2.guldbrand.net] May 5 10:35:34 [dbmail/lmtpd] Debug:[lmtp] lmtp.c,lmtp(+269): command issued :cmd [LHLO], value [niki2.guldbrand.net]_ May 5 10:35:34 [dbmail/lmtpd] Debug:[lmtp] lmtp.c,lmtp(+277): command looked up as commandtype 0 May 5 10:35:34 [dbmail/lmtpd] Debug:[lmtp] lmtp.c,lmtp(+255): incoming buffer: [MAIL FROM:<[EMAIL PROTECTED]>] May 5 10:35:34 [dbmail/lmtpd] Debug:[lmtp] lmtp.c,lmtp(+269): command issued :cmd [MAIL], value [FROM:<[EMAIL PROTECTED]>]_ May 5 10:35:34 [dbmail/lmtpd] Debug:[lmtp] lmtp.c,lmtp(+277): command looked up as commandtype 4 May 5 10:35:34 [dbmail/lmtpd] Info:[misc] misc.c,find_bounded(+374): Found [EMAIL PROTECTED] of length [22] between '<' and '>' so next skip [28] May 5 10:35:34 [dbmail/lmtpd] Debug:[lmtp] lmtp.c,lmtp(+255): incoming buffer: [RCPT TO:<[EMAIL PROTECTED]>] May 5 10:35:34 [dbmail/lmtpd] Debug:[lmtp] lmtp.c,lmtp(+269): command issued :cmd [RCPT], value [TO:<[EMAIL PROTECTED]>]_ May 5 10:35:34 [dbmail/lmtpd] Debug:[lmtp] lmtp.c,lmtp(+277): command looked up as commandtype 9 May 5 10:35:34 [dbmail/lmtpd] Info:[misc] misc.c,find_bounded(+374): Found [EMAIL PROTECTED] of length [28] between '<' and '>' so next skip [32] May 5 10:35:34 [dbmail/lmtpd] Debug:[dsn] dsn.c,dsnuser_init(+215): dsnuser initialized May 5 10:35:34 [dbmail/lmtpd] Info:[dsn] dsn.c,dsnuser_resolve(+596): checking if [EMAIL PROTECTED] is a valid username, alias, or catchall. May 5 10:35:34 [dbmail/lmtpd] Debug:[auth] authsql.c,auth_check_user_ext(+219): checking user [EMAIL PROTECTED] in alias table May 5 10:35:34 [dbmail/lmtpd] Debug:[auth] authsql.c,auth_check_user_ext(+236): checks [0] May 5 10:35:34 [dbmail/lmtpd] Debug:[sql] dbpgsql.c,db_query(+281): [SELECT deliver_to FROM dbmail_aliases WHERE lower(alias) = lower('[EMAIL PROTECTED]') AND lower(alias) <> lower(deliver_to)] May 5 10:35:34 [dbmail/lmtpd] Debug:[auth] authsql.c,auth_check_user_ext(+270): into checking loop May 5 10:35:34 [dbmail/lmtpd] Debug:[auth] authsql.c,auth_check_user_ext(+276): checking user [EMAIL PROTECTED] to 4 May 5 10:35:34 [dbmail/lmtpd] Debug:[auth] authsql.c,auth_check_user_ext(+219): checking user [4] in alias table May 5 10:35:34 [dbmail/lmtpd] Debug:[auth] authsql.c,auth_check_user_ext(+236): checks [1] May 5 10:35:34 [dbmail/lmtpd] Debug:[sql] dbpgsql.c,db_query(+281): [SELECT deliver_to FROM dbmail_aliases WHERE lower(alias) = lower('4') AND lower(alias) <> lower(deliver_to)] May 5 10:35:34 [dbmail/lmtpd] Debug:[auth] authsql.c,auth_check_user_ext(+258): adding [4] to deliver_to address May 5 10:35:34 [dbmail/lmtpd] Debug:[dsn] dsn.c,address_has_alias(+262): user [EMAIL PROTECTED] found total of [1] aliases May 5 10:35:34 [dbmail/lmtpd] Info:[dsn] dsn.c,dsnuser_resolve(+603): delivering [EMAIL PROTECTED] as an alias. May 5 10:35:34 [dbmail/lmtpd] Debug:[lmtp] lmtp.c,lmtp(+255): incoming buffer: [DATA] May 5 10:35:34 [dbmail/lmtpd] Debug:[lmtp] lmtp.c,lmtp(+277): command looked up as commandtype 3 May 5 10:35:34 [dbmail/lmtpd] Debug:[lmtp] lmtp.c,lmtp(+532): requesting sender to begin message. May 5 10:35:34 [dbmail/lmtpd] Error:[message] dbmail-message.c,_set_content_from_stream(+385): Short write [0 < 3], is your /tmp filesystem full? May 5 10:35:34 [dbmail/lmtpd] Debug:[message] dbmail-message.c,_set_content_from_stream(+417): parse message May 5 10:35:34 [dbmail/lmtpd] Error:[lmtp] lmtp.c,lmtp(+556): dbmail_message_new_from_stream() failed May 5 10:45:34 [postfix/lmtp] 5BD1E9B9D1E: to=<[EMAIL PROTECTED]>, orig_to=<[EMAIL PROTECTED]>, relay=localhost[127.0.0.1]:24, delay=41136, delays=40536/0.03/0.04/600, dsn=4.4.2, status=deferred (conversation with localhost[127.0.0.1] timed out while sending end of data -- message may be sent more than once) May 5 10:45:34 [dbmail/lmtpd] Error:[misc] misc.c,discard_client_input(+1302): unexpected EOF from stdio (client hangup?) May 5 10:45:34 [dbmail/lmtpd] Debug:[dsn] dsn.c,dsnuser_free(+241): dsnuser freed May 5 10:45:34 [dbmail/lmtpd] Debug:[serverchild] serverchild.c,PerformChildTask(+370): client handling complete, closing streams May 5 10:45:34 [dbmail/lmtpd] Info:[serverchild] serverchild.c,PerformChildTask(+372): connection closed May 5 10:45:34 [dbmail/lmtpd] Info:[serverchild] serverchild.c,select_and_accept(+223): waiting for connection May 5 10:45:34 [postfix/qmgr] warning: qmgr_active_corrupt: save corrupt file queue active id 5BD1E9B9D1E: No such file or directory The qmgr warning is because of i had requeued it while it was trying to deliver the mail. ---------------------------------------------------------------------- niki - 06-May-07 21:42 ---------------------------------------------------------------------- Was just inspired by http://www.dbmail.org/mantis/view.php?id=584 to cat the message in to dbmail-smtp, and it gives me the same result as with dbmail-lmtp, so now i have a strace and a ltrace of the issue here, i have attached the strace to this bug. Collected with: cat deffered-5BD1E9B9D1E | strace -o strace-dbmail.log dbmail-smtp -u niki ---------------------------------------------------------------------- niki - 06-May-07 22:01 ---------------------------------------------------------------------- Is NULL chars (0x00) allowed in mails ? Because the first one occurs at offset 0x24b in the deffered mail. Don't know that much about the mail standards, so... ---------------------------------------------------------------------- aaron - 07-May-07 01:34 ---------------------------------------------------------------------- Yes, nul bytes are allowed. We fixed an issue related to that after 2.2.4 was released. If you'd like to recompile from source, it is a pair of one-line changes in dbmail-message.c: 375c375 < putslen = g_mime_stream_write_string(fstream, buf); --- > putslen = g_mime_stream_write(fstream, buf, getslen); 383c383 < if (putslen < getslen && getslen > 1) { --- > if (putslen < getslen && getslen > putslen+1) { Please let us know if you can confirm that these two lines fix this issue for you! ---------------------------------------------------------------------- niki - 15-May-07 21:32 ---------------------------------------------------------------------- Hi aaron. I have now upgraded to 2.2.5-rc2 and this issue has been fixed, so you can close it with fixed in 2.2.5 or something like that. Thanks for your help. ---------------------------------------------------------------------- aaron - 15-May-07 23:07 ---------------------------------------------------------------------- Great, glad to hear that everything's working! Issue History Date Modified Username Field Change ====================================================================== 05-May-07 09:24 niki New Issue 05-May-07 09:24 niki File Added: deffered-5BD1E9B9D1E 05-May-07 12:01 niki Note Added: 0002134 06-May-07 21:42 niki Note Added: 0002137 06-May-07 21:43 niki File Added: strace-dbmail.log 06-May-07 22:01 niki Note Added: 0002138 07-May-07 01:34 aaron Note Added: 0002139 15-May-07 21:32 niki Note Added: 0002181 15-May-07 23:07 aaron Status new => resolved 15-May-07 23:07 aaron Fixed in Version => 2.2.5 15-May-07 23:07 aaron Resolution open => fixed 15-May-07 23:07 aaron Assigned To => aaron 15-May-07 23:07 aaron Note Added: 0002182 ====================================================================== _______________________________________________ Dbmail-dev mailing list Dbmail-dev@dbmail.org http://twister.fastxs.net/mailman/listinfo/dbmail-dev
