MDaemon Technologies, Ltd.

DAVID

6/8/23, 3:22 PM

I've had this happen in the past in bursts, then it clears up... but now it's here again.

MDaemon v23.0.1 w/ MDaemon Antivirus

All the sudden, I get tons of alerts that "AntiVirus did not respond within expected time limit; DFEngine may have stopped responding; it will be stopped and restarted"

This go-round saw 2 alerts Tuesday at 8:15am, then 4 from 8:21-8:22am, then 6 from 5:29-5:31pm, then 6 from 8:57-9:01am Wednesday, 2 at 9:20am, 2 at 9:26am, 12 at 1:24-1:29pm, 6 from 3:34-3:36pm, 4 from 3:42-3:45pm, 8 from 4:54-4:58pm, 12 from 5:24-5:30pm, and today 4 from 9:43-9:45am, 2 at 9:51am, 2 at 10:22am, 2 at 10:27am, 2 at 10:39am, 8 from 10:46-10:50am, 4 from 10:59-11:01am, 6 from 11:42-11:44am, 8 from 1:33-1:36pm, 6 from 2:15-2:19pm, 6 from 2:51-2:57pm.

Yesterday, I shut down MDaemon and restarted it, but it didn't help. After hours today, I'll restart the whole server.

Any thoughts?

Thanks,

Dave

16
Posts

363
Views

A

Arron Staff

6/8/23, 3:35 PM

Were there any dump files created in the MDaemon\dumps directory? If there are I can provide a link to upload them to us.

Are there any errors in MDaemon's content filter log?

Are there any errors in MDaemon's AntiSpam log?

Are there any errors in MDaemon's AntiVirus log?

Are there any errors in MDaemon's inbound SMTP log?

What Antivirus engines do you have enabled in MDaemon?

Are there any errors in the Windows event log regarding applications crashing?

D

DAVID

6/8/23, 4:15 PM

Running both ClamAV and IKARUS.

Yes, there is a CFEngine.exe.2500.dmp file from 8:31am yesterday morning.

So, I picked 6/7/2023 at 8:57am as the time to search in the logs, as that corresponds to the first occurance on Wednesday morning.

Nothing out of the ordinary in the Content Filter log.

Nothing out of the ordinary in the AntiSpam log.

In the AntiVirus log, I found this:

Wed 2023-06-07 08:57:09.560: ----------
* SMTP ERROR: ClamAV error while scanning file d:\mdaemon\queues\temp\md5001000026211.wrk!
N/A: * comm-error

Then the log continued.

In the SMTP(in) log, the 08:57:09 time is skipped:

Wed 2023-06-07 08:57:07.907: 01: Message size: 53624 bytes
Wed 2023-06-07 08:57:07.915: 06: Passing message through AntiVirus (Size: 53624)...
Wed 2023-06-07 08:57:07.988: 06: * Message is clean (no viruses found) scanned by (IKARUS: clean (0.00341s)) (ClamAV: clean (0.05022s))
Wed 2023-06-07 08:57:07.988: 06: ---- End AntiVirus results
Wed 2023-06-07 08:57:07.990: 01: Message creation successful: d:\mdaemon\queues\inbound\md5001008524590.msg
Wed 2023-06-07 08:57:07.990: 03: --> 250 2.6.0 Ok, message saved <Message-ID: <023301d99947$f25bf1e0$d713d5a0$@schaefer-arch.com>>
Wed 2023-06-07 08:57:10.512: 02: <-- QUIT
Wed 2023-06-07 08:57:10.512: 03: --> 221 2.0.0 See ya in cyberspace
Wed 2023-06-07 08:57:10.512: 01: SMTP session successful (Bytes in/out: 55411/1724)
Wed 2023-06-07 08:57:10.512: 01: ----------

As for the Windows event logs... The only thing I see is random firings of this error:

36888 Error Schannel System, A fatal alert was generated and sent to the remote endpoint. This may result in termination of the connection. The TLS protocol defined fatal error code is 10. The Windows SChannel error state is 1203.

But these occur at all sorts of different intervals around the MDaemon AV Warnings, so I don't think these have a correlation.

Thanks.

I can do a deeper dive into the logs, but I wanted to get you a response.

A

Arron Staff

6/9/23, 7:15 AM

Can you upload the crash dump file to us using this URL?

https://mdaemon.sharefile.com/f/fo11e16f-9fcf-4dee-9af7-4a74116c176d

If its not already enabled, can you also enable ClamD logging by going to Security / AntiVirus, click the configure button next to Use ClamAV and check the box for Log ClamD activity. If the box is already checked, please check the MDaemon\Logs directory for a clamd log and check for an error at around the time of the error in the SMTP inbound log (Wed 2023-06-07 08:57:09.560).

