View Issue Details

Jump to NotesJump to History
IDProjectCategoryView StatusDate SubmittedLast Update
0005120SOGoWeb Mailpublic2020-08-06 14:082020-08-10 19:31
Reporterwimmer Assigned To 
PrioritynormalSeverityminorReproducibilityrandom
Status newResolutionopen 
Product Version4.3.2 
Summary0005120: Message is sended several times
Description

This happenes in some cases only. User sends message, but SOGo sends it 2-5 times.
Sender has 5 samples of this message in his Sent folder, every sample has different Message-ID.
Recipient receives all 5 messages.

In daily sogo.log I see 1200 records for sending message, 20 of them have this problem.
It has no user dependency and I see no relating error message in the log.

Here is log of that issue:
Aug 06 10:32:24 sogod [40612]: 147.228.130.24 "GET /SOGo/so/janecp00/Mail/0/folderDrafts/newDraft1596702743-1/edit HTTP/1.1" 200 349/0 0.265 - - 0 - 51
Aug 06 10:34:44 sogod [40591]: 147.228.130.24 "POST /SOGo/so/janecp00/Mail/0/folderDrafts/newDraft1596702743-1/send HTTP/1.1" 302 0/761 0.015 - - 0 - 19
Aug 06 10:34:47 sogod [40591]: 147.228.130.24 "POST /SOGo/so/janecp00/Mail/0/folderDrafts/newDraft1596702743-1/send HTTP/1.1" 200 21/761 0.412 - - 0 - 20
Aug 06 10:34:47 sogod [40562]: 147.228.130.24 "POST /SOGo/so/janecp00/Mail/0/folderDrafts/newDraft1596702743-1/send HTTP/1.1" 200 21/761 0.382 - - 0 - 15
Aug 06 10:34:48 sogod [40600]: 147.228.130.24 "POST /SOGo/so/janecp00/Mail/0/folderDrafts/newDraft1596702743-1/send HTTP/1.1" 200 21/761 0.382 - - 0 - 134
Aug 06 10:34:48 sogod [40678]: 147.228.130.24 "POST /SOGo/so/janecp00/Mail/0/folderDrafts/newDraft1596702743-1/send HTTP/1.1" 200 21/761 0.366 - - 0 - 46

TagsNo tags attached.

Activities

abma

abma

2020-08-07 09:03

reporter   ~0014646

we noticed this, too but couldn't find a way to reproduce it yet.
Christian Mack

Christian Mack

2020-08-10 13:53

developer   ~0014655

I only have seen that, if the storage of the send email in Folder Sent on the IMAP server takes too long to finish.
Then SOGo tries to send it again.
Was that on a high load interval on your IMAP server?
wimmer

wimmer

2020-08-10 17:59

reporter   ~0014661

I think it is not that case.
Look to my logs:

webmail/sogo server

Aug 10 14:29:48 sogod [34771]: 147.228.9.45 "POST /SOGo/so/#sender#/Mail/0/folderDrafts/newDraft1597062270-1/send HTTP/1.1" 302 0/2755 0.014 - - 0 - 27
Aug 10 14:29:51 sogod [40666]: 147.228.9.45 "POST /SOGo/so/#sender#/Mail/0/folderDrafts/newDraft1597062270-1/send HTTP/1.1" 200 81/2755 0.414 - - 0 - 18
Aug 10 14:29:51 sogod [40627]: 147.228.9.45 "POST /SOGo/so/#sender#/Mail/0/folderDrafts/newDraft1597062270-1/send HTTP/1.1" 200 21/2755 0.371 - - 0 - 18
Aug 10 14:29:51 sogod [35512]: 147.228.9.45 "POST /SOGo/so/#sender#/Mail/0/folderDrafts/newDraft1597062270-1/send HTTP/1.1" 200 21/2755 0.359 - - 0 - 15
Aug 10 14:29:51 sogod [40546]: 147.228.9.45 "POST /SOGo/so/#sender#/Mail/0/folderDrafts/newDraft1597062270-1/send HTTP/1.1" 200 21/2755 0.365 - - 0 - 17

smtp server

