~sircmpwn/aerc2#269: 
EOF Error

Sometimes when I send emails, I get an error that just says "EOF", and I'm not sure what seems to be causing it. I tried a number of things to reproduce it, including:

  • Adding a new line at the end of an email
  • Not adding a new line at the end of an email
  • Writing a long email
  • Starting an email and waiting a long time to send it

It seems to occur randomly, and I'm not able to discern any pattern. It's also not clear whether emails are still sent when I get this error. My friend reported receiving duplicate emails as I rewrote and re-sent an email, but I'm not sure if this has occurred every time. No email is saved to my Sent folder. I would estimate this occurs for 5 to 10 percent of my emails.

This is with Fastmail, but I believe I have also observed it on Gmail. I'm using the most recent commit on Master on Debian 10. I am sorry for not having more details.

Status
RESOLVED FIXED
Submitter
~alexwennerberg
Assigned to
No-one
Submitted
11 months ago
Updated
2 months ago
Labels
bug

~alexwennerberg 11 months ago

I'm working on trying to get more details on this issue -- it seems as though the email still sends but it isn't copied to my sent folder

~hdb2 11 months ago

I've been playing with aerc today and have experienced this same issue (running the latest aerc on MacOS with fastmail). I ran aerc like so:

aerc > aerc.log 2>&1

I was able to get the error to occur, here's the very end of the error log:

2019/08/21 13:34:06 Sending mail
smtp
2019/08/21 13:34:06 rcpt to: [REDACTED]
2019/08/21 13:34:06 (ui)=> *types.AppendMessage
2019/08/21 13:34:06 <-(ui) *types.AppendMessage(82)
DONE
FdId9w OK Completed
2019/08/21 13:34:06 ->(ui) *types.Error:*types.AppendMessage
eGiEog APPEND "Sent" (\Seen) "21-Aug-2019 13:34:06 -0500" {326+}
Content-Transfer-Encoding: quoted-printable
Content-Type: text/plain; charset=UTF-8
Date: Wed, 21 Aug 2019 13:34:06 -0500
Subject: test
From: "REDACTED" <REDACTED>
To: <REDACTED>
Message-Id: <BWFIVBX24BY8.YUAX4C7LU6I6@REDACTED>

yet another test from me!
mizm5A IDLE
2019/08/21 13:34:06 (ui)<= *types.Error(83):*types.AppendMessage(82)
2019/08/21 13:34:06 EOF
eGiEog BAD junk after literal
2019/08/21 13:34:12 Closing Unix server: accept unix /var/folders/6t/7xxzvyyx5dv2tyg8ncx9nqj40000gn/T/aerc.sock: use of closed network connection

hope this helps!

~devonrjohnson 10 months ago

I have also had this issue occur multiple times on a Linux system. I have not seemed to find any pattern to the issue in terms of content of the email. Only pattern I have had is that it has occurred multiple times sending to one email address. This is also sending from a gmail account.

~muellerj 10 months ago

I have experienced that problem twice as well. Re-writing the exact same email has worked in both cases. I don't have meaningful logs.

~alexwennerberg referenced this from #293 10 months ago

~akarle 9 months ago

I am also sporadically getting this error (aerc latest from master using IMAP via fastmail). My error log is identical to ~hdb2 's log.

I've never really written Go before, so I was limited to some good old println debugging. I narrowed it down to the handleAppendMessage function in worker/imap/movecopy.go.

Specifically, the call to imapw.client.Append is returning an err with message EOF. In every case (of the dozens I reproduced), the mail was sent, but it was not appended to my Sent folder.

If I had to guess what the EOF is, it is likely an error due to the io.Pipe writer being closed before the reader reads. The go documentation backs this up.

If this really is the case, I think it must be that the reader is called multiple times, and there is a race condition for the reader to finish and the writer to close. I say this because I believe the Write call (somewhere in composer.WriteMessage) should block until the data is read at least once. Once this happens, the thread can go on to close the writer.

Not sure where to go from here (maybe digging into the imap library, but that would be outside my domain knowledge and language knowledge :) ), but wanted to post my findings in case someone else can use it to dig deeper!

Hope this helps! Really enjoying aerc so far :)

~foxcpp 8 months ago

https://github.com/emersion/go-imap/issues/311#issuecomment-560037069 https://github.com/emersion/go-imap/issues/311#issuecomment-560042828

My guess of what happens here:

  1. aerc specifies the literal length smaller than the actual length of the message (?)
  2. go-imap sends the truncated literal and then fails, not sending the terminating CRLF
  3. aerc then proceeds to send another IMAP command, here is how the connection stream will look like:
{6}MMMMMMNNNNTAG commandCRLF
        ^~~~~~~~~~~~~~~~

As viewed by the server, the literal last octet is at the ^ sign, but the actual command ends at CRLF, everything in between (NNNNN and the next command) and is unexpected garbage, the server reports it:

eGiEog BAD junk after literal

I created a PR in go-imap that makes Append return a more useful error in this case and then close the connection. If somebody can reproduce this problem with it, the error will confirm my guess above (and also provide some context for further troubleshooting).

To use my PR with aerc, append the following line to the go.mod file in the repo root:

replace github.com/emersion/go-imap => github.com/foxcpp/go-imap append-eof

~keur 8 months ago

