[Dovecot] 2.0.7 (0757f4f5b882): LMTP Server refuses queued mail

older
[Dovecot] Error from mobile client...

Thomas Leuxner

27 Nov 2010 27 Nov '10

3:49 p.m.

Hi,

not sure what is wrong with the mail, but the Dovecot LMTP won't accept it. This is actually the first ever occurrence, so I'm attaching the evidence for further diagnosis:

[…] Nov 26 18:01:49 spectre dkim-filter[1723]: A7BEA4086: no signature data Nov 26 18:01:49 spectre postfix/qmgr[6175]: A7BEA4086: from=bounce-1841919-268661@news.juno.co.uk, size=131577, nrcpt=1 (queue active) […] Nov 26 18:01:49 spectre postfix/lmtp[27788]: 19FB54088: to=tlx@leuxner.net, relay=spectre.leuxner.net[private/dovecot-lmtp], delay=0.27, delays=0.25/0/0/0.01, dsn=4.3.0, status=deferred (host spectre.leuxner .net[private/dovecot-lmtp] said: 451 4.3.0 Temporary internal failure (in reply to end of DATA command))

$ mailq -Queue ID- --Size-- ----Arrival Time---- -Sender/Recipient------- 19FB54088 131807 Fri Nov 26 18:01:49 bounce-1841919-268661@news.juno.co.uk (host spectre.leuxner.net[private/dovecot-lmtp] said: 451 4.3.0 Temporary internal failure (in reply to end of DATA command)) tlx@leuxner.net

-- 129 Kbytes in 1 Request.

Regards Thomas

Attachments:

19FB54088.gz (application/x-gzip — 12.4 KB)

Show replies by date

Timo Sirainen

27 Nov 27 Nov

9:44 p.m.

On 27.11.2010, at 13.49, Thomas Leuxner wrote:

...

.net[private/dovecot-lmtp] said: 451 4.3.0 Temporary internal failure (in reply to end of DATA command))

Nothing in Dovecot's log? Typically this should log an error.

Thomas Leuxner

9:47 p.m.

Am 27.11.2010 um 20:44 schrieb Timo Sirainen:

...

Nothing in Dovecot's log? Typically this should log an error.

Hi Timo,

the only thing that is logged is the brief message:

$ grep -i temporary /var/log/dovecot/dovecot.log Nov 26 18:01:49 spectre dovecot: lmtp(27789): Disconnect from local: Temporary internal failure Nov 26 18:09:23 spectre dovecot: lmtp(27789): Disconnect from local: Temporary internal failure Nov 26 18:19:23 spectre dovecot: lmtp(27843): Disconnect from local: Temporary internal failure Nov 26 18:39:23 spectre dovecot: lmtp(27922): Disconnect from local: Temporary internal failure Nov 26 19:19:23 spectre dovecot: lmtp(27981): Disconnect from local: Temporary internal failure […]

Regards Thomas

Thomas Leuxner

28 Nov 28 Nov

7:56 a.m.

Am 27.11.2010 um 20:44 schrieb Timo Sirainen:

...

Nothing in Dovecot's log? Typically this should log an error.

Nov 28 06:49:23 spectre postfix/qmgr[6175]: 4608E408C: from=vzmaild@ft-ms-l1.serverloft.de, size=307431, nrcpt=1 (queue active) Nov 28 06:49:23 spectre postfix/lmtp[18445]: 4608E408C: to=tlx@leuxner.net, relay=spectre.leuxner.net[private/dovecot-lmtp], delay=2360, delays=2360/0.01/0/0.01, dsn=4.3.0, status=deferred (host spectre.leuxner.net[private/dovecot-lmtp] said: 451 4.3.0 Temporary internal failure (in reply to end of DATA command))

Another mail stuck. Just a hunch: Mails over 128k cause trouble…

Stan Hoeppner

10:01 a.m.

Thomas Leuxner put forth on 11/27/2010 11:56 PM:

...

Am 27.11.2010 um 20:44 schrieb Timo Sirainen:

...
Nothing in Dovecot's log? Typically this should log an error.

