search

haraka / Haraka

A fast, highly extensible, and event driven SMTP server
https://haraka.github.io
MIT License
5.09k stars 661 forks source link

Haraka is throwing errors when the client sends QUIT too early #1410

Closed dstibrany closed 7 years ago

dstibrany commented 8 years ago

Haraka version

2.7.2

Observed behaviour

I occasionally see clients send 'QUIT' commands before we send '250 Message Queued' replies. In those situations Haraka throws:

2016-04-08T13:54:53.00749 [ERROR] [EF24362D-72DC-4DBB-8B60-00DAD4A12BEF.1] [core] cmd_quit failed: Error: We are already running hooks! Fatal error! 2016-04-08T13:54:53.00778 [ERROR] [-] [core] undefinedError: We are already running hooks! Fatal error!0[ 'Error: We are already running hooks! Fatal error!', 2016-04-08T13:54:53.00779 ' at Object.plugins.run_hooks (/usr/local/lib/node_modules/Haraka/plugins.js:281:15)', 2016-04-08T13:54:53.00780 ' at Connection.cmd_quit (/usr/local/lib/node_modules/Haraka/connection.js:1193:13)', 2016-04-08T13:54:53.00781 ' at Connection.process_line (/usr/local/lib/node_modules/Haraka/connection.js:280:29)', 2016-04-08T13:54:53.00782 ' at Connection._process_data (/usr/local/lib/node_modules/Haraka/connection.js:423:18)', 2016-04-08T13:54:53.00783 ' at /usr/local/lib/node_modules/Haraka/connection.js:632:41', 2016-04-08T13:54:53.00783 ' at process._tickDomainCallback (node.js:486:13)' ]

Expected behaviour

1) Any ideas why the client is behaving this way? 2) Any way to handle this more cleanly? In particular, I'd prefer to have the option to DENY these, because with 421 replies I keep getting this message sent (and the subsequent error) over and over.

Steps to reproduce

Here is the last bit of data from the client before the error occurs:

...
2016-04-08T13:54:53.00168 [DATA] [EF24362D-72DC-4DBB-8B60-00DAD4A12BEF.1] [core] C: 0px; font-size: 0px; overflow: hidden; mso-hide: all"/></body>\r
2016-04-08T13:54:53.00181 [DATA] [EF24362D-72DC-4DBB-8B60-00DAD4A12BEF.1] [core] C: </html>\r
2016-04-08T13:54:53.00193 [DATA] [EF24362D-72DC-4DBB-8B60-00DAD4A12BEF.1] [core] C: <!-- /Wrapper -->\r
2016-04-08T13:54:53.00206 [DATA] [EF24362D-72DC-4DBB-8B60-00DAD4A12BEF.1] [core] C: ------=_NextPart_000_0186_01D1911A.E9F01E60--\r
2016-04-08T13:54:53.00220 [DATA] [EF24362D-72DC-4DBB-8B60-00DAD4A12BEF.1] [core] C: \r
2016-04-08T13:54:53.00233 [DATA] [EF24362D-72DC-4DBB-8B60-00DAD4A12BEF.1] [core] C: .\r
2016-04-08T13:54:53.00307 [DEBUG] [EF24362D-72DC-4DBB-8B60-00DAD4A12BEF.1] [core] running data_post hooks
2016-04-08T13:54:53.00319 [DEBUG] [EF24362D-72DC-4DBB-8B60-00DAD4A12BEF.1] [core] running data_post hook in hdmailer plugin
2016-04-08T13:54:53.00646 [PROTOCOL] [EF24362D-72DC-4DBB-8B60-00DAD4A12BEF.1] [core] C: QUIT state=1
2016-04-08T13:54:53.00656 [DEBUG] [EF24362D-72DC-4DBB-8B60-00DAD4A12BEF.1] [core] running quit hooks
2016-04-08T13:54:53.00749 [ERROR] [EF24362D-72DC-4DBB-8B60-00DAD4A12BEF.1] [core] cmd_quit failed: Error: We are already running hooks! Fatal error!