Thanks foxcpp. There are two places where aerc gets the message length of the APPEND command.

If the user is using SMTP, aerc counts the amount of bytes sent over the socket exposed by go-smtp.

        wc, err := conn.Data()                                                 
        if err != nil {                                                        
            return 0, errors.Wrap(err, "conn.Data")                            
        }                                                                      
        defer wc.Close()                                                       
        ctr := datacounter.NewWriterCounter(wc)                                
        composer.WriteMessage(header, ctr)                                     
        return int(ctr.Count()), nil     

If the user is using the sendmail binary, aerc counts the number of bytes it sends to sendmail stdin.

        wc, err := cmd.StdinPipe()                                                
        if err != nil {                                                           
            return 0, errors.Wrap(err, "cmd.StdinPipe")                           
        }                                                                         
        defer wc.Close()                                                       
        go cmd.Run()                                                           
        ctr := datacounter.NewWriterCounter(wc)                                
        composer.WriteMessage(header, ctr)                                     
        return int(ctr.Count()), nil

When aerc writes to the pipe for go-imap, it writes the same exact data.


            worker := composer.Worker()                                        
            r, w := io.Pipe()                                                  
            
            ...
                                                            
            header, _, _ := composer.PrepareHeader()                           
            composer.WriteMessage(header, w)                                   
            w.Close()      

I don't see how these values differ between calls. Are people experiencing issues using SMTP or sendmail? I'm unable to repro with SMTP.

~robjloranger 8 months ago

I am only using SMTP and the error seems random at best.

~foxcpp 8 months ago

  1. aerc specifies the literal length smaller than the actual length of the message (?)

Pardon, I meant "larger".

~ernierasta 8 months ago

Hi everyone, this issue is making me crazy (today I sent one mail 3 times to one of aerc devs ;-) ). I have upgraded go-message to actual version (1.0.2) in go.mod and I have this log:

pI5hLg OK Fetch completed (0.001 + 0.000 secs).
2019/12/09 21:59:02 ->(ui) *types.MessageBodyPart:*types.FetchMessageBodyPart
2019/12/09 21:59:02 ->(ui) *types.MessageInfo:*types.FetchMessageBodyPart
2019/12/09 21:59:02 ->(ui) *types.Done:*types.FetchMessageBodyPart
cu4bIg IDLE
2019/12/09 21:59:02 (ui)<= *types.MessageBodyPart(124):*types.FetchMessageBodyPart(123)
2019/12/09 21:59:02 (ui)<= *types.MessageInfo(125):*types.FetchMessageBodyPart(123)
2019/12/09 21:59:02 (ui)<= *types.Done(126):*types.FetchMessageBodyPart(123)
+ idling
2019/12/09 21:59:58 Sending mail
smtps
2019/12/09 21:59:59 rcpt to: [ernierasta@zori.cz]
2019/12/09 21:59:59 (ui)=> *types.AppendMessage
2019/12/09 21:59:59 <-(ui) *types.AppendMessage(127)
DONE
cu4bIg OK Idle completed (0.001 + 57.140 + 57.140 secs).
2019/12/09 21:59:59 error reading response: read tcp 192.168.1.112:53200->37.205.9.57:993: use of closed network connection
2019/12/09 21:59:59 ->(ui) *types.Error:*types.AppendMessage
2019/12/09 21:59:59 (ui)<= *types.Error(128):*types.AppendMessage(127)
2019/12/09 21:59:59 imap: size of Literal is not equal to Len() (1479 != 1478)

~ernierasta 8 months ago

Not go-message, but go-imap of course.

~ernierasta 8 months ago

It means message is too short, first value (1479) is expected, 1478 is actual length.

~ernierasta 8 months ago

I have found it!

I suspect problem is in Message-Id and potentially in Date? Message-Id differs for message sent and for message copied to Sent folder. That is why size is different. We takes amount of bytes sent by SMTP and then try to apply it on message with different ID?

More info: when copying we are using worker.PostAction which will then call: worker.setId(msg) which will ... you guessed it, set new Message-ID for message. But we are expecting, that message length will be the same!

Jonas Müller 8 months ago

Very cool analysis. This would also explain why the error only crops up sporadically - for messages where the old and new Ids have the same length, it sees no problem.

On 9. Dec 2019, at 23:23, ~ernierasta outgoing@sr.ht wrote:

I have found it!

I suspect problem is in Message-Id and potentially in Date? Message-Id differs for message sent and for message copied to Sent folder. That is why size is different. We takes amount of bytes sent by SMTP and then try to apply it on message with different ID?

More info: when copying we are using worker.PostAction which will then call: worker.setId(msg) which will ... you guessed it, set new Message-ID for message. But we are expecting, that message length will be the same!

-- View on the web: https://todo.sr.ht/~sircmpwn/aerc2/269#comment-5163

Jonas Müller referenced this from #269 8 months ago

~muellerj 8 months ago

Sorry about the quoted message, I hit send too early.

~ernierasta 7 months ago

Just for the record, my "More info:" section in previous message is wrong. composer.PrepareHeader() is generating new Message-ID and Date. Sending my naive solution now.

~sircmpwn REPORTED FIXED 7 months ago

Apoc referenced this from #408 2 months ago

Register here or Log in to comment, or comment via email.