Strange response with bad connection

[w-i-n-s]

Hi MailCore2 Team!

I want to send a message. And if mailcore2 can't do this and I get the error response - I start check operation (after good check I create a new SMTP session and try to send twice). Strange error when network is reachable (but I think quality isn't good)

2014-09-17 10:43:40.877 BlinkMail[42754:1141b] CFNetwork SSLHandshake failed (-9800)
2014-09-17 10:43:40.893 BlinkMail[42754:303] NMPC  | Error twice check {
    NSLocalizedDescription = "A stable connection to the server could not be established.";
}

send message op:

MCOSMTPSendOperation *sendOperation = [smtpSession sendOperationWithData:rfc822Data];
[sendOperation start:^(NSError *error) {
    if(error) {
        [self tryToSentTwiceMessage:message];
    }else{...}
}];

and check op:

MCOSMTPOperation *checkOperation = [session checkAccountOperationWithFrom:[MCOAddress addressWithDisplayName:displayName mailbox:email]];

[dinhvh]

I don't understand the question. Could you clarify?

[michaellenaghan]

I'm not sure, but this may be exactly the same thing I was about to post. I'm getting the same error (MCOErrorDomain, Code = 1, Description = "A stable connection to the server could not be established.") from MCOSMTPSendOperation. The problem is that I'm getting the error after the message has been successfully sent! Because of the error I retry, and of course I end up sending duplicates.

I haven't started digging into internals yet to see what might be happening. I don't know if this matters, but I'm seeing this in iOS 8.

One other detail: so far the errors are easier to reproduce with attachments of reasonable size.

[michaellenaghan]

OK, here's a little more info. I installed a progress callback; you can see that on sends with errors the progress callback doesn't quite reach the end:

2014-09-20 12:00:34.520 InTouch[1600:428215] __40-[INTSmtpMessageService addMessageAsync]_block_invoke318 progress: 1868577i of 1875102i
2014-09-20 12:00:34.521 InTouch[1600:428215] __40-[INTSmtpMessageService addMessageAsync]_block_invoke318 progress: 1872711i of 1875102i
2014-09-20 12:00:39.530 InTouch[1600:428215] __40-[INTSmtpMessageService addMessageAsync]_block_invoke353 error: 1 [Error Domain=MCOErrorDomain Code=1 "A stable connection to the server could not be established." UserInfo=0x178665840 {NSLocalizedDescription=A stable connection to the server could not be established.}]

Here's the re-send that followed it:

2014-09-20 12:00:43.123 InTouch[1600:428215] __40-[INTSmtpMessageService addMessageAsync]_block_invoke318 progress: 1872711i of 1875102i
2014-09-20 12:00:45.859 InTouch[1600:428215] __40-[INTSmtpMessageService addMessageAsync]_block_invoke318 progress: 1875102i of 1875102i

The thing is that the first message did make it through. Not only that, but the images sent in both copies of the mail are byte-for-byte identical.

[michaellenaghan]

Another example. Three total attempts, with the first two reporting errors and all three being successfully sent. Notice that the reported failures always seem to be at the very last packet.

2014-09-20 12:12:25.846 InTouch[1600:428215] __40-[INTSmtpMessageService addMessageAsync]_block_invoke318 progress: 1546125i of 1552858i
2014-09-20 12:12:25.854 InTouch[1600:428215] __40-[INTSmtpMessageService addMessageAsync]_block_invoke318 progress: 1550259i of 1552858i
2014-09-20 12:12:30.892 InTouch[1600:428215] __40-[INTSmtpMessageService addMessageAsync]_block_invoke353 error: 4 [Error Domain=MCOErrorDomain Code=1 "A stable connection to the server could not be established." UserInfo=0x170679040 {NSLocalizedDescription=A stable connection to the server could not be established.}]

2014-09-20 12:12:39.300 InTouch[1600:428215] __40-[INTSmtpMessageService addMessageAsync]_block_invoke318 progress: 1546125i of 1552858i
2014-09-20 12:12:39.301 InTouch[1600:428215] __40-[INTSmtpMessageService addMessageAsync]_block_invoke318 progress: 1550259i of 1552858i
2014-09-20 12:12:44.294 InTouch[1600:428215] __40-[INTSmtpMessageService addMessageAsync]_block_invoke353 error: 4 [Error Domain=MCOErrorDomain Code=1 "A stable connection to the server could not be established." UserInfo=0x170677780 {NSLocalizedDescription=A stable connection to the server could not be established.}]

2014-09-20 12:13:59.744 InTouch[1600:428215] __40-[INTSmtpMessageService addMessageAsync]_block_invoke318 progress: 1546125i of 1552858i
2014-09-20 12:13:59.746 InTouch[1600:428215] __40-[INTSmtpMessageService addMessageAsync]_block_invoke318 progress: 1550259i of 1552858i
2014-09-20 12:14:02.683 InTouch[1600:428215] __40-[INTSmtpMessageService addMessageAsync]_block_invoke318 progress: 1552858i of 1552858i

[michaellenaghan]

I had a bit more time to look into this. It looks like the issue is in mailesmtp_send_quit().