Thanks, let me know if there's any more info I can provide.

Dave

baudehlo commented 8 years ago

Hi Dave, nice to hear from you!

(for other Haraka devs reading this - I used to work at the company using this, and wrote the original plugin here)

Knowing a bit about what goes on in hdmailer, it's related to handling attachments and pausing/resuming is my guess.

We wouldn't process the QUIT from the client if the connection was paused. At least I hope not - that code hasn't broken for my uses of it.

I thought I had put enough code into hdmailer to support this - I guess not.

You can see what is required by looking into the attachment plugin: https://github.com/haraka/Haraka/blob/master/plugins/attachment.js - look for where we call pause and resume. Check against those places in hdmailer and see if you're missing something. The basic principal is that you're calling resume() too soon. Add logging to the plugin to see if you're calling resume before the processing of attachments ends.

Alternatively just contact me personally (you have my email) and I'll take a poke at the code - it might be a straightforward fix.

As a side note, I'd love to improve all of this hackery. But it's a big back-burner ticket in Haraka. Unfortunately due to attachments using streams, we have yet to figure out a way to make this transparent to plugins. Maybe for 3.0.

On Fri, Apr 8, 2016 at 6:21 PM, Dave Stibrany notifications@github.com wrote:

Haraka version

2.7.2 Observed behaviour

I occasionally see clients send 'QUIT' commands before we send '250 Message Queued' replies. In those situations Haraka throws:

2016-04-08T13:54:53.00749 [ERROR] [EF24362D-72DC-4DBB-8B60-00DAD4A12BEF.1] [core] cmd_quit failed: Error: We are already running hooks! Fatal error! 2016-04-08T13:54:53.00778 [ERROR] [-] [core] undefinedError: We are already running hooks! Fatal error!0[ 'Error: We are already running hooks! Fatal error!', 2016-04-08T13:54:53.00779 ' at Object.plugins.run_hooks (/usr/local/lib/node_modules/Haraka/plugins.js:281:15)', 2016-04-08T13:54:53.00780 ' at Connection.cmd_quit (/usr/local/lib/node_modules/Haraka/connection.js:1193:13)', 2016-04-08T13:54:53.00781 ' at Connection.process_line (/usr/local/lib/node_modules/Haraka/connection.js:280:29)', 2016-04-08T13:54:53.00782 ' at Connection._process_data (/usr/local/lib/node_modules/Haraka/connection.js:423:18)', 2016-04-08T13:54:53.00783 ' at /usr/local/lib/node_modules/Haraka/connection.js:632:41', 2016-04-08T13:54:53.00783 ' at process._tickDomainCallback (node.js:486:13)' ] Expected behaviour

1) Any ideas why the client is behaving this way? 2) Any way to handle this more cleanly? In particular, I'd prefer to have the option to DENY these, because with 421 replies I keep getting this message sent (and the subsequent error) over and over. Steps to reproduce

Here is the last bit of data from the client before the error occurs:

... 2016-04-08T13:54:53.00168 [DATA] [EF24362D-72DC-4DBB-8B60-00DAD4A12BEF.1] [core] C: 0px; font-size: 0px; overflow: hidden; mso-hide: all"/>\r 2016-04-08T13:54:53.00181 [DATA] [EF24362D-72DC-4DBB-8B60-00DAD4A12BEF.1] [core] C: \r 2016-04-08T13:54:53.00193 [DATA] [EF24362D-72DC-4DBB-8B60-00DAD4A12BEF.1] [core] C: \r 2016-04-08T13:54:53.00206 [DATA] [EF24362D-72DC-4DBB-8B60-00DAD4A12BEF.1] [core] C: ------=_NextPart_000_0186_01D1911A.E9F01E60--\r 2016-04-08T13:54:53.00220 [DATA] [EF24362D-72DC-4DBB-8B60-00DAD4A12BEF.1] [core] C: \r 2016-04-08T13:54:53.00233 [DATA] [EF24362D-72DC-4DBB-8B60-00DAD4A12BEF.1] [core] C: .\r 2016-04-08T13:54:53.00307 [DEBUG] [EF24362D-72DC-4DBB-8B60-00DAD4A12BEF.1] [core] running data_post hooks 2016-04-08T13:54:53.00319 [DEBUG] [EF24362D-72DC-4DBB-8B60-00DAD4A12BEF.1] [core] running data_post hook in hdmailer plugin 2016-04-08T13:54:53.00646 [PROTOCOL] [EF24362D-72DC-4DBB-8B60-00DAD4A12BEF.1] [core] C: QUIT state=1 2016-04-08T13:54:53.00656 [DEBUG] [EF24362D-72DC-4DBB-8B60-00DAD4A12BEF.1] [core] running quit hooks 2016-04-08T13:54:53.00749 [ERROR] [EF24362D-72DC-4DBB-8B60-00DAD4A12BEF.1] [core] cmd_quit failed: Error: We are already running hooks! Fatal error!