The Schannel errors are not related. The are typically caused by TLS negotiation failures.

D

DAVID

6/9/23, 8:42 AM

Ok, I've uploaded the dump file. The ClamD logging was not enabled, but I have now enabled it. I'll keep an eye open.

Thanks!

A

Arron Staff

6/9/23, 11:07 AM

The development team has looked at the dump file, unfortunately we have not yet been able to find information in the dump that tells us why it was not responding. We will keep looking. The dump file was generated by a crash that occurred while MDaemon was trying to shut down CFEngine. So while it is likely related to the issue, it is not giving us clues about why it wasn't responding.

Are there any inbound SMTP sessions that occur around the time that you are getting the warnings about CFEngine not responding?

Are there any messages in the local or remote queue that MDaemon could be trying to process each time the error occurs?

If you turn off the clamAV processing, does the issue go away?

D

DAVID

6/9/23, 11:12 AM

I will take a look at the references in your questions and get back.

D

DAVID

6/9/23, 4:09 PM

So, I went through all the log files again, this time looking at yesterday, 6/8/23 at around 14:51 when the last set of errors occurred.

In the All log, everything is ok at 14:50:39.697 to 14:50:39.812 but at 14:51:40.034 there is the SMTP ERROR: ClamAV Error...

But looking in the AntiVirus log, there is one of those errors at 14;51:13.812 and again 14 14:52:29.865.

I found nothing in any other log. Both of the errors above happen immediately AFTER completing a successful AV scan: For instance, here is what the ALL log shows at the 14:52:29.865 timeframe:

Thu 2023-06-08 14:52:29.783: MDaemon AntiVirus processing d:\mdaemon\queues\local\md5001009788940.msg...
Thu 2023-06-08 14:52:29.783: * Message return-path: cdyer@wichitachamber.org
Thu 2023-06-08 14:52:29.783: * Message from: cdyer@wichitachamber.org
Thu 2023-06-08 14:52:29.783: * Message to: sfbohm@schaefer-arch.com
Thu 2023-06-08 14:52:29.783: * Message subject: City to City pre-trip briefing
Thu 2023-06-08 14:52:29.783: * Message ID: <BY3PR18MB4546DE31A971BF8576D2DB4FDC50A@BY3PR18MB4546.namprd18.prod.outlook.com>
Thu 2023-06-08 14:52:29.783: Start MDaemon AntiVirus results
Thu 2023-06-08 14:52:29.786: * IKARUS AV: clean (0.00240 s) D:\MDaemon\CFilter\TEMP\2150310959\pd1758832232.hdr
Thu 2023-06-08 14:52:29.798: * ClamAV: clean (0.01192 s) D:\MDaemon\CFilter\TEMP\2150310959\pd1758832232.hdr
Thu 2023-06-08 14:52:29.800: * IKARUS AV: clean (0.00212 s) D:\MDaemon\CFilter\WORK\1100124356\pd321412896.txt
Thu 2023-06-08 14:52:29.817: * ClamAV: clean (0.01698 s) D:\MDaemon\CFilter\WORK\1100124356\pd321412896.txt
Thu 2023-06-08 14:52:29.819: * IKARUS AV: clean (0.00190 s) D:\MDaemon\CFilter\WORK\1100124356\pd74410508.txt
Thu 2023-06-08 14:52:29.833: * ClamAV: clean (0.01383 s) D:\MDaemon\CFilter\WORK\1100124356\pd74410508.txt
Thu 2023-06-08 14:52:29.835: * IKARUS AV: clean (0.00195 s) D:\MDaemon\CFilter\WORK\1100124356\pd572231348.txt
Thu 2023-06-08 14:52:29.840: * ClamAV: clean (0.00486 s) D:\MDaemon\CFilter\WORK\1100124356\pd572231348.txt
Thu 2023-06-08 14:52:29.840: * Total attachments scanned : 4 (including multipart/alternatives and message body)
Thu 2023-06-08 14:52:29.840: * Total attachments infected : 0
Thu 2023-06-08 14:52:29.840: * Total attachments disinfected: 0
Thu 2023-06-08 14:52:29.840: * Total errors while scanning : 0
Thu 2023-06-08 14:52:29.840: * Total attachments removed : 0
Thu 2023-06-08 14:52:29.865: End of MDaemon AntiVirus results
Thu 2023-06-08 14:52:29.865: ----------

So of course, it hasn't reoccurred since 2:57pm yesterday.... If it starts up again, I will try killing ClamAV.