The all-but-last-packet thing is simply an artifact of the way the progress callback works. SMTPSession::sendMessage() calls mailesmtp_send_quit(). mailesmtp_send_quit() has responsibility for all of the in-between progress calls, while SMTPSession::sendMessage() takes care of the first and last. Naturally, SMTPSession::sendMessage() doesn't bother with the last progress call if mailesmtp_send_quit() returns an error.

So: the problem is that mailesmtp_send_quit() returns an error after successfully sending the entire message.

Btw, I grabbed my copy of MailCore roughly two weeks ago, so everything is (or should be) pretty current. (libetpan-ios.a is dated 14 August 2014.)

[michaellenaghan]

I know you know your own code. :-) I'm just documenting my investigation; I hope that helps. And maybe someone else who knows more can chime in...

In LibEtPan mailesmtp_send_quit() calls mailsmtp_data_message_quit() to do the bulk of the work. mailsmtp_data_message_quit() makes these calls:

r = send_data(session, message, size);
if (r == -1)
    return MAILSMTP_ERROR_STREAM;
r = send_quit(session);
r = read_response(session);

So the error is happening either at the end of send_data() or (more likely I think) in read_response().

[michaellenaghan]

OK, it looks like the error is in or related to read_response(). I captured a failed session using the connection logger:

IoHooFaIjI6Cvp8PwVhrXdNHjVM/rvaTPiHSf2YNRmAl1O4AyRkE5NepWf7OfhOG18mdmZsckV9B
vcqshiAJYDNTpmRdwFezRyWnayR5s8bJ7s/Nf41fs+an4WQ614bU3NuvJHcemRXzJ/wjni//AJ8m
/L/69ft7dWsF3C1tcqHRhgg8jFYP/CIeHP8An0j/AO+R/hXPW4evK6KjjXY//9k=
--541e0bab_6b8b4567_78b--
.

2014-09-20 19:20:15.836 InTouch[1931:499646] event logged:0x178163a80 4294967295 withData: 
2014-09-20 19:20:15.836 InTouch[1931:499646] event logged:0x178163a80 4294967295 withData: 
2014-09-20 19:20:15.837 InTouch[1931:499646] event logged:0x178163a80 4294967295 withData: 
2014-09-20 19:20:15.838 InTouch[1931:499646] event logged:0x178163a80 1 withData: QUIT

2014-09-20 19:20:15.839 InTouch[1931:499646] event logged:0x178163a80 4294967295 withData: 
2014-09-20 19:20:15.840 InTouch[1931:499646] event logged:0x178163a80 4294967295 withData: 
2014-09-20 19:20:20.841 InTouch[1931:499646] event logged:0x178163a80 4 withData: 
2014-09-20 19:20:20.849 InTouch[1931:499351] __40-[INTSmtpMessageService addMessageAsync]_block_invoke369 error: 1 [Error Domain=MCOErrorDomain Code=1 "A stable connection to the server could not be established." UserInfo=0x170469240 {NSLocalizedDescription=A stable connection to the server could not be established.}]

The "4" in the last "event logged" line refers to this MCOConnectionLogType:

/** Error while receiving data. The data passed to the log will be nil.*/
MCOConnectionLogTypeErrorReceived,

[michaellenaghan]

OK, I've taken this just about as far as I think I will. One or two last comments.

First, I tried forcing this bit of code to use the non-pipelining branch:

if ((mSmtp->esmtp & MAILSMTP_ESMTP_PIPELINING) != 0) {
    r = mailesmtp_send_quit(mSmtp, MCUTF8(from->mailbox()), 0, NULL,
        address_list,
        messageData->bytes(), messageData->length());
}
else {
    r = mailesmtp_send(mSmtp, MCUTF8(from->mailbox()), 0, NULL,
        address_list,
        messageData->bytes(), messageData->length());
    mailsmtp_quit(mSmtp);
}

That didn't work; mailesmtp_send() still returned an error code--error code 3, in fact, which appears to be ErrorParse. Under the hood mailesmtp_send() calls mailsmtp_data_message(), and, like mailsmtp_data_message_quit(), mailsmtp_data_message() also calls read_response(). That brings everything back to the original problem: reading or parsing the server's response.

So, second: my temporary and very hacky kludge will be to ignore connection errors that appear to happen after the last bit of data has been sent.

Btw, all of this is against Gmail.

[michaellenaghan]

I sometimes call checkAccountOperationWithFrom: with a five second session timeout. I discovered that that timeout was still in effect when I was sending mail. I fixed that--and so far, at least, I'm not seeing the end-of-send errors anymore. At this point I don't know whether or not that's a coincidence.

[dinhvh]

Are you creating the send operation from a dispatch queue? A common mistake is to try to use mailcore in a dispatch queue and managing thread safety poorly.

[michaellenaghan]

I've been reviewing everything this morning and that doesn't seem to be the case. Not only that, but the error is rather deterministic: if I decrease the timeout value for the SMTP session to a small value (say, <= 5 seconds) LibEtPan very often (but not always) returns an error from read_response(). (It seems like the smaller the timeout the easier it is to reproduce the problem.)

[dinhvh]

Yes. It will depend on server performance. If you set a 30 sec timeout, everything should be fine for most of the case.