Thanks, let me know if there's any more info I can provide.

Dave

— You are receiving this because you are subscribed to this thread. Reply to this email directly or view it on GitHub https://github.com/haraka/Haraka/issues/1410

dstibrany commented 8 years ago

Hey Matt! Great to hear from you as well.

I had to end up going in and making some changes to the plugin, because we now support html emails. So we need to try and decide if an attachment is a true attachment or if it's part of an html email and making that decision turns out to be pretty hard.

Anyways, looks like this bug was introduced when I added that functionality. I'll try adding some more logging around pause/resume as you suggested.

Thanks!

Dave

baudehlo commented 8 years ago

You could probably just ignore attachments with a content-id header, no?

On Mon, Apr 11, 2016 at 10:37 AM, Dave Stibrany notifications@github.com wrote:

Closed #1410 https://github.com/haraka/Haraka/issues/1410.

— You are receiving this because you commented. Reply to this email directly or view it on GitHub https://github.com/haraka/Haraka/issues/1410#event-622569394

dstibrany commented 8 years ago

I think the problem was that some legitimate attachments still have a content-id, like when somebody drags an image into a gmail compose window, gmail treats it like an inline attachment.

smfreegard commented 8 years ago

Isn't Content-Disposition more appropriate here. e.g. Content-Disposition: attachment ...

dstibrany commented 8 years ago

A lot of clients seem to mark them as 'inline', iPhone's mail app for example.

baudehlo commented 8 years ago

Not all clients add the content disposition either. Isn't email fun :)

On Apr 11, 2016, at 5:03 PM, Steve Freegard notifications@github.com wrote:

Isn't Content-Disposition more appropriate here. e.g. Content-Disposition: attachment ...

— You are receiving this because you commented. Reply to this email directly or view it on GitHub

dstibrany commented 8 years ago

Processing attachments correctly has been crazy. I had to write some heuristic to make a decision, and in cases where we're not sure, get both the html body and the attachments. That way we're at least somewhat guaranteed not to miss anything.

baudehlo commented 8 years ago

You'll also want to upgrade to 2.8 as soon as you can because it handles the headers/file names more correctly.

On Apr 11, 2016, at 5:17 PM, Dave Stibrany notifications@github.com wrote:

Processing attachments correctly has been crazy. I had to write some heuristic to make a decision, and in cases where we're not sure, get both the html body and the attachments. That way we're at least somewhat guaranteed not to miss anything.

— You are receiving this because you commented. Reply to this email directly or view it on GitHub

dstibrany commented 8 years ago

Nice, thanks!

dstibrany commented 7 years ago

Hey Matt,

We're having this issue pop up again. We end up reading the client's QUIT too early and then throw errors. I'm able to reproduce this locally against the stock "attachment.js" plugin via netcat:

$ cat broken.txt | nc -i 1 localhost 25

See the attached bad.email file. I'm pretending that the file is a zip so that it goes through the unarchive process and also note that I needed to add a \r\n after the final dot to get it to work in netcat. broken.txt

Do you have an suggestions on how to work around this? This issue only happens with 2 or 3 clients, but happens consistently for those clients.