A

Arron Staff

6/10/23, 7:19 AM

Does the ClamD log show any errors or give any indication that clamd.exe might be restarting?

D

DAVID

6/12/23, 9:42 AM

Unfortunately, I only enabled the ClamD log on Friday the 9th, at your direction -- and the issue has not occurred since I enabled it. I'll check if/as soon as the issue repeats.

Dave

D

DAVID

6/12/23, 11:07 AM

Hey! It's started happening again... I'll do some log-checking and post shortly.

Dave

D

DAVID

6/12/23, 11:46 AM

So there was a lull with no instances between xx:xxpm last Thursday until 10:13am today.

I've noticed that I always get 2 copies of the error instead of one, and they are sent separately, as most of the time they have the same minute timestamp, but occasionally the second will spill over onto the next minute. And when there are multiple errors in a row, again, there are always an even number.

This morning, the errors I was sent via SMS:

08:17am (2x)
10:13am (2x)
10:23am (2x)
10:28-10:37am (16x)
10:50am (2x)
10:56-10:57am (4x)
11:07-11:11am (6x)
11:16am (2x)
11:23-11:27am (10x)

There are no odd/telling entries in the ClamD log. No new dumps.

ClamD updated this morning:
[Mon 2023-06-12 05:58:30] ----- AVUpdater for MDaemon 23.0.1 Log file starting ---
[Mon 2023-06-12 05:58:31] ClamAV update process started at Mon Jun 12 05:58:31 2023
[Mon 2023-06-12 05:58:31] Mon Jun 12 05:58:31 2023 -> daily.cld database is up-to-date (version: 26937, sigs: 2036957, f-level: 90, builder: raynman)
[Mon 2023-06-12 05:58:31] Mon Jun 12 05:58:31 2023 -> main.cvd database is up-to-date (version: 62, sigs: 6647427, f-level: 90, builder: sigmgr)
[Mon 2023-06-12 05:58:31] Mon Jun 12 05:58:31 2023 -> bytecode.cvd database is up-to-date (version: 334, sigs: 91, f-level: 90, builder: anvilleg)
[Mon 2023-06-12 05:58:32] ----- AVUpdater for MDaemon 23.0.1 Log file stopping ---

I will disable ClamAV and see if the errors stop. (Did so at 11:31am just now)

Errors in AntiVirus log are below. Please note that each error occurs at the END of a successful scan. I will include a complete example at the end of the error list:

Mon 2023-06-12 08:16:45.881: ----------
* SMTP ERROR: ClamAV error while scanning file d:\mdaemon\queues\temp\md5001000037786.wrk!
N/A: * comm-error
Mon 2023-06-12 10:13:15.359: ----------
* SMTP ERROR: ClamAV error while scanning file d:\mdaemon\queues\temp\md5001000038351.wrk!
N/A: * comm-error
Mon 2023-06-12 10:22:57.457: ----------
* SMTP ERROR: ClamAV error while scanning file d:\mdaemon\queues\temp\md5001000038408.wrk!
N/A: * comm-error
Mon 2023-06-12 10:28:01.242: ----------
* SMTP ERROR: ClamAV error while scanning file d:\mdaemon\queues\temp\md5001000038436.wrk!
N/A: * comm-error
Mon 2023-06-12 10:29:11.616: ----------
* SMTP ERROR: ClamAV error while scanning file d:\mdaemon\queues\temp\md5001000038440.wrk!
N/A: * comm-error
Mon 2023-06-12 10:29:35.896: ----------
* SMTP ERROR: ClamAV error while scanning file d:\mdaemon\queues\temp\md5001000038444.wrk!
N/A: * comm-error
Mon 2023-06-12 10:31:16.367: ----------
* SMTP ERROR: ClamAV error while scanning file d:\mdaemon\queues\temp\md5001000038452.wrk!
N/A: * comm-error
Mon 2023-06-12 10:32:27.624: ----------
* SMTP ERROR: ClamAV error while scanning file d:\mdaemon\queues\temp\md5001000038462.wrk!
N/A: * comm-error
Mon 2023-06-12 10:33:48.517: ----------
* SMTP ERROR: ClamAV error while scanning file d:\mdaemon\queues\temp\md5001000038471.wrk!
N/A: * comm-error
Mon 2023-06-12 10:34:32.881: ----------
* SMTP ERROR: ClamAV error while scanning file d:\mdaemon\queues\temp\md5001000038486.wrk!
N/A: * comm-error
Mon 2023-06-12 10:36:44.973: ----------
* SMTP ERROR: ClamAV error while scanning file d:\mdaemon\queues\temp\md5001000038499.wrk!
N/A: * comm-error
Mon 2023-06-12 10:49:43.592: ----------
* SMTP ERROR: ClamAV error while scanning file d:\mdaemon\queues\temp\md5001000038594.wrk!
N/A: * comm-error
Mon 2023-06-12 10:55:49.239: ----------
* SMTP ERROR: ClamAV error while scanning file d:\mdaemon\queues\temp\md5001000038645.wrk!
N/A: * comm-error
Mon 2023-06-12 10:57:19.498: ----------
* SMTP ERROR: ClamAV error while scanning file d:\mdaemon\queues\temp\md5001000038664.wrk!
N/A: * comm-error
Mon 2023-06-12 11:07:26.187: ----------
* SMTP ERROR: ClamAV error while scanning file d:\mdaemon\queues\temp\md5001000038740.wrk!
N/A: * comm-error
Mon 2023-06-12 11:09:40.973: ----------
* SMTP ERROR: ClamAV error while scanning file d:\mdaemon\queues\temp\md5001000038755.wrk!
N/A: * comm-error
Mon 2023-06-12 11:11:06.760: ----------
* SMTP ERROR: ClamAV error while scanning file d:\mdaemon\queues\temp\md5001000038773.wrk!
N/A: * comm-error
Mon 2023-06-12 11:16:53.075: ----------
* SMTP ERROR: ClamAV error while scanning file d:\mdaemon\queues\temp\md5001000038835.wrk!
N/A: * comm-error
Mon 2023-06-12 11:22:55.142: ----------
* SMTP ERROR: ClamAV error while scanning file d:\mdaemon\queues\temp\md5001000038880.wrk!
N/A: * comm-error
Mon 2023-06-12 11:25:05.259: ----------
* SMTP ERROR: ClamAV error while scanning file d:\mdaemon\queues\temp\md5001000038899.wrk!
N/A: * comm-error
Mon 2023-06-12 11:25:51.333: ----------
* SMTP ERROR: ClamAV error while scanning file d:\mdaemon\queues\temp\md5001000038909.wrk!
N/A: * comm-error
Mon 2023-06-12 11:27:35.679: ----------
* SMTP ERROR: ClamAV error while scanning file d:\mdaemon\queues\temp\md5001000038922.wrk!
N/A: * comm-error
Mon 2023-06-12 11:28:52.855: ----------
* SMTP ERROR: ClamAV error while scanning file d:\mdaemon\queues\temp\md5001000038934.wrk!
N/A: * comm-error

Here is an example of two consecutive errors:

Mon 2023-06-12 11:25:45.216: ----------
Mon 2023-06-12 11:25:51.107: MDaemon AntiVirus processing d:\mdaemon\queues\local\md5001009792840.msg...
Mon 2023-06-12 11:25:51.107: * Message return-path: bounce-34_HTML-76108109-132512-514005572-27267@bounce.mc.ihg.com
Mon 2023-06-12 11:25:51.107: * Message from: IHGOneRewards@mc.ihg.com
Mon 2023-06-12 11:25:51.107: * Message to: gholler@schaefer-arch.com
Mon 2023-06-12 11:25:51.107: * Message subject: Here's how to heat up your summer
Mon 2023-06-12 11:25:51.107: * Message ID: <a157328b-4b1a-4762-b565-b160d4494e60@atl1s11mta427.xt.local>
Mon 2023-06-12 11:25:51.107: Start MDaemon AntiVirus results
Mon 2023-06-12 11:25:51.114: * IKARUS AV: clean (0.00587 s) D:\MDaemon\CFilter\TEMP\170137751\pd2561218170.hdr
Mon 2023-06-12 11:25:51.138: * ClamAV: clean (0.02467 s) D:\MDaemon\CFilter\TEMP\170137751\pd2561218170.hdr
Mon 2023-06-12 11:25:51.146: * IKARUS AV: clean (0.00762 s) D:\MDaemon\CFilter\WORK\2240621468\pd921525850.txt
Mon 2023-06-12 11:25:51.182: * ClamAV: clean (0.03566 s) D:\MDaemon\CFilter\WORK\2240621468\pd921525850.txt
Mon 2023-06-12 11:25:51.190: * IKARUS AV: clean (0.00850 s) D:\MDaemon\CFilter\WORK\2240621468\pd25104364.txt
Mon 2023-06-12 11:25:51.282: * ClamAV: clean (0.09178 s) D:\MDaemon\CFilter\WORK\2240621468\pd25104364.txt
Mon 2023-06-12 11:25:51.282: * Total attachments scanned : 3 (including multipart/alternatives and message body)
Mon 2023-06-12 11:25:51.282: * Total attachments infected : 0
Mon 2023-06-12 11:25:51.282: * Total attachments disinfected: 0
Mon 2023-06-12 11:25:51.282: * Total errors while scanning : 0
Mon 2023-06-12 11:25:51.282: * Total attachments removed : 0
Mon 2023-06-12 11:25:51.333: End of MDaemon AntiVirus results
Mon 2023-06-12 11:25:51.333: ----------
* SMTP ERROR: ClamAV error while scanning file d:\mdaemon\queues\temp\md5001000038909.wrk!
N/A: * comm-error
Mon 2023-06-12 11:27:35.506: MDaemon AntiVirus processing d:\mdaemon\queues\local\md5001009792841.msg...
Mon 2023-06-12 11:27:35.506: * Message return-path: ngordon@huttonbuilds.com
Mon 2023-06-12 11:27:35.506: * Message from: ngordon@huttonbuilds.com
Mon 2023-06-12 11:27:35.506: * Message to: mmeyer@schaefer-arch.com
Mon 2023-06-12 11:27:35.506: * Message subject: Re: Area B Brick Wraps to Painted Wall
Mon 2023-06-12 11:27:35.506: * Message ID: <459859B0-1ADF-42CA-85C4-9B897BD9B4AC@huttonbuilds.com>
Mon 2023-06-12 11:27:35.506: Start MDaemon AntiVirus results
Mon 2023-06-12 11:27:35.514: * IKARUS AV: clean (0.00826 s) D:\MDaemon\CFilter\TEMP\1217229394\pd580726797.hdr
Mon 2023-06-12 11:27:35.530: * ClamAV: clean (0.01514 s) D:\MDaemon\CFilter\TEMP\1217229394\pd580726797.hdr
Mon 2023-06-12 11:27:35.534: * IKARUS AV: clean (0.00393 s) D:\MDaemon\CFilter\WORK\1669720142\pd1423812270.txt
Mon 2023-06-12 11:27:35.542: * ClamAV: clean (0.00814 s) D:\MDaemon\CFilter\WORK\1669720142\pd1423812270.txt
Mon 2023-06-12 11:27:35.547: * IKARUS AV: clean (0.00524 s) D:\MDaemon\CFilter\TEMP\1217229394\pd3197014847.att
Mon 2023-06-12 11:27:35.555: * ClamAV: clean (0.00749 s) D:\MDaemon\CFilter\TEMP\1217229394\pd3197014847.att
Mon 2023-06-12 11:27:35.561: * IKARUS AV: clean (0.00632 s) D:\MDaemon\CFilter\TEMP\1217229394\pd129735249.att
Mon 2023-06-12 11:27:35.576: * ClamAV: clean (0.01448 s) D:\MDaemon\CFilter\TEMP\1217229394\pd129735249.att
Mon 2023-06-12 11:27:35.576: * Total attachments scanned : 4 (including multipart/alternatives and message body)
Mon 2023-06-12 11:27:35.576: * Total attachments infected : 0
Mon 2023-06-12 11:27:35.576: * Total attachments disinfected: 0
Mon 2023-06-12 11:27:35.576: * Total errors while scanning : 0
Mon 2023-06-12 11:27:35.576: * Total attachments removed : 0
Mon 2023-06-12 11:27:35.679: End of MDaemon AntiVirus results
Mon 2023-06-12 11:27:35.679: ----------
* SMTP ERROR: ClamAV error while scanning file d:\mdaemon\queues\temp\md5001000038922.wrk!
N/A: * comm-error

Hope this helps.

Dave

A

Arron Staff

6/12/23, 11:54 AM

Can I get a copy of the clamd log along with copies of the inbound smtp log and the antivirus log?

Do you have copies of any of the messages that generated an error in the logs when ClamAV was trying to scan then?

Please send the logs and any messages that generated errors during the ClamAV scanning to arron.caruth @ mdaemon.com.

D

DAVID

6/12/23, 11:57 AM

Will do.

Dave

D

DAVID

6/12/23, 12:23 PM

FYI, I'm seeing more of the SMTP ERROR: ClamAV error while scanning messages even though I unchecked "Use the ClamAV engine to scan messages" item 5 minutes earlier.

D

DAVID

6/12/23, 12:25 PM

While I was trying to copy messages for you, I noticed that the .wrk file mentioned in the errors doesn't correspond to either the .msg file name in the log before or the .msg in the log after the error.... so I don't know if this is an entirely other message or not. I'll upload the things I've gathered in a minute.

AV Not Responding Within Time Limit