Aug 10 14:29:51 fred postfix/cleanup[673]: 3EEF3756B: hold: header Received: from webmail.zcu.cz (webmail.zcu.cz [147.228.57.30])??by fred.zcu.cz (Postfix) with ESMTP id 3EEF3756B??for <#recipient#@kap.zcu.cz>; Mon, 10 Aug 2020 14:29:51 +0200 (CEST) from webmail.zcu.cz[147.228.57.30]; from=<#sender#@rek.zcu.cz> to=<#recipient#@kap.zcu.cz> proto=ESMTP helo=<webmail.zcu.cz>
Aug 10 14:29:51 fred postfix/cleanup[18964]: 5762F7570: hold: header Received: from webmail.zcu.cz (webmail.zcu.cz [147.228.57.30])??by fred.zcu.cz (Postfix) with ESMTP id 5762F7570??for <#recipient#@kap.zcu.cz>; Mon, 10 Aug 2020 14:29:51 +0200 (CEST) from webmail.zcu.cz[147.228.57.30]; from=<#sender#@rek.zcu.cz> to=<#recipient#@kap.zcu.cz> proto=ESMTP helo=<webmail.zcu.cz>
Aug 10 14:29:51 fred postfix/cleanup[3615]: 5C7696847: hold: header Received: from webmail.zcu.cz (webmail.zcu.cz [147.228.57.30])??by fred.zcu.cz (Postfix) with ESMTP id 5C7696847??for <#recipient#@kap.zcu.cz>; Mon, 10 Aug 2020 14:29:51 +0200 (CEST) from webmail.zcu.cz[147.228.57.30]; from=<#sender#@rek.zcu.cz> to=<#recipient#@kap.zcu.cz> proto=ESMTP helo=<webmail.zcu.cz>
Aug 10 14:29:51 fred postfix/cleanup[673]: BF99C684E: hold: header Received: from webmail.zcu.cz (webmail.zcu.cz [147.228.57.30])??by fred.zcu.cz (Postfix) with ESMTP id BF99C684E??for <#recipient#@kap.zcu.cz>; Mon, 10 Aug 2020 14:29:51 +0200 (CEST) from webmail.zcu.cz[147.228.57.30]; from=<#sender#@rek.zcu.cz> to=<#recipient#@kap.zcu.cz> proto=ESMTP helo=<webmail.zcu.cz>

imap server