Some additional info: OS: Ubuntu 14.04 Node version: v4.6.0 Haraka version: 2.8.12

baudehlo commented 7 years ago

There's no gap between the headers and the body. Is that intentional?

On Tue, Mar 21, 2017 at 11:15 AM, Dave Stibrany notifications@github.com wrote:

Hey Matt,

We're having this issue pop up again. We end up reading the client's QUIT too early and then throw errors. I'm able to reproduce this locally against the stock "attachment.js" plugin via netcat:

$ cat broken.txt | nc -i 1 localhost 25

See the attached bad.email file. I'm pretending that the file is a zip so that it goes through the unarchive process and also note that I needed to add a \r\n after the final dot to get it to work in netcat. broken.txt https://github.com/haraka/Haraka/files/858574/broken.txt

Do you have an suggestions on how to work around this? This issue only happens with 2 or 3 clients, but happens consistently for those clients.

Some additional info: OS: Ubuntu 14.04 Node version: v4.6.0 Haraka version: 2.8.12

— You are receiving this because you commented. Reply to this email directly, view it on GitHub https://github.com/haraka/Haraka/issues/1410#issuecomment-288111019, or mute the thread https://github.com/notifications/unsubscribe-auth/AAobY5aTCbUcrxt01yQ-XLOCbOlcIUbKks5rn-l0gaJpZM4IDbym .

dstibrany commented 7 years ago

Damn, the no gap was unintentional. With the gap the test case now totally passes both on the stock attachment.js and our own plugin. I'll see if I can find another test case that breaks our app.

I pushed a change to how we do pause/resume of the stream, so I'll see if that makes this go away.

baudehlo commented 7 years ago

In fairness it shouldn't crash Haraka, even with no gap. Is it doing that?

On Tue, Mar 21, 2017 at 12:29 PM, Dave Stibrany notifications@github.com wrote:

Damn, the no gap was unintentional. With the gap the test case now totally passes both on the stock attachment.js and our own plugin. I'll see if I can find another test case that breaks our app.

I pushed a change to how we do pause/resume of the stream, so I'll see if that makes this go away.

— You are receiving this because you commented. Reply to this email directly, view it on GitHub https://github.com/haraka/Haraka/issues/1410#issuecomment-288136002, or mute the thread https://github.com/notifications/unsubscribe-auth/AAobY9Rfy2PBHgjeqoxPtC5F-jrC16J6ks5rn_rjgaJpZM4IDbym .

dstibrany commented 7 years ago

Not a hard crash, just lots of errors:

[ERROR] [BA8E40D0-3D19-4233-8C54-386388B00007.1] [core] cmd_quit failed: Error: We are already running hooks! Fatal error!
[ERROR] [-] [core] undefinedError: We are already running hooks! Fatal error!0[ 'Error: We are already running hooks! Fatal error!',
  '    at Object.plugins.run_hooks (/home/vagrant/.nvm/versions/node/v4.6.0/lib/node_modules/Haraka/plugins.js:396:15)',
  '    at Connection.cmd_quit (/home/vagrant/.nvm/versions/node/v4.6.0/lib/node_modules/Haraka/connection.js:1279:13)',
  '    at Connection.process_line (/home/vagrant/.nvm/versions/node/v4.6.0/lib/node_modules/Haraka/connection.js:319:29)',
  '    at Connection._process_data (/home/vagrant/.nvm/versions/node/v4.6.0/lib/node_modules/Haraka/connection.js:464:18)',
  '    at Immediate._onImmediate (/home/vagrant/.nvm/versions/node/v4.6.0/lib/node_modules/Haraka/connection.js:680:37)',
  '    at processImmediate [as _immediateCallback] (timers.js:383:17)' ]

and then we send a 421 Internal Server Error

baudehlo commented 7 years ago

OK, but that error also shouldn't occur. I'll have a look anyway.

On Tue, Mar 21, 2017 at 1:28 PM, Dave Stibrany notifications@github.com wrote:

Not a hard crash, just lots of errors:

[ERROR] [BA8E40D0-3D19-4233-8C54-386388B00007.1] [core] cmd_quit failed: Error: We are already running hooks! Fatal error! [ERROR] [-] [core] undefinedError: We are already running hooks! Fatal error!0[ 'Error: We are already running hooks! Fatal error!', ' at Object.plugins.run_hooks (/home/vagrant/.nvm/versions/node/v4.6.0/lib/node_modules/Haraka/plugins.js:396:15)', ' at Connection.cmd_quit (/home/vagrant/.nvm/versions/node/v4.6.0/lib/node_modules/Haraka/connection.js:1279:13)', ' at Connection.process_line (/home/vagrant/.nvm/versions/node/v4.6.0/lib/node_modules/Haraka/connection.js:319:29)', ' at Connection._process_data (/home/vagrant/.nvm/versions/node/v4.6.0/lib/node_modules/Haraka/connection.js:464:18)', ' at Immediate._onImmediate (/home/vagrant/.nvm/versions/node/v4.6.0/lib/node_modules/Haraka/connection.js:680:37)', ' at processImmediate [as _immediateCallback] (timers.js:383:17)' ]

and then we send a 421 Internal Server Error

— You are receiving this because you commented. Reply to this email directly, view it on GitHub https://github.com/haraka/Haraka/issues/1410#issuecomment-288155666, or mute the thread https://github.com/notifications/unsubscribe-auth/AAobY9lp0wFNP8qa7ijJPLKzIPIlziPlks5roAjFgaJpZM4IDbym .

dstibrany commented 7 years ago

Awesome, thanks Matt.

dstibrany commented 7 years ago

Hey, I've managed to create another minimal test case that breaks both our app and the attachment plugin. The key was having an attachment size >= 16384 bytes, and sending a QUIT right after the final dot. If I reduce the attachment size down to 16383, everything works fine. 

$ cat min_test_case.txt | nc -i 1 localhost 25

min_test_case.txt

dstibrany commented 7 years ago

Bump on this, I think it might be a legitimate issue and am wondering if you guys can confirm. Running the above test case against the stock attachment plugin should reproduce it.

smfreegard commented 7 years ago

@dstibrany - looks like an easy fix. Can you change this line https://github.com/haraka/Haraka/blob/master/plugins.js#L402

