A NOTE has been added to this issue. ====================================================================== http://www.dbmail.org/mantis/view.php?id=581 ====================================================================== Reported By: niki Assigned To: ====================================================================== Project: DBMail Issue ID: 581 Category: LMTP daemon Reproducibility: always Severity: minor Priority: normal Status: new target: ====================================================================== Date Submitted: 05-May-07 09:24 CEST Last Modified: 15-May-07 21:32 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. 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 ====================================================================== _______________________________________________ Dbmail-dev mailing list Dbmail-dev@dbmail.org http://twister.fastxs.net/mailman/listinfo/dbmail-dev
