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:
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.
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
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>&1I 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 connectionhope this helps!
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.
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.
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
handleAppendMessagefunction inworker/imap/movecopy.go.Specifically, the call to
imapw.client.Appendis returning anerrwith messageEOF. 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.Pipewriter 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 :)
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:
- aerc specifies the literal length smaller than the actual length of the message (?)
- go-imap sends the truncated literal and then fails, not sending the terminating CRLF
- 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
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()), nilIf 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()), nilWhen 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.
I am only using SMTP and the error seems random at best.
- aerc specifies the literal length smaller than the actual length of the message (?)
Pardon, I meant "larger".
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)
Not go-message, but
go-imapof course.
It means message is too short, first value (1479) is expected, 1478 is actual length.
I have found it!
I suspect problem is in
Message-Idand potentially in Date?Message-Iddiffers 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.PostActionwhich 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!
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-Idand potentially in Date?Message-Iddiffers 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.PostActionwhich 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
Sorry about the quoted message, I hit send too early.
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.