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: 05-May-07 12:01 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. 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 ====================================================================== _______________________________________________ Dbmail-dev mailing list Dbmail-dev@dbmail.org http://twister.fastxs.net/mailman/listinfo/dbmail-dev