to 

    if (!/^(reset_transaction|disconnect|quit|deny|log)$/.test(hook) &&

And let me know that it fixes this.

dstibrany commented 7 years ago

@smfreegard That fix prevents all of the "'Error: We are already running hooks!" errors from being thrown, but the attachment is then not processed in my test case. Haraka reads the QUIT too early, then disconnects, at which point the data_post hooks do not run.

I updated the test case; my previous version was using a content-type of application/pdf which was skipping the unarchive code. The new version has a content-type of application/zip; if you send it in to the attachment plugin as is (with the above fix you provided), it skips the attachment. If you remove one line of text from the body, it processes the attachment and works fine.

min_test_case.txt

This issue seems to be related to having a body size > 16k and having the client send the QUIT early.

Let me know if there's any more info I can provide or any way that I can help.

smfreegard commented 7 years ago

@dstibrany - Ok reading back, your 'test-case' is broken though. You're making the SMTP Client send the ending dot and then immediately pipelining a QUIT straight after which a real SMTP client would never do. What should happen in that case is that Haraka shouldn't deliver the message because the client didn't wait for the response, it shouldn't process the attachment because the remote end has disconnected, so it would be wasting it's time to do so.

The 16Kb thing is probably what was already buffered by the kernel in a single packet, so splitting it would mean the QUIT would likely be received in a separate packet, allowing it to proceed through the attachment hooks before the QUIT is seen by Haraka.

In your test case - if this were a real SMTP client, it should retry the message again because it doesn't know the message was delivered, because it never received the '250' in response to sending the ending '.', so it should be retried again.

So - there's either a bug in your code, or, your attachment hooks are taking so long (e.g. usually this would be > 30s) that the remote clients are dropping the connections on a timeout. Looking at your logs should tell you this e.g.:

Apr 11 04:07:06 mail1-ewh haraka[25302]: [NOTICE] [544C61F5-BE96-41AD-BBCD-895F18082605.1] [core] message mid="1820796063.60037570.1491898011346.JavaMail.rocketman@push-dispatcher4" size=89417 rcpts=1/0/0 delay=10.825 code=CONT msg=""

or - if you don't have a message entry (this will only fire after hook_data_post completes):

Apr 11 04:07:11 mail1-ewh haraka[25302]: [NOTICE] [544C61F5-BE96-41AD-BBCD-895F18082605.1] [core] disconnect ip=50.115.211.91 rdns="mta391s1.r.groupon.com" helo="mta391s1.r.groupon.com" relay=N early=N esmtp=Y tls=Y pipe=N errors=0 txns=1 rcpts=1/0/0 msgs=1/0/0 bytes=89417 lr="" time=20.197

baudehlo commented 7 years ago

I still think this is a bug, not a broken test case. Yes the client SHOULD wait for the response to final dot, but even if it doesn't we shouldn't be processing the QUIT command before processing attachments finishes, assuming the connection is paused/resumed properly.

I haven't had time to look into it yet. Maybe this easter weekend.

On Tue, Apr 11, 2017 at 4:40 AM, Steve Freegard notifications@github.com wrote:

@dstibrany https://github.com/dstibrany - Ok reading back, your 'test-case' is broken though. You're making the SMTP Client send the ending dot and then immediately pipelining a QUIT straight after which a real SMTP client would never do. What should happen in that case is that Haraka shouldn't deliver the message because the client didn't wait for the response, it shouldn't process the attachment because the remote end has disconnected, so it would be wasting it's time to do so.

The 16Kb thing is probably what was already buffered by the kernel in a single packet, so splitting it would mean the QUIT would likely be received in a separate packet, allowing it to proceed through the attachment hooks before the QUIT is seen by Haraka.

In your test case - if this were a real SMTP client, it should retry the message again because it doesn't know the message was delivered, because it never received the '250' in response to sending the ending '.', so it should be retried again.

So - there's either a bug in your code, or, your attachment hooks are taking so long (e.g. usually this would be > 30s) that the remote clients are dropping the connections on a timeout. Looking at your logs should tell you this e.g.:

Apr 11 04:07:06 mail1-ewh haraka[25302]: [NOTICE] [544C61F5-BE96-41AD-BBCD-895F18082605.1] [core] message mid="1820796063.60037570.1491898011346.JavaMail. rocketman@push-dispatcher4" size=89417 rcpts=1/0/0 delay=10.825 code=CONT msg=""

or - if you don't have a message entry (this will only fire after hook_data_post completes):

Apr 11 04:07:11 mail1-ewh haraka[25302]: [NOTICE] [544C61F5-BE96-41AD-BBCD-895F18082605.1] [core] disconnect ip=50.115.211.91 rdns="mta391s1.r.groupon.com" helo=" mta391s1.r.groupon.com" relay=N early=N esmtp=Y tls=Y pipe=N errors=0 txns=1 rcpts=1/0/0 msgs=1/0/0 bytes=89417 lr="" time=20.197

— You are receiving this because you commented. Reply to this email directly, view it on GitHub https://github.com/haraka/Haraka/issues/1410#issuecomment-293190749, or mute the thread https://github.com/notifications/unsubscribe-auth/AAobYwYxQ6rKM5zQDRwOPgVSBUo1NH8Vks5ruzx_gaJpZM4IDbym .

dstibrany commented 7 years ago

Is it possible that the client is doing something bizarre? This issue does not happen with > 99% of our users, but happens consistently for those ones. Here's an example, the attachment processing took < 1s but the client still appears to be sending the QUIT early, or has already sent it.

2017-04-10T17:41:58.22501 [PROTOCOL] [7AFDF64E-85E2-44B7-9819-F2A7EC6F5ADC] [core] C: EHLO server.example.com state=1
... rest of the message
2017-04-10T17:41:58.70248 [DATA] [7AFDF64E-85E2-44B7-9819-F2A7EC6F5ADC.1] [core] C: .\r
2017-04-10T17:41:58.70288 [DEBUG] [7AFDF64E-85E2-44B7-9819-F2A7EC6F5ADC.1] [core] running data_post hooks
2017-04-10T17:41:58.70306 [DEBUG] [7AFDF64E-85E2-44B7-9819-F2A7EC6F5ADC.1] [core] running data_post hook in hdmailer plugin
2017-04-10T17:41:58.70384 [PROTOCOL] [7AFDF64E-85E2-44B7-9819-F2A7EC6F5ADC.1] [core] C: QUIT state=1
2017-04-10T17:41:58.70396 [DEBUG] [7AFDF64E-85E2-44B7-9819-F2A7EC6F5ADC.1] [core] running quit hooks
2017-04-10T17:41:58.70464 [ERROR] [7AFDF64E-85E2-44B7-9819-F2A7EC6F5ADC.1] [core] cmd_quit failed: Error: We are already running hooks! Fatal error!
2017-04-10T17:41:58.70703 [PROTOCOL] [7AFDF64E-85E2-44B7-9819-F2A7EC6F5ADC.1] [core] S: 421 Internal Server Error
2017-04-10T17:41:58.70734 [DEBUG] [7AFDF64E-85E2-44B7-9819-F2A7EC6F5ADC.1] [core] running reset_transaction hooks
2017-04-10T17:41:58.70747 [DEBUG] [7AFDF64E-85E2-44B7-9819-F2A7EC6F5ADC.1] [core] running disconnect hooks
2017-04-10T17:41:58.70761 [NOTICE] [7AFDF64E-85E2-44B7-9819-F2A7EC6F5ADC.1] [core] disconnect ip=x.x.x.222 rdns="unallocated-static.rogers.com" helo="server.example.com" relay=N early=N esmtp=Y tls=N pipe=Y errors=0 txns=1 rcpts=1/0/0 msgs=0/0/0 bytes=120808 lr="421 Internal Server Error" time=0.572
smfreegard commented 7 years ago

@dstibrany - that log excerpt shows that the client immediately sends QUIT after the dot, there is not even a seconds delay whilst it waits for the response. Whatever is doing that is terminally busted IMO and isn't a real SMTP client.

dstibrany commented 7 years ago

Yep it's super frustrating. Originally we had one customer whose client was behaving this way and I wrote it off as a one-off error that I'll never encounter again; then recently we had a second customer who exhibits the same behaviour so I started looking into it again.

What do you mean by "isn't a real SMTP client", though? I'm fairly sure that these users aren't doing anything fancy and are using some sort of email client to send this stuff in (although maybe the client they're using is busted).

baudehlo commented 7 years ago

The clients aren't doing anything wrong. See https://tools.ietf.org/html/rfc2920 section 4 the example even shows pipelining of the QUIT command.

We have a bug.

On Tue, Apr 11, 2017 at 3:20 PM, Dave Stibrany notifications@github.com wrote:

Yep it's super frustrating. Originally we had one customer whose client was behaving this way and I wrote it off as a one-off error that I'll never encounter again; then recently we had a second customer who exhibits the same behaviour so I started looking into it again.

What do you mean by "isn't a real SMTP client", though? I'm fairly sure that these users aren't doing anything fancy and are using some sort of email client to send this stuff in (although maybe the client they're using is busted).

— You are receiving this because you commented. Reply to this email directly, view it on GitHub https://github.com/haraka/Haraka/issues/1410#issuecomment-293372845, or mute the thread https://github.com/notifications/unsubscribe-auth/AAobY-ngjl32Ytpp0dyw_hrpPAk571Urks5ru9KQgaJpZM4IDbym .

baudehlo commented 7 years ago

See the linked PR. It requires changes to whatever plugin you're using to process attachments - a pause when you enter the end state, and a resume when you're done. Plus there's a minor core change which appears to help.

dstibrany commented 7 years ago

Thanks for looking into that, I'll give this a try today.

dstibrany commented 7 years ago

Nice, that worked!