Aug 10 14:29:50 axor dovecot: imap-login: Login: user=<#sender#>, method=PLAIN, rip=147.228.57.30, lip=147.228.57.20, mpid=2324186, TLS, session=<DVtaHIWssKST5Dke>
Aug 10 14:29:50 axor dovecot: imap(#sender#)<2324186><DVtaHIWssKST5Dke>: Logged out in=713 out=84027 deleted=0 expunged=0 trashed=0 hdr_count=100 hdr_bytes=200 body_count=0 body_bytes=0
Aug 10 14:29:50 axor dovecot: imap-login: Login: user=<#sender#>, method=PLAIN, rip=147.228.57.30, lip=147.228.57.20, mpid=2324203, TLS, session=<ZHZjHIWszKST5Dke>
Aug 10 14:29:50 axor dovecot: imap(#sender#)<2324203><ZHZjHIWszKST5Dke>: Logged out in=117 out=973 deleted=0 expunged=0 trashed=0 hdr_count=0 hdr_bytes=0 body_count=0 body_bytes=0
Aug 10 14:29:51 axor dovecot: imap-login: Login: user=<#sender#>, method=PLAIN, rip=147.228.57.30, lip=147.228.57.20, mpid=2324223, TLS, session=<w99qHIWs2KST5Dke>
Aug 10 14:29:51 axor dovecot: imap-login: Login: user=<#sender#>, method=PLAIN, rip=147.228.57.30, lip=147.228.57.20, mpid=2324229, TLS, session=<9upsHIWs5KST5Dke>
Aug 10 14:29:51 axor dovecot: imap-login: Login: user=<#sender#>, method=PLAIN, rip=147.228.57.30, lip=147.228.57.20, mpid=2324230, TLS, session=<v0RtHIWs6KST5Dke>
Aug 10 14:29:51 axor dovecot: imap(#sender#)<2324223><w99qHIWs2KST5Dke>: save: box=Sent, uid=278, msgid=<9eda-5f313d80-49-b844580@256294720>, size=3808, from=<#sender#@rek.zcu.cz>
Aug 10 14:29:51 axor dovecot: imap(#sender#)<2324223><w99qHIWs2KST5Dke>: Logged out in=4181 out=2220 deleted=0 expunged=0 trashed=0 hdr_count=0 hdr_bytes=0 body_count=0 body_bytes=0
Aug 10 14:29:51 axor dovecot: imap(#sender#)<2324229><9upsHIWs5KST5Dke>: save: box=Sent, uid=279, msgid=<9eb3-5f313d80-8b-39bcf580@129892584>, size=3757, from=<#sender#@rek.zcu.cz>
Aug 10 14:29:51 axor dovecot: imap(#sender#)<2324229><9upsHIWs5KST5Dke>: Logged out in=4073 out=1746 deleted=0 expunged=0 trashed=0 hdr_count=0 hdr_bytes=0 body_count=0 body_bytes=0
Aug 10 14:29:51 axor dovecot: imap(#sender#)<2324230><v0RtHIWs6KST5Dke>: save: box=Sent, uid=280, msgid=<8ab8-5f313d80-5-57a10980@145399396>, size=3756, from=<#sender#@rek.zcu.cz>
Aug 10 14:29:51 axor dovecot: imap(#sender#)<2324230><v0RtHIWs6KST5Dke>: Logged out in=4007 out=1279 deleted=0 expunged=0 trashed=0 hdr_count=0 hdr_bytes=0 body_count=0 body_bytes=0
Aug 10 14:29:51 axor dovecot: imap-login: Login: user=<#sender#>, method=PLAIN, rip=147.228.57.30, lip=147.228.57.20, mpid=2324245, TLS, session=<S2ZzHIWsCqWT5Dke>
Aug 10 14:29:51 axor dovecot: imap(#sender#)<2324245><S2ZzHIWsCqWT5Dke>: save: box=Sent, uid=281, msgid=<9e62-5f313d80-39-16796ce0@222081511>, size=3757, from=<#sender#@rek.zcu.cz>
Aug 10 14:29:51 axor dovecot: imap(#sender#)<2324245><S2ZzHIWsCqWT5Dke>: Logged out in=4073 out=1746 deleted=0 expunged=0 trashed=0 hdr_count=0 hdr_bytes=0 body_count=0 body_bytes=0

=>
SOGo logs command for sending message at 14:29:48. It has 302 return code.
Then there are 3 seconds pause and then SOGo logs 4 command for sending the same message at 14:29:51. They have 200 return code.

smtp server logs first incoming message at 14:29:51.

imap server logs first command for saving message to Sent folder at 14:29:51.

All SOGo, smtp and imap server was not under load.
I see about 20 these cases every day, including weekend.

I could change SOGoSMTPServer to localhost when it could indicate something.
wimmer

wimmer

2020-08-10 19:31

reporter   ~0014662

I have large log file, so I did not join other record, which has relation to this issue.
Here it is:
Aug 10 14:29:48 sogod [34771]: <0x0x5601e68586a0[SOGoWebAuthenticator]> Expired session received, redirecting to login page.
Aug 10 14:29:48 sogod [34771]: <0x0x5601e68586a0[SOGoWebAuthenticator]> tried wrong password for user '2JTsPb8+Y4BcSn1thXhTBlQEtnkU0CrrAXXhaNDl55wWTvMbFh3r0OIkzgBgLX2PrMP7yHa85prKWuKaIOv/hFFpA/bilMT0o3SDc8Tf5tVrJ0cARihJMikUDnic9kA4sB+5+kWbJ6BadOawWSyj9junHJ8shEY5onGrH5+H6wfRZsZAJT07tadLWniH8J8KxFtYHerApK1gXvDVJMPuhg=='!
Aug 10 14:29:48 sogod [34771]: 147.228.9.45 "POST /SOGo/so/hbilkova/Mail/0/folderDrafts/newDraft1597062270-1/send HTTP/1.1" 302 0/2755 0.014 - - 0 - 27

So it looks it has relation to Expired session in SAML authentication which I use.
Users told me they did not see something wrong in their web browser and they were not redirected to Login page.
So forced Page redirection on Expired session could cause this issue...

Issue History

Date Modified Username Field Change
2020-08-06 14:08 wimmer New Issue
2020-08-07 09:03 abma Note Added: 0014646
2020-08-10 13:53 Christian Mack Note Added: 0014655
2020-08-10 17:59 wimmer Note Added: 0014661
2020-08-10 19:31 wimmer Note Added: 0014662