External Fetcher - DELE without RETR

Use this forum if you want to discuss a problem or ask a question related to a hMailServer beta release.
Post Reply
sprint
Normal user
Normal user
Posts: 30
Joined: 2018-01-31 01:36

External Fetcher - DELE without RETR

Post by sprint » 2018-03-09 02:05

I have recently started testing 5.7.0-B2429 and been getting errors when the external fetch tries to delete old messages. This only, and always, happens when there is no new messages to fetch but there is an old message to be deleted . After the error, the old message remains on the external server and hMailServer seems to ignore it in future sessions, neither fetching nor deleting it. I never saw this issue with 5.6.7-B2425 or earlier.

Code: Select all

"DEBUG"	6816	"2018-03-07 18:11:08.793"	"Adding task ExternalFetchTask to work queue External fetch queue"
"DEBUG"	4260	"2018-03-07 18:11:08.793"	"Executing task ExternalFetchTask in work queue External fetch queue"
"DEBUG"	4260	"2018-03-07 18:11:08.793"	"Retrieving messages from external account mail"
"DEBUG"	4260	"2018-03-07 18:11:08.794"	"Pre-creating session 1629"
"TCPIP"	4260	"2018-03-07 18:11:08.794"	"Connecting to xxx.xxx.xxx.xxx:995..."
"DEBUG"	6664	"2018-03-07 18:11:08.800"	"TCP connection started for session 1629"
"DEBUG"	6664	"2018-03-07 18:11:08.800"	"Performing SSL/TLS handshake for session 1629. Verify certificate: True, Expected remote host name: mail.domain.com"
"DEBUG"	6656	"2018-03-07 18:11:08.816"	"Certificate verification succeeded for session 1629."
"TCPIP"	6664	"2018-03-07 18:11:08.829"	"TCPConnection - TLS/SSL handshake completed. Session Id: 1629, Remote IP: xxx.xxx.xxx.xxx, Version: TLSv1.2, Cipher: ECDHE-RSA-AES128-GCM-SHA256, Bits: 128"
"POP3C"	6664	1629	"2018-03-07 18:11:09.029"	"xxx.xxx.xxx.xxx"	"RECEIVED: +OK Dovecot ready."
"POP3C"	6664	1629	"2018-03-07 18:11:09.030"	"xxx.xxx.xxx.xxx"	"SENT: USER mail@domain.com"
"POP3C"	6656	1629	"2018-03-07 18:11:09.035"	"xxx.xxx.xxx.xxx"	"RECEIVED: +OK"
"POP3C"	6656	1629	"2018-03-07 18:11:09.035"	"xxx.xxx.xxx.xxx"	"SENT: ***"
"POP3C"	6664	1629	"2018-03-07 18:11:09.142"	"xxx.xxx.xxx.xxx"	"RECEIVED: +OK Logged in."
"POP3C"	6664	1629	"2018-03-07 18:11:09.142"	"xxx.xxx.xxx.xxx"	"SENT: UIDL"
"POP3C"	6656	1629	"2018-03-07 18:11:09.158"	"xxx.xxx.xxx.xxx"	"SENT: DELE 51"
"POP3C"	6656	1629	"2018-03-07 18:11:09.164"	"xxx.xxx.xxx.xxx"	"RECEIVED: +OK Marked to be deleted."
"ERROR"	6656	"2018-03-07 18:11:09.164"	"Severity: 3 (Medium), Code: HM5136, Source: TCPConnection::AsyncReadCompleted, Description: An error occured while parsing data. Data size: 0 Remote IP: xxx.xxx.xxx.xxx"
"DEBUG"	6656	"2018-03-07 18:11:09.165"	"Ending session 1629"
"DEBUG"	4260	"2018-03-07 18:11:09.165"	"Completed retrieval of messages from external account."
"ERROR"	6656	"2018-03-07 18:11:09.165"	"Severity: 2 (High), Code: HM4208, Source: ExceptionHandler::Run, Description: An error occured while executing 'IOCPQueueWorkerTask'"
"DEBUG"	6656	"2018-03-07 18:11:09.165"	"Logging exception.."
"ERROR"	6656	"2018-03-07 18:11:09.278"	"Severity: 1 (Critical), Code: HM5519, Source: StackLogger::Log, Description: An error has been detected. A mini dump has been written to C:\hMailServer\Logs\minidump_2018-03-07 181109_{0F93C8D0-6197-4E1E-A4B1-78EBB49D585F}.dmp"
"DEBUG"	6656	"2018-03-07 18:11:09.278"	"Completed logging of exception..."