Nov 28 06:49:23 spectre postfix/qmgr[6175]: 4608E408C: from=, size=307431, nrcpt=1 (queue active) Nov 28 06:49:23 spectre postfix/lmtp[18445]: 4608E408C: to=, relay=spectre.leuxner.net[private/dovecot-lmtp], delay=2360, delays=2360/0.01/0/0.01, dsn=4.3.0, status=deferred (host spectre.leuxner.net[private/dovecot-lmtp] said: 451 4.3.0 Temporary internal failure (in reply to end of DATA command))

Another mail stuck. Just a hunch: Mails over 128k cause trouble…

http://www.dovecot.org/list/dovecot-cvs/2009-April/013190.html Below, I believe, is the code generating the error. And it seems you're absolutely right about the 128KB issue. It seems the lmtpd is trying to append the mail to "/tmp/dovecot.lmtp." if the email is greater than 128KB. Is it possible the permissions you have on /tmp aren't compatible with lmtpd? static void client_input_data_handle(struct client *client) @@ -353,7 +407,11 @@ static void client_input_data_handle(str } } else if (client->state.data_end_idx == DATA_DOT_NEXT_POS) { /* saw a dot at the beginning of line. drop it. */ - client_input_add(client, data, i-1); + if (client_input_add(client, data, i-1) < 0) { + client_destroy(client, "451 4.3.0", + "Temporary internal failure"); + return; + } start = i; client->state.data_end_idx = 0; } else { @@ -366,7 +424,11 @@ static void client_input_data_handle(str rewind = client->state.data_end_idx - DATA_DOT_NEXT_POS + 1; i -= rewind; size -= rewind; } - client_input_add(client, data + start, i-start); + if (client_input_add(client, data + start, i-start) < 0) { + client_destroy(client, "451 4.3.0", + "Temporary internal failure"); + return; + } i_stream_skip(client->input, skip == 0 ? i : skip); if (i < size) { -- Stan

Thomas Leuxner

10:39 a.m.

Am 28.11.2010 um 09:01 schrieb Stan Hoeppner:

...

http://www.dovecot.org/list/dovecot-cvs/2009-April/013190.html

Below, I believe, is the code generating the error. And it seems you're absolutely right about the 128KB issue. It seems the lmtpd is trying to append the mail to "/tmp/dovecot.lmtp." if the email is greater than 128KB. Is it possible the permissions you have on /tmp aren't compatible with lmtpd?

Strange. I haven't changed the permissions, and there is also enough space to accommodate >128k mails :)

# ls -ald /tmp/; df -h /tmp/ drwxrwxrwt 3 root root 5120 Nov 28 09:25 /tmp/ Filesystem Size Used Avail Use% Mounted on /dev/mapper/vg0-tmp 248M 11M 226M 5% /tmp

Narrowing down the issue a bit. With the code that was present on Nov 22, those Newsletter mails worked (needless to say config wasn't changed):

Nov 22 14:43:46 spectre postfix/qmgr[6175]: 20F194088: from=subscriptions@lists.juno.co.uk, size=485127, nrcpt=1 (queue active) Nov 22 14:43:46 spectre clamsmtpd: 100080: from=subscriptions@lists.juno.co.uk, to=tlx@leuxner.net, status=CLEAN Nov 22 14:43:46 spectre postfix/smtp[18915]: 0A89E4086: to=tlx@leuxner.net, relay=127.0.0.1[127.0.0.1]:10025, delay=3.9, delays=2.6/0.01/0.05/1.3, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 20F194088) Nov 22 14:43:46 spectre postfix/smtpd[18917]: disconnect from localhost[127.0.0.1] Nov 22 14:43:46 spectre postfix/qmgr[6175]: 0A89E4086: removed Nov 22 14:43:46 spectre postfix/lmtp[18919]: 20F194088: to=tlx@leuxner.net, relay=spectre.leuxner.net[private/dovecot-lmtp], delay=1.4, delays=1.3/0.01/0/0.07, dsn=2.0.0, status=sent (250 2.0.0 tlx@leuxner.net wpSLISRy6kzISQAAqZii3w Saved) […]

At that time system was running on:

Nov 21 07:34:36 spectre dovecot: master: Dovecot v2.0.7 (f5bec4e94b55) starting up

