short write error while running mattermail as systemd

[cseeger-epages]

Running mattermail as a systemd service gives short write error after some time of running.

After some time the tcp connection seems to break (dont know why) but does not get renewed. The checkAndWait() function returns an error, then waiting 30 seconds https://github.com/rodcorsi/mattermail/blob/56def3a50866d4f4cec4415180d4902e310f3f34/mmail/mattermail.go#L75 . But the tcp connection does not get renewed so the same broken connection is used and the system does not recover from the error. I checked if the connection changes using lsof -p $(ps aux | grep mattermail | head -1 | awk '{print $2}') giving sth. like

mattermai 16528 root    3u  IPv4            3621110      0t0     TCP mattermost-helper.xxx:52623->x.x.x.x:imap2 (ESTABLISHED)

the port never changes so the connection seems to be reused every time even if the tcp connection is broken in some way.

The error gets provided by github.com/emersion/go-imap/client https://github.com/emersion/go-imap/blob/9e7e4429063c1a251cf96bb3306129d2af1e6d4a/client/client.go#L178 https://github.com/emersion/go-imap/blob/9e7e4429063c1a251cf96bb3306129d2af1e6d4a/client/client.go#L246 while trying to write to the server chan.

[cseeger-epages]

i think after checking the checkAndWait error the connection needs to be reseted but i did not find a good way to do it yet

[rodcorsi]

I think is possible the problem is inside of checkConnection function. There we have an if to reuse the imap client. Another possibility is a bug inside of go-imap lib, maybe an upgrade could solve.

[rodcorsi]

Your log:

DEBG iphh-support-mails        12:51:10 MailProviderImap.CheckNewMessage
DEBG iphh-support-mails        12:51:10 MailProviderImap.CheckConnection: Connection state 0x857960
DEBG iphh-support-mails        12:51:10 MailProviderImap.selectMailBox: Select mailbox: Test
EROR iphh-support-mails        12:51:10 MailProviderImap.selectMailBox: Error on select Test
DEBG iphh-support-mails        12:51:10 MailProviderImap.CheckNewMessage: select MailBox:  Test
EROR iphh-support-mails        12:51:10 MatterMail.InitMatterMail Error on check new messsage: select mailbox: select mailbox 'Test': short write
DEBG iphh-support-mails        12:51:10 check new message: select mailbox: select mailbox 'Test': short write
INFO iphh-support-mails        12:51:10 Try again in 30s

You can see a small bug in this line Connection state 0x857960, but I fixed in PR #70 and rebase release-4.1 Please test again to we discover which state the connection is when we have the error

[cseeger-epages]

yeah i fixed this bug in my debug binary but the connection state looks good even if the problem occures. I did not understand exactly what the number tells me https://godoc.org/github.com/emersion/go-imap#ConnState in my case i get a connection state 6.

[cseeger-epages]

You added the connection states to your PR (nice) so i get selectedState, here is the output of my debug binary (i added some debug to imap-go/client execute function to find the line giving me the error).

Feb 08 10:38:50 mattermost-helper mattermail[21330]: DEBG mattermail-test        10:38:50 MailProviderImap.CheckNewMessage
Feb 08 10:38:50 mattermost-helper mattermail[21330]: DEBG mattermail-test        10:38:50 MailProviderImap.CheckConnection: Connection state 6
Feb 08 10:38:50 mattermost-helper mattermail[21330]: DEBG mattermail-test        10:38:50 MailProviderImap.selectMailBox: Select mailbox: Testordner
Feb 08 10:38:50 mattermost-helper mattermail[21330]: EROR mattermail-test        10:38:50 MailProviderImap.selectMailBox: Error on select Testordner
Feb 08 10:38:50 mattermost-helper mattermail[21330]: DEBG mattermail-test        10:38:50 MailProviderImap.CheckNewMessage: select MailBox:  Testordner
Feb 08 10:38:50 mattermost-helper mattermail[21330]: EROR mattermail-test        10:38:50 MatterMail.InitMatterMail Error on check new messsage: select mailbox: select mailbox 'Testordner': go-imap/client: execute error: execute, write error: short write
Feb 08 10:38:50 mattermost-helper mattermail[21330]: DEBG mattermail-test        10:38:50 check new message: select mailbox: select mailbox 'Testordner': go-imap/client: execute error: execute, write error: short write
Feb 08 10:38:50 mattermost-helper mattermail[21330]: DEBG mattermail-test        10:38:50 MailProviderImap.CheckConnection: Connection state 6
Feb 08 10:38:50 mattermost-helper mattermail[21330]: INFO mattermail-test        10:38:50 Try again in 30s

[cseeger-epages]

short write errors occur when write operations transfer fewer bytes than requested on a tcp stream. I also checked if the connection on the mailserver was there and everything looks fine. If i have time today i will take a deeper look into the tcp stream with tcpdump. Is there some function from the imapClient to rebuild the tcp connection and take care of the environment (used port etc, i tried the Terminate() function hoping it will reconnect but this only results in using a port that does not exists anymore)

[rodcorsi]

// In a selected state, a mailbox has been selected to access.
// This state is entered when a mailbox has been successfully
// selected.
SelectedState = AuthenticatedState + 1<<2 // 6

Following the go-imap documents, it looks like the client already has the folder selected and Mattermail tries to select another folder or the same folder. Update: The operation to select another folder should be allowed, I don't know why this error, maybe the IDLE mode needs to be terminated before to change the folder

[cseeger-epages]

since it is related to here https://github.com/emersion/go-imap/issues/173. Im actually testing a fix reconnecting and close the old connection. This seems to work if i have cleaned the code and artifacts ill drop a PR for 4.1-release

[cseeger-epages]

here it is: https://github.com/rodcorsi/mattermail/pull/71. The fix now should resolv also various other tcp connection errors by dropping the old connection and reconnecting.

[rodcorsi]

Waiting for emersion/go-imap#107 to upgrade the lib