User avatar
mattg
Moderator
Moderator
Posts: 19101
Joined: 2007-06-14 05:12
Location: 'The Outback' Australia

Re: External Fetcher - DELE without RETR

Post by mattg » 2018-03-09 02:36

Have you posted this to Github?
Just 'cause I link to a page and say little else doesn't mean I am not being nice.
https://www.hmailserver.com/documentation

sprint
Normal user
Normal user
Posts: 30
Joined: 2018-01-31 01:36

Re: External Fetcher - DELE without RETR

Post by sprint » 2018-03-09 03:02

Not yet. I have only just figured out exactly when it was happening.

I have recently been testing an external script that watches the external account with IMAP idle and calls FetchAccount.DownloadNow when a new message comes in. I left hMailServer set to download every 15mins as a backup while I confirmed the script was reliable. This was all working well with 5.6.7 .

When I upgraded to 5.7 the errors started, but seemingly at random. But I noticed it only happened on the fetches that hMailServer had triggered, not the ones triggered by my script. And it seemed to happen mostly in the early hours of the morning, and only occasionally during business hours.

When I realised that it happened only when there was no new messages this made sense, since the script only triggers when there is a message, and also there is a lot more mail that comes in during business hours.

For now I have set hMailServer to fetch every 360mins which seems to avoid the issue since we never go that long between messages (and the scripted call to DownloadNow resets the timer) so the fetch account never gets checked unless there is new mail waiting.

sprint
Normal user
Normal user
Posts: 30
Joined: 2018-01-31 01:36

Re: External Fetcher - DELE without RETR

Post by sprint » 2018-03-15 07:59

Reverting 000131a fixes this for me.

User avatar
jimimaseye
Moderator
Moderator
Posts: 7520
Joined: 2011-09-08 17:48

Re: External Fetcher - DELE without RETR

Post by jimimaseye » 2018-03-15 09:03

Can you report this all on github?
HMS 5.6.6 B2383 on Win Server 2008 R2 Foundation, + 5.6.7-B2415 on test.
SpamassassinForWindows 3.4.0 spamd service
AV: Clamwin + Clamd service + sanesecurity defs : https://www.hmailserver.com/forum/viewtopic.php?f=21&t=26829

sprint
Normal user
Normal user
Posts: 30
Joined: 2018-01-31 01:36

Re: External Fetcher - DELE without RETR

Post by sprint » 2018-03-16 08:26

I had already done so.

I think I've just tracked down the problem, but I won't have time to compile and test til next week

sprint
Normal user
Normal user
Posts: 30
Joined: 2018-01-31 01:36

Re: External Fetcher - DELE without RETR

Post by sprint » 2018-03-19 05:50

Fixed with 260f999

User avatar
RvdH
Senior user
Senior user
Posts: 590
Joined: 2008-06-27 14:42
Location: Netherlands

Re: External Fetcher - DELE without RETR

Post by RvdH » 2018-03-19 17:56

Is this something that should/could be fixed in 5.6.x as well? I reviewed the code in 5.6.x and it is very similar to 5.7 code except for a few int to size conversions (64-bit migrations)
CIDR to RegEx: d-fault.nl/CIDRtoRegEx
DNS Lookup: d-fault.nl/DNSTools
DNSBL Lookup: d-fault.nl/DNSBLLookup
GEOIP Lookup: d-fault.nl/GeoipLookup

sprint
Normal user
Normal user
Posts: 30
Joined: 2018-01-31 01:36

Re: External Fetcher - DELE without RETR

Post by sprint » 2018-03-19 22:52

Not in any official build. The bug was introduced in Handling of long UIDL response lists was too slow. #93
But the patch should be harmless on older builds.

User avatar
RvdH
Senior user
Senior user
Posts: 590
Joined: 2008-06-27 14:42
Location: Netherlands

Re: External Fetcher - DELE without RETR

Post by RvdH » 2018-03-20 10:23

OK, I guess i need to fix this in my experimental build than as it has #93 implemented
CIDR to RegEx: d-fault.nl/CIDRtoRegEx
DNS Lookup: d-fault.nl/DNSTools
DNSBL Lookup: d-fault.nl/DNSBLLookup
GEOIP Lookup: d-fault.nl/GeoipLookup

ecoexteriors
New user
New user
Posts: 1
Joined: 2018-05-28 11:44

Re: External Fetcher - DELE without RETR

Post by ecoexteriors » 2018-05-28 11:46

Thanks for this...

Post Reply