Conclusion: some change in between broke it.

Bernhard Schmidt

2:23 p.m.

Thomas Leuxner tlx@leuxner.net wrote:

...

Narrowing down the issue a bit. With the code that was present on Nov 22, those Newsletter mails worked (needless to say config wasn't changed):

Same here, but I can limit the window some more. 8adacd9c03b2 from Nov 18th was fine and it was busted with 0bc3751c6657 on Nov 23rd. So it seems the problem has been introduced somewhere between f5bec4e94b55 and 0bc3751c6657.

Bernhard

Stan Hoeppner

29 Nov 29 Nov

1:36 a.m.

Bernhard Schmidt put forth on 11/28/2010 6:23 AM:

...

Thomas Leuxner wrote:

...
Narrowing down the issue a bit. With the code that was present on Nov 22, those Newsletter mails worked (needless to say config wasn't changed):

Same here, but I can limit the window some more. 8adacd9c03b2 from Nov 18th was fine and it was busted with 0bc3751c6657 on Nov 23rd. So it seems the problem has been introduced somewhere between f5bec4e94b55 and 0bc3751c6657.

The code I linked to was from 1.2.x and is over a year old. I'm having trouble finding the current version of that code segment in the source. In the mean time, I'm thinking the hard coding of "/tmp/" has probably been changed especially given that Timo left himself a note at that time to change it. If so, maybe the following changes in 0bc3751c6657 on Nov 23rd relating to "mail_temp_dir" may be involved: diff -r 66428c763354 -r 0bc3751c6657 src/lib-storage/mail-storage-settings.c --- a/src/lib-storage/mail-storage-settings.c Tue Nov 23 19:07:19 2010 +0000 +++ b/src/lib-storage/mail-storage-settings.c Tue Nov 23 19:37:56 2010 +0000 @@ -150,7 +150,7 @@ static const struct setting_define mail_user_setting_defines[] = { DEF(SET_STR, base_dir), DEF(SET_STR, auth_socket_path), - DEF(SET_STR, mail_temp_dir), + DEF(SET_STR_VARS, mail_temp_dir), DEF(SET_STR, mail_uid), DEF(SET_STR, mail_gid), Can you guys check your systems to confirm exactly where these mails

...

128KB are being written, or attempted to be written, if not to /tmp/dovecot.lmtp. If since Nov 23rd mail_temp_dir now points to a location other than /tmp/ you may still have a permissions problem, or maybe mail_temp_dir now points to a non-existent location, or?

I'm thinking I'm on the right track here, but I'm unable to pinpoint the exact cause of the problem. I'm not a coder, and until today was totally unfamiliar with any of the Dovecot source. I'm just playing Sherlock Holmes on this one as it piqued my interest. And, I'm hoping my efforts will assist Timo in identifying the problem a little quicker. -- Stan

Timo Sirainen

30 Nov 30 Nov

1:59 a.m.

On 28.11.2010, at 23.36, Stan Hoeppner wrote:

...

In the mean time, I'm thinking the hard coding of "/tmp/" has probably been changed especially given that Timo left himself a note at that time to change it. If so, maybe the following changes in 0bc3751c6657 on Nov 23rd relating to "mail_temp_dir" may be involved:

Yep. Thanks, fixed: http://hg.dovecot.org/dovecot-2.0/rev/77d582b2dc51

Thomas Leuxner

6:31 a.m.

Am 30.11.2010 um 00:59 schrieb Timo Sirainen:

...

On 28.11.2010, at 23.36, Stan Hoeppner wrote:

...
In the mean time, I'm thinking the hard coding of "/tmp/" has probably been changed especially given that Timo left himself a note at that time to change it. If so, maybe the following changes in 0bc3751c6657 on Nov 23rd relating to "mail_temp_dir" may be involved:

Yep. Thanks, fixed: http://hg.dovecot.org/dovecot-2.0/rev/77d582b2dc51

Issue confirmed fixed. Please see new thread for subsequent issues around SSL.

5076

Age (days ago)

5079

Last active (days ago)

List overview

9 comments

4 participants

participants (4)

Bernhard Schmidt
Stan Hoeppner
Thomas Leuxner
Timo Sirainen