Vulnerability scan for viruses?

Use this forum if you have installed hMailServer and want to ask a question related to a production release of hMailServer. Before posting, please read the troubleshooting guide. A large part of all reported issues are already described in detail here.
Post Reply
HonzaK
New user
New user
Posts: 3
Joined: 2014-06-04 17:16

Vulnerability scan for viruses?

Post by HonzaK » 2014-06-09 15:03

Hi all,
I use hMailServer as SMTP relay. Now test the anti-virus scan with the ESET command line scanner. I have this knowledge: AV scanner check only first received mail in the SMTP session. The second and more mail pass through without inspection:

List of the hmailserver_2014-06-09.log:
"SMTPD" 6016 33783 "2014-06-09 14:16:12.729" "10.0.15.1" "SENT: 220 mail2.aliaweb.cz ESMTP"
"SMTPD" 1392 33783 "2014-06-09 14:16:12.729" "10.0.15.1" "RECEIVED: EHLO raptor.extalia1.local"
"SMTPD" 1392 33783 "2014-06-09 14:16:12.729" "10.0.15.1" "SENT: 250-mail2.aliaweb.cz[nl]250-SIZE 20480000[nl]250 AUTH LOGIN"
"SMTPD" 152 33783 "2014-06-09 14:16:12.729" "10.0.15.1" "RECEIVED: MAIL FROM:<avtest1@otherdomain.cz> SIZE=204404"
"SMTPD" 152 33783 "2014-06-09 14:16:12.745" "10.0.15.1" "SENT: 250 OK"
"SMTPD" 4264 33783 "2014-06-09 14:16:12.745" "10.0.15.1" "RECEIVED: RCPT TO:<my.address@aliaweb.cz>"
"SMTPD" 4264 33783 "2014-06-09 14:16:12.760" "10.0.15.1" "SENT: 250 OK"
"SMTPD" 152 33783 "2014-06-09 14:16:12.760" "10.0.15.1" "RECEIVED: DATA"
"SMTPD" 152 33783 "2014-06-09 14:16:12.760" "10.0.15.1" "SENT: 354 OK, send."
"SMTPD" 4392 33783 "2014-06-09 14:16:13.026" "10.0.15.1" "SENT: 250 Queued (0.219 seconds)"
"SMTPD" 4552 33783 "2014-06-09 14:16:13.026" "10.0.15.1" "RECEIVED: RSET"
"SMTPD" 4552 33783 "2014-06-09 14:16:13.026" "10.0.15.1" "SENT: 250 OK"
"SMTPD" 3532 33783 "2014-06-09 14:16:13.026" "10.0.15.1" "RECEIVED: MAIL FROM:<avtest2@otherdomain.cz> SIZE=104894"
"SMTPD" 3532 33783 "2014-06-09 14:16:13.026" "10.0.15.1" "SENT: 250 OK"
"SMTPD" 4552 33783 "2014-06-09 14:16:13.026" "10.0.15.1" "RECEIVED: RCPT TO:<my.address@aliaweb.cz>"
"SMTPD" 4552 33783 "2014-06-09 14:16:13.042" "10.0.15.1" "SENT: 250 OK"
"SMTPD" 3532 33783 "2014-06-09 14:16:13.057" "10.0.15.1" "RECEIVED: DATA"
"SMTPD" 3532 33783 "2014-06-09 14:16:13.057" "10.0.15.1" "SENT: 354 OK, send."
"SMTPD" 4392 33783 "2014-06-09 14:16:13.198" "10.0.15.1" "SENT: 250 Queued (0.094 seconds)"
"SMTPD" 2720 33783 "2014-06-09 14:16:13.198" "10.0.15.1" "RECEIVED: RSET"
"SMTPD" 2720 33783 "2014-06-09 14:16:13.198" "10.0.15.1" "SENT: 250 OK"
"SMTPD" 2720 33783 "2014-06-09 14:16:13.198" "10.0.15.1" "RECEIVED: MAIL FROM:<avtest3@otherdomain.cz> SIZE=204380"
"SMTPD" 2720 33783 "2014-06-09 14:16:13.245" "10.0.15.1" "SENT: 250 OK"
"SMTPD" 1392 33783 "2014-06-09 14:16:13.245" "10.0.15.1" "RECEIVED: RCPT TO:<my.address@aliaweb.cz>"
"SMTPD" 1392 33783 "2014-06-09 14:16:13.260" "10.0.15.1" "SENT: 250 OK"
"SMTPD" 3488 33783 "2014-06-09 14:16:13.260" "10.0.15.1" "RECEIVED: DATA"
"SMTPD" 3488 33783 "2014-06-09 14:16:13.260" "10.0.15.1" "SENT: 354 OK, send."
"SMTPD" 4392 33783 "2014-06-09 14:16:13.510" "10.0.15.1" "SENT: 250 Queued (0.203 seconds)"
"SMTPD" 4056 33783 "2014-06-09 14:16:13.510" "10.0.15.1" "RECEIVED: RSET"
"SMTPD" 4056 33783 "2014-06-09 14:16:13.510" "10.0.15.1" "SENT: 250 OK"
"SMTPD" 5324 33783 "2014-06-09 14:16:13.510" "10.0.15.1" "RECEIVED: MAIL FROM:<avtest4@otherdomain.cz> SIZE=104894"
"SMTPD" 5324 33783 "2014-06-09 14:16:13.510" "10.0.15.1" "SENT: 250 OK"
"SMTPD" 4056 33783 "2014-06-09 14:16:13.526" "10.0.15.1" "RECEIVED: RCPT TO:<my.address@aliaweb.cz>"
"SMTPD" 4056 33783 "2014-06-09 14:16:13.542" "10.0.15.1" "SENT: 250 OK"
"SMTPD" 5324 33783 "2014-06-09 14:16:13.542" "10.0.15.1" "RECEIVED: DATA"
"SMTPD" 5324 33783 "2014-06-09 14:16:13.542" "10.0.15.1" "SENT: 354 OK, send."
"SMTPD" 4392 33783 "2014-06-09 14:16:13.682" "10.0.15.1" "SENT: 250 Queued (0.094 seconds)"
"SMTPD" 4552 33783 "2014-06-09 14:16:13.682" "10.0.15.1" "RECEIVED: RSET"
"SMTPD" 4552 33783 "2014-06-09 14:16:13.682" "10.0.15.1" "SENT: 250 OK"
"SMTPD" 3532 33783 "2014-06-09 14:16:13.682" "10.0.15.1" "RECEIVED: MAIL FROM:<avtest5@otherdomain.cz> SIZE=204382"
"SMTPD" 3532 33783 "2014-06-09 14:16:13.713" "10.0.15.1" "SENT: 250 OK"
"SMTPD" 3532 33783 "2014-06-09 14:16:13.729" "10.0.15.1" "RECEIVED: RCPT TO:<my.address@aliaweb.cz>"
"SMTPD" 3532 33783 "2014-06-09 14:16:13.745" "10.0.15.1" "SENT: 250 OK"
"SMTPD" 3532 33783 "2014-06-09 14:16:13.760" "10.0.15.1" "RECEIVED: DATA"
"SMTPD" 3532 33783 "2014-06-09 14:16:13.760" "10.0.15.1" "SENT: 354 OK, send."
"SMTPD" 4392 33783 "2014-06-09 14:16:14.010" "10.0.15.1" "SENT: 250 Queued (0.203 seconds)"
"SMTPD" 4264 33783 "2014-06-09 14:16:14.010" "10.0.15.1" "RECEIVED: QUIT"
"SMTPD" 4264 33783 "2014-06-09 14:16:14.010" "10.0.15.1" "SENT: 221 goodbye"

but in the Antivir's log is only one record:
-------------------------------------------------------------------------------------------------------------------
20140609 14:16:13, INF, Start "C:\Apl\hMailServer\VirusScan.bat", Verzion 1.2, File: "X:\MailRoot.HMS\Data\{CA870C49-A8E6-4783-87CB-E6AA26431FB4}.eml"
20140609 14:16:12, ReceiveMail, From: Mail Delivery Subsystem <avtest1@otherdomain.cz>, To: my.address@aliaweb.cz, Delivery Status Notification (Failure), X:\MailRoot.HMS\Data\{CA870C49-A8E6-4783-87CB-E6AA26431FB4}.eml

ECLS command line scanner, verzion 4.5.12015.1, (C) 1992-2013 ESET, spol. s r.o.
...
Command line: /base-dir=C:\Program Files\ESET\ESET File Security /adv-heur /no-boots /arch /log-file=X:\mail.log\hMail\av140609.log X:\MailRoot.HMS\Data\{CA870C49-A8E6-4783-87CB-E6AA26431FB4}.eml

Start scan 06/09/14 2:16:15 p.m.
Name="X:\MailRoot.HMS\Data\{CA870C49-A8E6-4783-87CB-E6AA26431FB4}.eml", virus="Win32/TrojanDownloader.FakeAlert.BED trojan", action="", info=""
Name="X:\MailRoot.HMS\Data\{CA870C49-A8E6-4783-87CB-E6AA26431FB4}.eml » MIME » 60401Forwarded message.zip", virus="Win32/TrojanDownloader.FakeAlert.BED trojan", action="", info=""
Name="X:\MailRoot.HMS\Data\{CA870C49-A8E6-4783-87CB-E6AA26431FB4}.eml » MIME » 60401Forwarded message.zip » ZIP » Forwarded message.exe", virus="Win32/TrojanDownloader.FakeAlert.BED trojan", action="", info=""

End of the scan 6/9/14 2:16:15 p.m.
Total time: 0 sec (0:00:00)
Overall: files - 1, objects 2
Infected: files - 1, objects 1
Cured: files - 0, objects 0
-------------------------------------------------------------------------------------------------------------------



Can someone please verify this?

Thx, HonzaK
English is not my primary language, so please excuse for my English. Thanks.

percepts
Senior user
Senior user
Posts: 5282
Joined: 2009-10-20 16:33
Location: Sceptred Isle

Re: Vulnerability scan for viruses?

Post by percepts » 2014-06-09 17:45

I think that if you send one mail to several recipients at the same host name (but maybe different domains) then hmail doesn't split the message being sent. Its the receiving server which splits it after it receives and after it has done its spam and virus checks. At least thats what seems to be happening with with spam checks so I guess the same happens with virus checks.

i.e. hmail only splits mail for delivery by host name and not by user or domain name on sending. At least that what it looks like to me.

If your mails are being marked as containing spam are they all marked even though ESET was only called once ? That is what you should be checking.

Bill48105
Developer
Developer
Posts: 6192
Joined: 2010-04-24 23:16
Location: Michigan, USA

Re: Vulnerability scan for viruses?

Post by Bill48105 » 2014-06-09 23:55

After RSET indeed full tests should be performed. Percepts is talking about multiple RCPT TO's which is correct there would only be one scan per message (all in 1 message at time of reception) but as you see in the logs each is added to queue individually. I would need to test here though since you must not have full logging enabled as hmail logs will tell you if AV/antispam tests are run or not instead of assuming your AV log is accurate.
Bill
hMailServer build LIVE on my servers: 5.4-B2014050402
#hmailserver on FreeNode IRC https://webchat.freenode.net/?channels=#hmailserver
*** ABSENT FROM hMail! Those in IRC know how to find me if urgent. ***

Bill48105
Developer
Developer
Posts: 6192
Joined: 2010-04-24 23:16
Location: Michigan, USA

Re: Vulnerability scan for viruses?

Post by Bill48105 » 2014-06-10 00:21

Looking at the code I think I can see why this might happen but I'd need to test myself to confirm. I really need to see the full logging to know.
Bill
hMailServer build LIVE on my servers: 5.4-B2014050402
#hmailserver on FreeNode IRC https://webchat.freenode.net/?channels=#hmailserver
*** ABSENT FROM hMail! Those in IRC know how to find me if urgent. ***

Bill48105
Developer
Developer
Posts: 6192
Joined: 2010-04-24 23:16
Location: Michigan, USA

Re: Vulnerability scan for viruses?

Post by Bill48105 » 2014-06-10 00:45

Ok scratch that. Now you know why I wanted to see the logs. I just tested here & hmail is indeed testing each correctly. I had full verbose extended logging enabled so there is a lot of extras (heck I removed 40% of the log lines that were not related to this) but you can clearly see hmail does av & antispam tests for both:
(Look for "Running custom virus scanner...". One is for 1st message before RSET & the other is for 2nd after RSET. Note that I don't have AV on that test box so I just called PING.EXE as a custom scanner for testing purposes since although it doesn't actually do anything it is fast dirty trick to test av scanning call & doesn't hurt anything either)
"TCPIP" 660 "2014-06-09 18:32:25.367" "TCP - 192.168.3.20 connected to 192.168.3.198:25."
"SMTPD" 660 5 "2014-06-09 18:32:25.367" "192.168.3.20" "SENT: 220 WIN7-20 ESMTP"
"SMTPD" 920 5 "2014-06-09 18:32:28.534" "192.168.3.20" "RECEIVED: helo test1"
"SMTPD" 920 5 "2014-06-09 18:32:28.534" "192.168.3.20" "SENT: 250 Hello."
"SMTPD" 2324 5 "2014-06-09 18:32:36.536" "192.168.3.20" "RECEIVED: MAIL FROM:<bill48105@somdomain.dom>"
"SMTPD" 2324 0 "2014-06-09 18:32:36.536" "TCP" "DNS lookup: 20.3.168.192.zen.spamhaus.org, 1 addresses found: 127.0.0.2, Match: True"
"DEBUG" 2324 "2014-06-09 18:32:36.536" "DNS Blacklist Score -2"
"SMTPD" 2324 0 "2014-06-09 18:32:36.536" "TCP" "DNS lookup: 20.3.168.192.bl.spamcop.net, 1 addresses found: 127.0.0.2, Match: True"
"DEBUG" 2324 "2014-06-09 18:32:36.536" "DNS Blacklist Score -2"
"DEBUG" 2324 "2014-06-09 18:32:36.536" "Spam test: SpamTestDNSBlackLists, Score: -4"
"DEBUG" 2324 "2014-06-09 18:32:36.536" "Total spam score: -4"
"SMTPD" 2324 5 "2014-06-09 18:32:36.552" "192.168.3.20" "SENT: 250 OK"
"SMTPD" 2148 5 "2014-06-09 18:32:42.589" "192.168.3.20" "RECEIVED: RCPT TO:<test@test.dom>"
"SMTPD" 2148 5 "2014-06-09 18:32:42.605" "192.168.3.20" "SENT: 250 OK"
"SMTPD" 920 5 "2014-06-09 18:32:45.116" "192.168.3.20" "RECEIVED: data"
"SMTPD" 920 5 "2014-06-09 18:32:45.132" "192.168.3.20" "SENT: 354 OK, send."
"DEBUG" 2120 "2014-06-09 18:32:51.169" "Saving message: {84D5133A-57DC-45F9-B889-CBF2C8CAD30C}.eml"
"DEBUG" 2120 "2014-06-09 18:32:51.169" "Requesting SMTPDeliveryManager to start message delivery"
"SMTPD" 2120 5 "2014-06-09 18:32:51.169" "192.168.3.20" "SENT: 250 Queued (6.038 seconds)"
"DEBUG" 2420 "2014-06-09 18:32:51.169" "Delivering message..."
"APPLICATION" 2420 "2014-06-09 18:32:51.169" "SMTPDeliverer - Message 1599: Delivering message from bill48105@somdomain.dom to test@test.dom. File: Z:\hMailServer\Data\{84D5133A-57DC-45F9-B889-CBF2C8CAD30C}.eml"
"DEBUG" 2420 "2014-06-09 18:32:51.169" "Running custom virus scanner..."
"DEBUG" 2420 "2014-06-09 18:32:51.200" "Scanner: ping.exe Z:\hMailServer\Data\{84D5133A-57DC-45F9-B889-CBF2C8CAD30C}.eml. Return code: 1"

"DEBUG" 2420 "2014-06-09 18:32:51.200" "Applying rules"
"DEBUG" 2420 "2014-06-09 18:32:51.200" "Performing local delivery"
"DEBUG" 2420 "2014-06-09 18:32:51.216" "Applying rules"
"DEBUG" 2420 "2014-06-09 18:32:51.232" "Saving message: {84D5133A-57DC-45F9-B889-CBF2C8CAD30C}.eml"
"DEBUG" 2420 "2014-06-09 18:32:51.232" "Local delivery completed"
"APPLICATION" 2420 "2014-06-09 18:32:51.232" "SMTPDeliverer - Message 1599: Message delivery thread completed."
"SMTPD" 2344 5 "2014-06-09 18:32:53.275" "192.168.3.20" "RECEIVED: RSET"
"SMTPD" 2344 5 "2014-06-09 18:32:53.275" "192.168.3.20" "SENT: 250 OK"
"SMTPD" 2324 5 "2014-06-09 18:33:04.570" "192.168.3.20" "RECEIVED: MAIL FROM:<bill48105-2@somdomain.dom>"
"SMTPD" 2324 0 "2014-06-09 18:33:04.585" "TCP" "DNS lookup: 20.3.168.192.zen.spamhaus.org, 1 addresses found: 127.0.0.2, Match: True"
"DEBUG" 2324 "2014-06-09 18:33:04.585" "DNS Blacklist Score -2"
"SMTPD" 2324 0 "2014-06-09 18:33:04.585" "TCP" "DNS lookup: 20.3.168.192.bl.spamcop.net, 1 addresses found: 127.0.0.2, Match: True"
"DEBUG" 2324 "2014-06-09 18:33:04.585" "DNS Blacklist Score -2"
"DEBUG" 2324 "2014-06-09 18:33:04.585" "Spam test: SpamTestDNSBlackLists, Score: -4"
"DEBUG" 2324 "2014-06-09 18:33:04.585" "Total spam score: -4"
"SMTPD" 2324 5 "2014-06-09 18:33:04.585" "192.168.3.20" "SENT: 250 OK"
"SMTPD" 2324 5 "2014-06-09 18:33:11.792" "192.168.3.20" "RECEIVED: RCPT TO:<test2@test.dom>"
"SMTPD" 2324 5 "2014-06-09 18:33:11.792" "192.168.3.20" "SENT: 250 OK"
"SMTPD" 964 5 "2014-06-09 18:33:15.646" "192.168.3.20" "RECEIVED: data"
"SMTPD" 964 5 "2014-06-09 18:33:15.661" "192.168.3.20" "SENT: 354 OK, send."
"DEBUG" 2120 "2014-06-09 18:33:20.700" "Total spam score: 0"
"DEBUG" 2120 "2014-06-09 18:33:20.700" "messagesize:: 197"
"DEBUG" 2120 "2014-06-09 18:33:20.700" "Saving message: {E0DC4E6C-4F8E-4FDA-9180-C24FB7A47F4E}.eml"
"DEBUG" 2120 "2014-06-09 18:33:20.700" "Requesting SMTPDeliveryManager to start message delivery"
"SMTPD" 2120 5 "2014-06-09 18:33:20.700" "192.168.3.20" "SENT: 250 Queued (5.039 seconds)"
"DEBUG" 2420 "2014-06-09 18:33:20.700" "Delivering message..."
"APPLICATION" 2420 "2014-06-09 18:33:20.716" "SMTPDeliverer - Message 1600: Delivering message from bill48105-2@somdomain.dom to test2@test.dom. File: Z:\hMailServer\Data\{E0DC4E6C-4F8E-4FDA-9180-C24FB7A47F4E}.eml"
"DEBUG" 2420 "2014-06-09 18:33:20.716" "Running custom virus scanner..."
"DEBUG" 2420 "2014-06-09 18:33:20.747" "Scanner: ping.exe Z:\hMailServer\Data\{E0DC4E6C-4F8E-4FDA-9180-C24FB7A47F4E}.eml. Return code: 1"

"DEBUG" 2420 "2014-06-09 18:33:20.747" "Applying rules"
"DEBUG" 2420 "2014-06-09 18:33:20.747" "Performing local delivery"
"DEBUG" 2420 "2014-06-09 18:33:20.872" "Creating out-of-office message."
"DEBUG" 2420 "2014-06-09 18:33:20.903" "messagesize:: 393"
"DEBUG" 2420 "2014-06-09 18:33:20.903" "Saving message: {7F973B9A-B6E6-43C7-B3B7-7BE31CF4FE29}.eml"
"DEBUG" 2420 "2014-06-09 18:33:20.903" "Requesting SMTPDeliveryManager to start message delivery"
"DEBUG" 2420 "2014-06-09 18:33:20.903" "Applying rules"
"DEBUG" 2420 "2014-06-09 18:33:20.903" "messagesize:: 197"
"DEBUG" 2420 "2014-06-09 18:33:20.903" "Saving message: {E0DC4E6C-4F8E-4FDA-9180-C24FB7A47F4E}.eml"
"DEBUG" 2420 "2014-06-09 18:33:20.903" "Local delivery completed"
"APPLICATION" 2420 "2014-06-09 18:33:20.903" "SMTPDeliverer - Message 1600: Message delivery thread completed."
"DEBUG" 2420 "2014-06-09 18:33:20.919" "Delivering message..."
"APPLICATION" 2420 "2014-06-09 18:33:20.919" "SMTPDeliverer - Message 1601: Delivering message from to bill48105-2@somdomain.dom. File: Z:\hMailServer\Data\{7F973B9A-B6E6-43C7-B3B7-7BE31CF4FE29}.eml"
"DEBUG" 2420 "2014-06-09 18:33:20.919" "Applying rules"
"DEBUG" 2420 "2014-06-09 18:33:20.919" "Performing local delivery"
"DEBUG" 2420 "2014-06-09 18:33:20.919" "Local delivery completed"
hMailServer build LIVE on my servers: 5.4-B2014050402
#hmailserver on FreeNode IRC https://webchat.freenode.net/?channels=#hmailserver
*** ABSENT FROM hMail! Those in IRC know how to find me if urgent. ***

percepts
Senior user
Senior user
Posts: 5282
Joined: 2009-10-20 16:33
Location: Sceptred Isle

Re: Vulnerability scan for viruses?

Post by percepts » 2014-06-10 01:53

Bill,

In your log you have two messages, 1599 and 1600.

In my log I only have one message ( 622 )being delivered to two different domains and virus scanner is run only once. But message was sent To: user@domain1.com,user@domain2.com which I think is what OP is seeing. The scan happens before the message is split. There is no RSET in my test. Don't know whats different between yours and mine.
"APPLICATION" 8944 "2014-06-10 00:35:44.892" "Stopping servers..."
"DEBUG" 8944 "2014-06-10 00:35:45.687" "Ending session 1"
"APPLICATION" 8944 "2014-06-10 00:35:45.687" "Servers stopped."
"DEBUG" 8944 "2014-06-10 00:35:45.953" "Application::ExitInstance - Closing database connection..."
"DEBUG" 8944 "2014-06-10 00:35:45.953" "Application::ExitInstance - Deleting caches..."
"DEBUG" 7268 "2014-06-10 00:35:46.311" "Application::InitInstance - Configuration loaded."
"APPLICATION" 7268 "2014-06-10 00:35:46.311" "Starting servers..."
"DEBUG" 11052 "2014-06-10 00:35:46.701" "SMTPDeliveryManager::Start()"
"DEBUG" 6532 "2014-06-10 00:35:46.701" "ExternalFetchManager::Start()"
"APPLICATION" 7268 "2014-06-10 00:35:46.701" "Servers started."
"DEBUG" 1036 "2014-06-10 00:35:54.938" "ScriptServer::FireEvent-OnClientConnect"
"DEBUG" 1036 "2014-06-10 00:35:54.954" "ScriptServer:~FireEvent"
"DEBUG" 1036 "2014-06-10 00:35:54.954" "Creating session 1"
"DEBUG" 1036 "2014-06-10 00:35:54.954" "TCPConnection::Write non ssl"
"DEBUG" 11144 "2014-06-10 00:35:54.954" "TCPConnection::Read non ssl"
"DEBUG" 1036 "2014-06-10 00:35:54.954" "TCPConnection::Write non ssl"
"DEBUG" 2756 "2014-06-10 00:35:54.954" "TCPConnection::Read non ssl"
"DEBUG" 1036 "2014-06-10 00:35:54.985" "TCPConnection::Write non ssl"
"DEBUG" 11144 "2014-06-10 00:35:55.001" "TCPConnection::Read non ssl"
"DEBUG" 1036 "2014-06-10 00:35:55.001" "TCPConnection::Write non ssl"
"DEBUG" 2756 "2014-06-10 00:35:55.001" "TCPConnection::Read non ssl"
"DEBUG" 1036 "2014-06-10 00:35:55.001" "TCPConnection::Write non ssl"
"DEBUG" 2756 "2014-06-10 00:35:55.016" "TCPConnection::Read non ssl"
"DEBUG" 1036 "2014-06-10 00:36:11.603" "ScriptServer::FireEvent-OnClientConnect"
"DEBUG" 1036 "2014-06-10 00:36:11.619" "ScriptServer:~FireEvent"
"DEBUG" 1036 "2014-06-10 00:36:11.619" "Creating session 2"
"SMTPD" 1036 2 "2014-06-10 00:36:11.619" "212.227.15.18" "SENT: 220 mail.mymailserver.com ESMTP"
"DEBUG" 1036 "2014-06-10 00:36:11.634" "TCPConnection::Write non ssl"
"DEBUG" 2756 "2014-06-10 00:36:11.634" "TCPConnection::Read non ssl"
"SMTPD" 2756 2 "2014-06-10 00:36:11.665" "212.227.15.18" "RECEIVED: EHLO mout.gmx.net"
"DEBUG" 2756 "2014-06-10 00:36:11.665" "SMTPConnection::_SendEHLOKeywords() - DisableAUTHList Option: "
"SMTPD" 2756 2 "2014-06-10 00:36:11.681" "212.227.15.18" "SENT: 250-mail.mymailserver.com[nl]250-SIZE 20000000[nl]250-AUTH LOGIN[nl]250 HELP"
"DEBUG" 2756 "2014-06-10 00:36:11.712" "TCPConnection::Write non ssl"
"DEBUG" 1036 "2014-06-10 00:36:11.717" "TCPConnection::Read non ssl"
"SMTPD" 1036 2 "2014-06-10 00:36:11.758" "212.227.15.18" "RECEIVED: MAIL FROM:<user@domain0.com> SIZE=1002"
"DEBUG" 1036 "2014-06-10 00:36:11.758" "Spam test: SpamTestHeloHost, Score: 0"
"DEBUG" 1036 "2014-06-10 00:36:11.758" "DNSResolver::_Resolve() - Using DNS Servers: Windows System DNS"
"DEBUG" 1036 "2014-06-10 00:36:11.773" "Spam test: SpamTestMXRecords, Score: 0"
"DEBUG" 1036 "2014-06-10 00:36:11.773" "Set OK. SPFDefaultPolicy: SPFDefaultPolicyA: "
"DEBUG" 1036 "2014-06-10 00:36:11.773" "SPFPolicyOverride Set: "
"DEBUG" 1036 "2014-06-10 00:36:11.773" "Spam test: SpamTestSPF, Score: 0"
"DEBUG" 1036 "2014-06-10 00:36:11.773" "Total spam score: 0"
"SMTPD" 1036 2 "2014-06-10 00:36:11.789" "212.227.15.18" "SENT: 250 OK"
"DEBUG" 1036 "2014-06-10 00:36:11.789" "TCPConnection::Write non ssl"
"DEBUG" 2756 "2014-06-10 00:36:11.789" "TCPConnection::Read non ssl"
"SMTPD" 10916 2 "2014-06-10 00:36:11.820" "212.227.15.18" "RECEIVED: RCPT TO:<user@domain1.com>"
"DEBUG" 10916 "2014-06-10 00:36:11.820" "RecipientParser::CheckDeliveryPossibility START: user@domain1.com"
"DEBUG" 10916 "2014-06-10 00:36:11.836" "RecipientParser::CheckDeliveryPossibility islocal"
"DEBUG" 10916 "2014-06-10 00:36:11.836" "RecipientParser::CheckDeliveryPossibility recurse 1"
"DEBUG" 10916 "2014-06-10 00:36:11.836" "RecipientParser::CheckDeliveryPossibility is account"
"DEBUG" 10916 "2014-06-10 00:36:11.836" "RecipientParser::CheckDeliveryPossibility is active user"
"DEBUG" 10916 "2014-06-10 00:36:11.836" "SMTPConnection::_ProtocolRCPT localsender false"
"DEBUG" 10916 "2014-06-10 00:36:11.836" "SMTPConnection::_ProtocolRCPT localDelivery true"
"SMTPD" 10916 2 "2014-06-10 00:36:11.836" "212.227.15.18" "SENT: 250 OK"
"DEBUG" 10916 "2014-06-10 00:36:11.851" "TCPConnection::Write non ssl"
"DEBUG" 7964 "2014-06-10 00:36:11.851" "TCPConnection::Read non ssl"
"SMTPD" 11144 2 "2014-06-10 00:36:11.883" "212.227.15.18" "RECEIVED: RCPT TO:<user@domain2.com>"
"DEBUG" 11144 "2014-06-10 00:36:11.883" "RecipientParser::CheckDeliveryPossibility START: user@domain2.com"
"DEBUG" 11144 "2014-06-10 00:36:11.883" "RecipientParser::CheckDeliveryPossibility islocal"
"DEBUG" 11144 "2014-06-10 00:36:11.898" "RecipientParser::CheckDeliveryPossibility recurse 1"
"DEBUG" 11144 "2014-06-10 00:36:11.903" "RecipientParser::CheckDeliveryPossibility is account"
"DEBUG" 11144 "2014-06-10 00:36:11.906" "RecipientParser::CheckDeliveryPossibility is active user"
"DEBUG" 11144 "2014-06-10 00:36:11.908" "SMTPConnection::_ProtocolRCPT localsender false"
"DEBUG" 11144 "2014-06-10 00:36:11.911" "SMTPConnection::_ProtocolRCPT localDelivery true"
"SMTPD" 11144 2 "2014-06-10 00:36:11.913" "212.227.15.18" "SENT: 250 OK"
"DEBUG" 11144 "2014-06-10 00:36:11.916" "TCPConnection::Write non ssl"
"DEBUG" 7748 "2014-06-10 00:36:11.918" "TCPConnection::Read non ssl"
"SMTPD" 7748 2 "2014-06-10 00:36:11.951" "212.227.15.18" "RECEIVED: DATA"
"DEBUG" 7748 "2014-06-10 00:36:11.953" "!m_sSTARTTLS.IsEmpty() TRUE"
"SMTPD" 7748 2 "2014-06-10 00:36:11.958" "212.227.15.18" "SENT: 354 OK, send."
"DEBUG" 7748 "2014-06-10 00:36:11.961" "TCPConnection::Write non ssl"
"DEBUG" 11144 "2014-06-10 00:36:11.963" "TCPConnection::Read non ssl"
"DEBUG" 7748 "2014-06-10 00:36:11.997" "TCPConnection::Read non ssl"
"DEBUG" 11144 "2014-06-10 00:36:11.997" "TCPConnection::Read non ssl"
"DEBUG" 11144 "2014-06-10 00:36:12.231" "DNSResolver::_Resolve() - Using DNS Servers: Windows System DNS"
"DEBUG" 6076 "2014-06-10 00:36:12.231" "Creating session 3"
"DEBUG" 11144 "2014-06-10 00:36:12.247" "TCPConnection::~TCPConnection 6!USESSL & !TLS"
"DEBUG" 11144 "2014-06-10 00:36:12.247" "TCPConnection::Write non ssl"
"DEBUG" 11144 "2014-06-10 00:36:12.247" "Sending message to SpamAssassin. Session 3, File: G:\docs\hMailServer\Data\{7AD5113D-CE55-4870-A15F-F16F52E5B45D}.eml"
"DEBUG" 7748 "2014-06-10 00:36:12.247" "TCPConnection::Write non ssl"
"DEBUG" 7964 "2014-06-10 00:36:12.262" "TCPConnection::Write non ssl"
"DEBUG" 10916 "2014-06-10 00:36:12.262" "TCPConnection::Write non ssl"
"DEBUG" 7964 "2014-06-10 00:36:12.262" "TCPConnection::Read non ssl"
"DEBUG" 1104 "2014-06-10 00:36:12.612" "Parsing response from SpamAssassin. Session 3"
"DEBUG" 1104 "2014-06-10 00:36:12.640" "TCPConnection::Read non ssl"
"DEBUG" 10676 "2014-06-10 00:36:12.650" "TCPConnection::Read non ssl"
"DEBUG" 1104 "2014-06-10 00:36:12.655" "TCPConnection::Read non ssl"
"DEBUG" 6076 "2014-06-10 00:36:12.660" "SA - Copy+Delete used"
"DEBUG" 6076 "2014-06-10 00:36:12.662" "MimeHeader::GetUnicodeFieldValue - sRawFieldValue.IsEmpty"
"DEBUG" 6076 "2014-06-10 00:36:12.665" "MessageData::GetFieldValue - GetUnicodeFieldValue sName: X-Spam-Status"
"DEBUG" 6076 "2014-06-10 00:36:12.670" "Ending session 3"
"DEBUG" 6076 "2014-06-10 00:36:12.670" "Spam test: SpamTestSpamAssassin, Score: 0"
"DEBUG" 6076 "2014-06-10 00:36:12.672" "Total spam score: 0"
"DEBUG" 6076 "2014-06-10 00:36:12.675" "ScriptServer::FireEvent-OnAcceptMessage"
"DEBUG" 6076 "2014-06-10 00:36:12.680" "MimeHeader::GetUnicodeFieldValue - sWideStr: user@domain1.com, user@domain2.com"
"DEBUG" 6076 "2014-06-10 00:36:12.682" "MessageData::GetFieldValue - GetUnicodeFieldValue sName: To"
"DEBUG" 6076 "2014-06-10 00:36:12.685" "ScriptServer:~FireEvent"
"DEBUG" 6076 "2014-06-10 00:36:12.687" "messagesize:: 1200"
"DEBUG" 6076 "2014-06-10 00:36:12.692" "Saving message: {7AD5113D-CE55-4870-A15F-F16F52E5B45D}.eml"
"DEBUG" 6076 "2014-06-10 00:36:12.695" "Requesting SMTPDeliveryManager to start message delivery"
"SMTPD" 6076 2 "2014-06-10 00:36:12.697" "212.227.15.18" "SENT: 250 Queued (0.718 seconds)"
"DEBUG" 9660 "2014-06-10 00:36:12.700" "Delivering message..."
"DEBUG" 6076 "2014-06-10 00:36:12.700" "TCPConnection::Write non ssl"
"APPLICATION" 9660 "2014-06-10 00:36:12.702" "SMTPDeliverer - Message 622: Delivering message from user@domain0.com to user@domain1.com, user@domain2.com. File: G:\docs\hMailServer\Data\{7AD5113D-CE55-4870-A15F-F16F52E5B45D}.eml"
"DEBUG" 1104 "2014-06-10 00:36:12.705" "TCPConnection::Read non ssl"
"DEBUG" 9660 "2014-06-10 00:36:12.707" "Running custom virus scanner..."
"SMTPD" 10676 2 "2014-06-10 00:36:12.737" "212.227.15.18" "RECEIVED: QUIT"
"SMTPD" 10676 2 "2014-06-10 00:36:12.740" "212.227.15.18" "SENT: 221 goodbye"
"DEBUG" 10676 "2014-06-10 00:36:12.745" "TCPConnection::Write non ssl"
"DEBUG" 1104 "2014-06-10 00:36:12.745" "Closing TCP/IP socket"
"DEBUG" 1104 "2014-06-10 00:36:12.745" "Ending session 2"
"DEBUG" 9660 "2014-06-10 00:36:12.760" "Scanner: "c:\program files\Microsoft Security Client\MpCmdRun.exe" -Scan -ScanType 3 -File "G:\docs\hMailServer\Data\{7AD5113D-CE55-4870-A15F-F16F52E5B45D}.eml" -DisableRemediation. Return code: 0"
"DEBUG" 9660 "2014-06-10 00:36:12.760" "Applying rules"
"DEBUG" 9660 "2014-06-10 00:36:12.807" "Performing local delivery"
"DEBUG" 9660 "2014-06-10 00:36:12.807" "Copying mail contents"
"DEBUG" 9660 "2014-06-10 00:36:12.823" "Applying rules"
"DEBUG" 9660 "2014-06-10 00:36:12.823" "messagesize:: 1130"
"DEBUG" 9660 "2014-06-10 00:36:12.823" "Saving message: {6DD2E123-6C23-4638-BA50-215F514BAA3A}.eml"
"DEBUG" 9660 "2014-06-10 00:36:12.838" "Applying rules"
"DEBUG" 9660 "2014-06-10 00:36:12.838" "messagesize:: 1130"
"DEBUG" 9660 "2014-06-10 00:36:12.838" "Saving message: {7AD5113D-CE55-4870-A15F-F16F52E5B45D}.eml"
"DEBUG" 9660 "2014-06-10 00:36:12.838" "Local delivery completed"
"APPLICATION" 9660 "2014-06-10 00:36:12.838" "SMTPDeliverer - Message 622: Message delivery thread completed."

Bill48105
Developer
Developer
Posts: 6192
Joined: 2010-04-24 23:16
Location: Michigan, USA

Re: Vulnerability scan for viruses?

Post by Bill48105 » 2014-06-10 02:07

percepts wrote:Bill,

In your log you have two messages, 1599 and 1600.

In my log I only have one message ( 622 )being delivered to two different domains and virus scanner is run only once. But message was sent To: user@domain1.com,user@domain2.com which I think is what OP is seeing. The scan happens before the message is split. There is no RSET in my test. Don't know whats different between yours and mine.
Ok thx. The difference is mine was from local to external. It must be external to local or local to local that it's happening. Since mine were to external the AV is done from the queue. I'll have to look at it again then.
thx
Bill
hMailServer build LIVE on my servers: 5.4-B2014050402
#hmailserver on FreeNode IRC https://webchat.freenode.net/?channels=#hmailserver
*** ABSENT FROM hMail! Those in IRC know how to find me if urgent. ***

percepts
Senior user
Senior user
Posts: 5282
Joined: 2009-10-20 16:33
Location: Sceptred Isle

Re: Vulnerability scan for viruses?

Post by percepts » 2014-06-10 02:12

Bill48105 wrote:
percepts wrote:Bill,

In your log you have two messages, 1599 and 1600.

In my log I only have one message ( 622 )being delivered to two different domains and virus scanner is run only once. But message was sent To: user@domain1.com,user@domain2.com which I think is what OP is seeing. The scan happens before the message is split. There is no RSET in my test. Don't know whats different between yours and mine.
Ok thx. The difference is mine was from local to external. It must be external to local or local to local that it's happening. Since mine were to external the AV is done from the queue. I'll have to look at it again then.
thx
Bill
I don't think there is a problem. Since the message hasn't been split it only needs to be scanned once and any added mail headers added by AV or Spam checker will appear in each mail when it is split. i.e. the expectation by OP that scan should happen multiple times is incorrect in my example instance.

Bill48105
Developer
Developer
Posts: 6192
Joined: 2010-04-24 23:16
Location: Michigan, USA

Re: Vulnerability scan for viruses?

Post by Bill48105 » 2014-06-10 03:33

if you didn't do a RSET between each percepts you are right it is one email but if you notice if you do RSET hmail queues each not as one. I need to test outside to in to confirm it though but hmail wouldn't say queued for each if they were 1 email.
hMailServer build LIVE on my servers: 5.4-B2014050402
#hmailserver on FreeNode IRC https://webchat.freenode.net/?channels=#hmailserver
*** ABSENT FROM hMail! Those in IRC know how to find me if urgent. ***

Bill48105
Developer
Developer
Posts: 6192
Joined: 2010-04-24 23:16
Location: Michigan, USA

Re: Vulnerability scan for viruses?

Post by Bill48105 » 2014-06-10 06:09

Think I'm not getting enough sleep.. I checked mine again & my tests were external to internal which appear to be what OP logs show as well. So not sure what could be different but in my case each was definitely being scanned. GUess we need to wait for OP for more info there is an important piece missing.
But yeah without RSET & multiple to's only 1 scan is done as it's 1 message with multiple recipients but with RSET they are treated as individual messages. Just not sure why here the logs look different than OP.
Bill
Bill48105 wrote:
percepts wrote:Bill,

In your log you have two messages, 1599 and 1600.

In my log I only have one message ( 622 )being delivered to two different domains and virus scanner is run only once. But message was sent To: user@domain1.com,user@domain2.com which I think is what OP is seeing. The scan happens before the message is split. There is no RSET in my test. Don't know whats different between yours and mine.
Ok thx. The difference is mine was from local to external. It must be external to local or local to local that it's happening. Since mine were to external the AV is done from the queue. I'll have to look at it again then.
thx
Bill
hMailServer build LIVE on my servers: 5.4-B2014050402
#hmailserver on FreeNode IRC https://webchat.freenode.net/?channels=#hmailserver
*** ABSENT FROM hMail! Those in IRC know how to find me if urgent. ***

HonzaK
New user
New user
Posts: 3
Joined: 2014-06-04 17:16

Re: Vulnerability scan for viruses?

Post by HonzaK » 2014-06-10 12:20

Hi guys,
thank you very much for your interest.
It was not one mail to multiple recipients. I tested five separate emails to deliver five different addresses. Exactly: I copied the five separate EML files with the virus in pickup folder on my test IIS SMTP. All mails should sender in the foreign domains and the recipient in local domains.
Yesterday I did not the IP of the my test IIS SMTP set for check the SPAM, now I have and doing it differently: hMailServer receipt only two mails in SMTP session. But the second mail not start AV check again.

I'm sorry, I'm not able to provide purified debug logs from hMailServer. It's a high-traffic production servers now. I have install separate hMail for testing first.

HonzaK
English is not my primary language, so please excuse for my English. Thanks.

percepts
Senior user
Senior user
Posts: 5282
Joined: 2009-10-20 16:33
Location: Sceptred Isle

Re: Vulnerability scan for viruses?

Post by percepts » 2014-06-10 14:12

OK I understand the problem now. I misinterpreted your log. :oops:

HonzaK
New user
New user
Posts: 3
Joined: 2014-06-04 17:16

Re: Vulnerability scan for viruses?

Post by HonzaK » 2014-06-10 16:53

Hi,
I have a testing environment, error is the same: one mail AV scanner checks, others pass without inspection.

This is debug log from hMailServer when receive and relay five different mails (without virus):
"DEBUG" 1720 "2014-06-10 16:43:57.504" "Creating session 25"
"SMTPD" 1720 25 "2014-06-10 16:43:57.504" "192.168.0.135" "SENT: 220 TestHMail ESMTP"
"SMTPD" 2280 25 "2014-06-10 16:43:57.504" "192.168.0.135" "RECEIVED: EHLO al12.aliaweb1.local"
"SMTPD" 2280 25 "2014-06-10 16:43:57.520" "192.168.0.135" "SENT: 250-TestHMail[nl]250-SIZE 20480000[nl]250 AUTH LOGIN"
"SMTPD" 2280 25 "2014-06-10 16:43:57.520" "192.168.0.135" "RECEIVED: MAIL FROM:<testvir-2@foreigndomain-2.cz> SIZE=766"
"SMTPD" 2280 25 "2014-06-10 16:43:57.520" "192.168.0.135" "SENT: 250 OK"
"SMTPD" 2280 25 "2014-06-10 16:43:57.520" "192.168.0.135" "RECEIVED: RCPT TO:<jan.kavka@aliaweb.cz>"
"SMTPD" 2280 25 "2014-06-10 16:43:57.535" "192.168.0.135" "SENT: 250 OK"
"SMTPD" 2280 25 "2014-06-10 16:43:57.535" "192.168.0.135" "RECEIVED: DATA"
"SMTPD" 2280 25 "2014-06-10 16:43:57.535" "192.168.0.135" "SENT: 354 OK, send."
"DEBUG" 4048 "2014-06-10 16:43:57.551" "Saving message: {63FA6B3F-AB3E-466C-A229-45F626E25D6A}.eml"
"DEBUG" 4048 "2014-06-10 16:43:57.551" "Requesting SMTPDeliveryManager to start message delivery"
"SMTPD" 4048 25 "2014-06-10 16:43:57.551" "192.168.0.135" "SENT: 250 Queued (0.016 seconds)"
"DEBUG" 4076 "2014-06-10 16:43:57.582" "Delivering message..."
"APPLICATION" 4076 "2014-06-10 16:43:57.582" "SMTPDeliverer - Message 120: Delivering message from testvir-2@foreigndomain-2.cz to jan.kavka@aliaweb.cz. File: C:\Program Files (x86)\hMailServer\Data\{63FA6B3F-AB3E-466C-A229-45F626E25D6A}.eml"
"DEBUG" 4076 "2014-06-10 16:43:57.582" "Running custom virus scanner..."
"SMTPD" 3136 25 "2014-06-10 16:43:57.613" "192.168.0.135" "RECEIVED: QUIT"
"SMTPD" 3136 25 "2014-06-10 16:43:57.613" "192.168.0.135" "SENT: 221 goodbye"
"DEBUG" 2280 "2014-06-10 16:43:57.613" "Closing TCP/IP socket"
"DEBUG" 2280 "2014-06-10 16:43:57.613" "Ending session 25"
"DEBUG" 1720 "2014-06-10 16:43:57.613" "Creating session 26"
"SMTPD" 1720 26 "2014-06-10 16:43:57.613" "192.168.0.135" "SENT: 220 TestHMail ESMTP"
"DEBUG" 2280 "2014-06-10 16:43:57.629" "Creating session 27"
"SMTPD" 2280 27 "2014-06-10 16:43:57.629" "192.168.0.135" "SENT: 220 TestHMail ESMTP"
"SMTPD" 1720 26 "2014-06-10 16:43:57.629" "192.168.0.135" "RECEIVED: EHLO al12.aliaweb1.local"
"SMTPD" 1720 26 "2014-06-10 16:43:57.629" "192.168.0.135" "SENT: 250-TestHMail[nl]250-SIZE 20480000[nl]250 AUTH LOGIN"
"SMTPD" 2280 27 "2014-06-10 16:43:57.629" "192.168.0.135" "RECEIVED: EHLO al12.aliaweb1.local"
"SMTPD" 2280 27 "2014-06-10 16:43:57.629" "192.168.0.135" "SENT: 250-TestHMail[nl]250-SIZE 20480000[nl]250 AUTH LOGIN"
"SMTPD" 1720 26 "2014-06-10 16:43:57.629" "192.168.0.135" "RECEIVED: MAIL FROM:<testvir-5@foreigndomain-5.cz> SIZE=760"
"SMTPD" 1720 26 "2014-06-10 16:43:57.645" "192.168.0.135" "SENT: 250 OK"
"SMTPD" 2280 27 "2014-06-10 16:43:57.645" "192.168.0.135" "RECEIVED: MAIL FROM:<testvir-4@foreigndomain-4.cz> SIZE=762"
"SMTPD" 2280 27 "2014-06-10 16:43:57.645" "192.168.0.135" "SENT: 250 OK"
"SMTPD" 1720 26 "2014-06-10 16:43:57.645" "192.168.0.135" "RECEIVED: RCPT TO:<admin@kurzy.cz>"
"SMTPD" 1720 26 "2014-06-10 16:43:57.645" "192.168.0.135" "SENT: 250 OK"
"SMTPD" 3312 27 "2014-06-10 16:43:57.645" "192.168.0.135" "RECEIVED: RCPT TO:<kavka@aliaweb.cz>"
"SMTPD" 3312 27 "2014-06-10 16:43:57.645" "192.168.0.135" "SENT: 250 OK"
"SMTPD" 1720 26 "2014-06-10 16:43:57.645" "192.168.0.135" "RECEIVED: DATA"
"SMTPD" 1720 26 "2014-06-10 16:43:57.660" "192.168.0.135" "SENT: 354 OK, send."
"SMTPD" 1720 27 "2014-06-10 16:43:57.660" "192.168.0.135" "RECEIVED: DATA"
"SMTPD" 1720 27 "2014-06-10 16:43:57.660" "192.168.0.135" "SENT: 354 OK, send."
"DEBUG" 4048 "2014-06-10 16:43:57.660" "Saving message: {72564A77-5B36-40D4-8F62-FE52E96FEAFE}.eml"
"DEBUG" 4048 "2014-06-10 16:43:57.660" "Requesting SMTPDeliveryManager to start message delivery"
"SMTPD" 4048 26 "2014-06-10 16:43:57.660" "192.168.0.135" "SENT: 250 Queued (0.000 seconds)"
"DEBUG" 2512 "2014-06-10 16:43:57.676" "Delivering message..."
"APPLICATION" 2512 "2014-06-10 16:43:57.676" "SMTPDeliverer - Message 121: Delivering message from testvir-5@foreigndomain-5.cz to admin@kurzy.cz. File: C:\Program Files (x86)\hMailServer\Data\{72564A77-5B36-40D4-8F62-FE52E96FEAFE}.eml"
"SMTPD" 1808 26 "2014-06-10 16:43:57.676" "192.168.0.135" "RECEIVED: RSET"
"SMTPD" 1808 26 "2014-06-10 16:43:57.676" "192.168.0.135" "SENT: 250 OK"
"DEBUG" 2512 "2014-06-10 16:43:57.676" "Running custom virus scanner..."
"SMTPD" 1808 26 "2014-06-10 16:43:57.676" "192.168.0.135" "RECEIVED: MAIL FROM:<testvir-1@foreigndomain-1.cz> SIZE=764"
"SMTPD" 1808 26 "2014-06-10 16:43:57.691" "192.168.0.135" "SENT: 250 OK"
"DEBUG" 4048 "2014-06-10 16:43:57.691" "Saving message: {ADE153B0-348F-4165-B673-DE43FC0CC7A5}.eml"
"SMTPD" 1808 26 "2014-06-10 16:43:57.691" "192.168.0.135" "RECEIVED: RCPT TO:<jan.kavka@kurzy.cz>"
"SMTPD" 1808 26 "2014-06-10 16:43:57.691" "192.168.0.135" "SENT: 250 OK"
"DEBUG" 4048 "2014-06-10 16:43:57.691" "Requesting SMTPDeliveryManager to start message delivery"
"SMTPD" 4048 27 "2014-06-10 16:43:57.691" "192.168.0.135" "SENT: 250 Queued (0.031 seconds)"
"SMTPD" 1808 26 "2014-06-10 16:43:57.691" "192.168.0.135" "RECEIVED: DATA"
"SMTPD" 1808 26 "2014-06-10 16:43:57.691" "192.168.0.135" "SENT: 354 OK, send."
"DEBUG" 3272 "2014-06-10 16:43:57.691" "Delivering message..."
"APPLICATION" 3272 "2014-06-10 16:43:57.691" "SMTPDeliverer - Message 122: Delivering message from testvir-4@foreigndomain-4.cz to kavka@aliaweb.cz. File: C:\Program Files (x86)\hMailServer\Data\{ADE153B0-348F-4165-B673-DE43FC0CC7A5}.eml"
"DEBUG" 3272 "2014-06-10 16:43:57.691" "Running custom virus scanner..."
"SMTPD" 3136 27 "2014-06-10 16:43:57.691" "192.168.0.135" "RECEIVED: RSET"
"SMTPD" 3136 27 "2014-06-10 16:43:57.691" "192.168.0.135" "SENT: 250 OK"
"SMTPD" 3136 27 "2014-06-10 16:43:57.707" "192.168.0.135" "RECEIVED: MAIL FROM:<testvir-3@foreigndomain-3.cz> SIZE=762"
"SMTPD" 3136 27 "2014-06-10 16:43:57.707" "192.168.0.135" "SENT: 250 OK"
"DEBUG" 4048 "2014-06-10 16:43:57.707" "Saving message: {4545B892-A8AD-4BCB-85B6-472F9AEB1A0D}.eml"
"DEBUG" 4048 "2014-06-10 16:43:57.707" "Requesting SMTPDeliveryManager to start message delivery"
"SMTPD" 4048 26 "2014-06-10 16:43:57.707" "192.168.0.135" "SENT: 250 Queued (0.016 seconds)"
"SMTPD" 1720 27 "2014-06-10 16:43:57.707" "192.168.0.135" "RECEIVED: RCPT TO:<honza@aliaweb.cz>"
"SMTPD" 1720 27 "2014-06-10 16:43:57.707" "192.168.0.135" "SENT: 250 OK"
"DEBUG" 1616 "2014-06-10 16:43:57.707" "Delivering message..."
"SMTPD" 3136 26 "2014-06-10 16:43:57.723" "192.168.0.135" "RECEIVED: QUIT"
"SMTPD" 3136 26 "2014-06-10 16:43:57.723" "192.168.0.135" "SENT: 221 goodbye"
"DEBUG" 1808 "2014-06-10 16:43:57.723" "Closing TCP/IP socket"
"DEBUG" 1808 "2014-06-10 16:43:57.723" "Ending session 26"
"APPLICATION" 1616 "2014-06-10 16:43:57.723" "SMTPDeliverer - Message 123: Delivering message from testvir-1@foreigndomain-1.cz to jan.kavka@kurzy.cz. File: C:\Program Files (x86)\hMailServer\Data\{4545B892-A8AD-4BCB-85B6-472F9AEB1A0D}.eml"
"SMTPD" 1720 27 "2014-06-10 16:43:57.723" "192.168.0.135" "RECEIVED: DATA"
"SMTPD" 1720 27 "2014-06-10 16:43:57.723" "192.168.0.135" "SENT: 354 OK, send."
"DEBUG" 1616 "2014-06-10 16:43:57.723" "Running custom virus scanner..."
"DEBUG" 4048 "2014-06-10 16:43:57.754" "Saving message: {4A0A3279-BFD4-43AB-B04D-A4927E75E52E}.eml"
"DEBUG" 4048 "2014-06-10 16:43:57.754" "Requesting SMTPDeliveryManager to start message delivery"
"SMTPD" 4048 27 "2014-06-10 16:43:57.754" "192.168.0.135" "SENT: 250 Queued (0.032 seconds)"
"DEBUG" 2212 "2014-06-10 16:43:57.754" "Delivering message..."
"APPLICATION" 2212 "2014-06-10 16:43:57.754" "SMTPDeliverer - Message 124: Delivering message from testvir-3@foreigndomain-3.cz to honza@aliaweb.cz. File: C:\Program Files (x86)\hMailServer\Data\{4A0A3279-BFD4-43AB-B04D-A4927E75E52E}.eml"
"SMTPD" 3136 27 "2014-06-10 16:43:57.754" "192.168.0.135" "RECEIVED: QUIT"
"SMTPD" 3136 27 "2014-06-10 16:43:57.754" "192.168.0.135" "SENT: 221 goodbye"
"DEBUG" 2212 "2014-06-10 16:43:57.754" "Running custom virus scanner..."
"DEBUG" 1808 "2014-06-10 16:43:57.754" "Closing TCP/IP socket"
"DEBUG" 1808 "2014-06-10 16:43:57.754" "Ending session 27"
"DEBUG" 4076 "2014-06-10 16:43:58.051" "Scanner: "C:\Program Files (x86)\hMailServer\Events\ViruScan.bat" "C:\Program Files (x86)\hMailServer\Data\{63FA6B3F-AB3E-466C-A229-45F626E25D6A}.eml". Return code: 0"
"DEBUG" 4076 "2014-06-10 16:43:58.051" "Applying rules"
"DEBUG" 4076 "2014-06-10 16:43:58.051" "Performing local delivery"
"DEBUG" 4076 "2014-06-10 16:43:58.051" "Local delivery completed"
"DEBUG" 4076 "2014-06-10 16:43:58.051" "Performing external delivery"
"APPLICATION" 4076 "2014-06-10 16:43:58.051" "SMTPDeliverer - Message 120: Relaying to host 192.168.0.4."
"DEBUG" 4076 "2014-06-10 16:43:58.051" "SD::_InitiateExternalConnection"
"DEBUG" 4076 "2014-06-10 16:43:58.051" "Creating session 28"
"DEBUG" 2512 "2014-06-10 16:43:58.051" "Scanner: "C:\Program Files (x86)\hMailServer\Events\ViruScan.bat" "C:\Program Files (x86)\hMailServer\Data\{72564A77-5B36-40D4-8F62-FE52E96FEAFE}.eml". Return code: 0"
"DEBUG" 2512 "2014-06-10 16:43:58.051" "Applying rules"
"DEBUG" 2512 "2014-06-10 16:43:58.051" "Performing local delivery"
"DEBUG" 2512 "2014-06-10 16:43:58.051" "Local delivery completed"
"DEBUG" 2512 "2014-06-10 16:43:58.051" "Performing external delivery"
"SMTPD" 2512 0 "2014-06-10 16:43:58.051" "TCP" "DNS - MX Lookup: kurzy.cz"
"DEBUG" 1616 "2014-06-10 16:43:58.051" "Scanner: "C:\Program Files (x86)\hMailServer\Events\ViruScan.bat" "C:\Program Files (x86)\hMailServer\Data\{4545B892-A8AD-4BCB-85B6-472F9AEB1A0D}.eml". Return code: 0"
"DEBUG" 1616 "2014-06-10 16:43:58.051" "Applying rules"
"DEBUG" 1616 "2014-06-10 16:43:58.051" "Performing local delivery"
"DEBUG" 1616 "2014-06-10 16:43:58.066" "Local delivery completed"
"DEBUG" 1616 "2014-06-10 16:43:58.066" "Performing external delivery"
"SMTPD" 1616 0 "2014-06-10 16:43:58.066" "TCP" "DNS - MX Lookup: kurzy.cz"
"SMTPD" 2512 0 "2014-06-10 16:43:58.082" "TCP" "DNS - MX Result: 2 IP addresses were found."
"DEBUG" 2512 "2014-06-10 16:43:58.098" "SD::_InitiateExternalConnection"
"DEBUG" 2512 "2014-06-10 16:43:58.098" "Creating session 29"
"SMTPD" 1616 0 "2014-06-10 16:43:58.098" "TCP" "DNS - MX Result: 2 IP addresses were found."
"DEBUG" 1616 "2014-06-10 16:43:58.098" "SD::_InitiateExternalConnection"
"DEBUG" 1616 "2014-06-10 16:43:58.098" "Creating session 30"
"DEBUG" 2212 "2014-06-10 16:43:58.098" "Scanner: "C:\Program Files (x86)\hMailServer\Events\ViruScan.bat" "C:\Program Files (x86)\hMailServer\Data\{4A0A3279-BFD4-43AB-B04D-A4927E75E52E}.eml". Return code: 0"
"DEBUG" 2212 "2014-06-10 16:43:58.098" "Applying rules"
"DEBUG" 2212 "2014-06-10 16:43:58.098" "Performing local delivery"
"DEBUG" 2212 "2014-06-10 16:43:58.098" "Local delivery completed"
"DEBUG" 2212 "2014-06-10 16:43:58.098" "Performing external delivery"
"APPLICATION" 2212 "2014-06-10 16:43:58.098" "SMTPDeliverer - Message 124: Relaying to host 192.168.0.4."
"DEBUG" 2212 "2014-06-10 16:43:58.098" "SD::_InitiateExternalConnection"
"DEBUG" 2212 "2014-06-10 16:43:58.098" "Creating session 31"
"DEBUG" 2352 "2014-06-10 16:43:58.113" "SMTPClientConnection::_ParseASCII()"
"SMTPC" 2352 28 "2014-06-10 16:43:58.113" "192.168.0.4" "RECEIVED: 220 primus-incoming.aliaweb1.local Microsoft ESMTP MAIL Service ready at Tue, 10 Jun 2014 16:43:57 +0200"
"SMTPC" 2352 28 "2014-06-10 16:43:58.113" "192.168.0.4" "SENT: HELO TestHMail"
"DEBUG" 2352 "2014-06-10 16:43:58.113" "SMTPClientConnection::~_ParseASCII() - 2"
"DEBUG" 3440 "2014-06-10 16:43:58.113" "SMTPClientConnection::_ParseASCII()"
"SMTPC" 3440 31 "2014-06-10 16:43:58.113" "192.168.0.4" "RECEIVED: 220 primus-incoming.aliaweb1.local Microsoft ESMTP MAIL Service ready at Tue, 10 Jun 2014 16:43:57 +0200"
"SMTPC" 3440 31 "2014-06-10 16:43:58.113" "192.168.0.4" "SENT: HELO TestHMail"
"DEBUG" 3440 "2014-06-10 16:43:58.113" "SMTPClientConnection::~_ParseASCII() - 2"
"DEBUG" 2352 "2014-06-10 16:43:58.113" "SMTPClientConnection::_ParseASCII()"
"SMTPC" 2352 28 "2014-06-10 16:43:58.113" "192.168.0.4" "RECEIVED: 250 primus-incoming.aliaweb1.local Hello [192.168.0.140]"
"SMTPC" 2352 28 "2014-06-10 16:43:58.113" "192.168.0.4" "SENT: MAIL FROM:<testvir-2@foreigndomain-2.cz>"
"DEBUG" 2352 "2014-06-10 16:43:58.113" "SMTPClientConnection::~_ParseASCII() - 4"
"DEBUG" 3440 "2014-06-10 16:43:58.113" "SMTPClientConnection::_ParseASCII()"
"SMTPC" 3440 31 "2014-06-10 16:43:58.113" "192.168.0.4" "RECEIVED: 250 primus-incoming.aliaweb1.local Hello [192.168.0.140]"
"SMTPC" 3440 31 "2014-06-10 16:43:58.113" "192.168.0.4" "SENT: MAIL FROM:<testvir-3@foreigndomain-3.cz>"
"DEBUG" 3440 "2014-06-10 16:43:58.113" "SMTPClientConnection::~_ParseASCII() - 4"
"DEBUG" 2352 "2014-06-10 16:43:58.113" "SMTPClientConnection::_ParseASCII()"
"SMTPC" 2352 28 "2014-06-10 16:43:58.113" "192.168.0.4" "RECEIVED: 250 2.1.0 Sender OK"
"DEBUG" 2352 "2014-06-10 16:43:58.113" "SMTPClientConnection::~_ParseASCII() - 6"
"SMTPC" 2352 28 "2014-06-10 16:43:58.129" "192.168.0.4" "SENT: RCPT TO:<jan.kavka@aliaweb.cz>"
"DEBUG" 3440 "2014-06-10 16:43:58.129" "SMTPClientConnection::_ParseASCII()"
"SMTPC" 3440 31 "2014-06-10 16:43:58.129" "192.168.0.4" "RECEIVED: 250 2.1.0 Sender OK"
"DEBUG" 3440 "2014-06-10 16:43:58.129" "SMTPClientConnection::~_ParseASCII() - 6"
"SMTPC" 3440 31 "2014-06-10 16:43:58.129" "192.168.0.4" "SENT: RCPT TO:<honza@aliaweb.cz>"
"DEBUG" 3928 "2014-06-10 16:43:58.129" "SMTPClientConnection::_ParseASCII()"
"SMTPC" 3928 31 "2014-06-10 16:43:58.129" "192.168.0.4" "RECEIVED: 250 2.1.5 Recipient OK"
"SMTPC" 3928 31 "2014-06-10 16:43:58.129" "192.168.0.4" "SENT: DATA"
"DEBUG" 3928 "2014-06-10 16:43:58.129" "SMTPClientConnection::~_ParseASCII() - 7"
"DEBUG" 2164 "2014-06-10 16:43:58.129" "SMTPClientConnection::_ParseASCII()"
"SMTPC" 2164 28 "2014-06-10 16:43:58.129" "192.168.0.4" "RECEIVED: 250 2.1.5 Recipient OK"
"SMTPC" 2164 28 "2014-06-10 16:43:58.129" "192.168.0.4" "SENT: DATA"
"DEBUG" 2164 "2014-06-10 16:43:58.129" "SMTPClientConnection::~_ParseASCII() - 7"
"DEBUG" 1888 "2014-06-10 16:43:58.129" "SMTPClientConnection::_ParseASCII()"
"SMTPC" 1888 31 "2014-06-10 16:43:58.129" "192.168.0.4" "RECEIVED: 354 Start mail input; end with <CRLF>.<CRLF>"
"DEBUG" 1888 "2014-06-10 16:43:58.129" "SMTPClientConnection::~_BEFORE SendFile"
"DEBUG" 1888 "2014-06-10 16:43:58.129" "SMTPClientConnection::~_Continue sendfile"
"DEBUG" 1888 "2014-06-10 16:43:58.129" "SMTPClientConnection::~_SendFile done close file"
"DEBUG" 1888 "2014-06-10 16:43:58.129" "SMTPClientConnection::~_SendFile flushed buffer"
"DEBUG" 1888 "2014-06-10 16:43:58.129" "SMTPClientConnection::~_SendFile DATASENT set"
"SMTPC" 1888 31 "2014-06-10 16:43:58.129" "192.168.0.4" "SENT: [nl]."
"DEBUG" 1888 "2014-06-10 16:43:58.129" "SMTPClientConnection::~_SendFile . sent"
"DEBUG" 1888 "2014-06-10 16:43:58.129" "SMTPClientConnection::~_SendFile DATASENT set"
"DEBUG" 1888 "2014-06-10 16:43:58.129" "SMTPClientConnection::~_AFTER SendFile"
"DEBUG" 3252 "2014-06-10 16:43:58.129" "SMTPClientConnection::_ParseASCII()"
"SMTPC" 3252 28 "2014-06-10 16:43:58.129" "192.168.0.4" "RECEIVED: 354 Start mail input; end with <CRLF>.<CRLF>"
"DEBUG" 3252 "2014-06-10 16:43:58.129" "SMTPClientConnection::~_BEFORE SendFile"
"DEBUG" 3252 "2014-06-10 16:43:58.129" "SMTPClientConnection::~_Continue sendfile"
"DEBUG" 3252 "2014-06-10 16:43:58.129" "SMTPClientConnection::~_SendFile done close file"
"DEBUG" 3252 "2014-06-10 16:43:58.129" "SMTPClientConnection::~_SendFile flushed buffer"
"DEBUG" 3252 "2014-06-10 16:43:58.129" "SMTPClientConnection::~_SendFile DATASENT set"
"SMTPC" 3252 28 "2014-06-10 16:43:58.129" "192.168.0.4" "SENT: [nl]."
"DEBUG" 3252 "2014-06-10 16:43:58.145" "SMTPClientConnection::~_SendFile . sent"
"DEBUG" 3252 "2014-06-10 16:43:58.145" "SMTPClientConnection::~_SendFile DATASENT set"
"DEBUG" 3252 "2014-06-10 16:43:58.145" "SMTPClientConnection::~_AFTER SendFile"
"DEBUG" 2280 "2014-06-10 16:43:58.723" "SMTPClientConnection::_ParseASCII()"
"SMTPC" 2280 31 "2014-06-10 16:43:58.723" "192.168.0.4" "RECEIVED: 250 2.6.0 <64DEFCAF-8410-4DA0-B783-07CA6332B380@mail2.aliaweb.cz> [InternalId=897453] Queued mail for delivery"
"DEBUG" 2280 "2014-06-10 16:43:58.723" "SMTPClientConnection::~_BEFORE SendQUIT"
"SMTPC" 2280 31 "2014-06-10 16:43:58.723" "192.168.0.4" "SENT: QUIT"
"DEBUG" 2280 "2014-06-10 16:43:58.723" "SMTPClientConnection::~_AFTER SendQUIT"
"DEBUG" 2280 "2014-06-10 16:43:58.723" "SMTPClientConnection::~_ParseASCII() - 9"
"DEBUG" 3312 "2014-06-10 16:43:58.754" "SMTPClientConnection::_ParseASCII()"
"SMTPC" 3312 31 "2014-06-10 16:43:58.754" "192.168.0.4" "RECEIVED: 221 2.0.0 Service closing transmission channel"
"DEBUG" 3312 "2014-06-10 16:43:58.754" "Closing TCP/IP socket"
"DEBUG" 2212 "2014-06-10 16:43:58.754" "SD::~_InitiateExternalConnection-5"
"DEBUG" 2212 "2014-06-10 16:43:58.754" "SD::~_DeliverToExternalAccounts-1"
"DEBUG" 2212 "2014-06-10 16:43:58.754" "Collect delivery result"
"DEBUG" 2212 "2014-06-10 16:43:58.754" "Collect delivery result - Done"
"DEBUG" 2212 "2014-06-10 16:43:58.754" "Deleting message"
"DEBUG" 2212 "2014-06-10 16:43:58.754" "Deleting message file."
"APPLICATION" 2212 "2014-06-10 16:43:58.754" "SMTPDeliverer - Message 124: Message delivery thread completed."
"DEBUG" 3248 "2014-06-10 16:43:58.754" "Ending session 31"
"DEBUG" 3248 "2014-06-10 16:43:58.785" "SMTPClientConnection::_ParseASCII()"
"SMTPC" 3248 28 "2014-06-10 16:43:58.785" "192.168.0.4" "RECEIVED: 250 2.6.0 <64DEFCAF-8410-4DA0-B783-07CA6332B380@mail2.aliaweb.cz> [InternalId=897454] Queued mail for delivery"
"DEBUG" 3248 "2014-06-10 16:43:58.785" "SMTPClientConnection::~_BEFORE SendQUIT"
"SMTPC" 3248 28 "2014-06-10 16:43:58.785" "192.168.0.4" "SENT: QUIT"
"DEBUG" 3248 "2014-06-10 16:43:58.785" "SMTPClientConnection::~_AFTER SendQUIT"
"DEBUG" 3248 "2014-06-10 16:43:58.785" "SMTPClientConnection::~_ParseASCII() - 9"
"DEBUG" 1808 "2014-06-10 16:43:58.801" "SMTPClientConnection::_ParseASCII()"
"SMTPC" 1808 28 "2014-06-10 16:43:58.801" "192.168.0.4" "RECEIVED: 221 2.0.0 Service closing transmission channel"
"DEBUG" 1808 "2014-06-10 16:43:58.801" "Closing TCP/IP socket"
"DEBUG" 4076 "2014-06-10 16:43:58.801" "SD::~_InitiateExternalConnection-5"
"DEBUG" 4076 "2014-06-10 16:43:58.801" "Ending session 28"
"DEBUG" 4076 "2014-06-10 16:43:58.801" "SD::~_DeliverToExternalAccounts-1"
"DEBUG" 4076 "2014-06-10 16:43:58.801" "Collect delivery result"
"DEBUG" 4076 "2014-06-10 16:43:58.801" "Collect delivery result - Done"
"DEBUG" 4076 "2014-06-10 16:43:58.801" "Deleting message"
"DEBUG" 4076 "2014-06-10 16:43:58.801" "Deleting message file."
"APPLICATION" 4076 "2014-06-10 16:43:58.801" "SMTPDeliverer - Message 120: Message delivery thread completed."
"DEBUG" 3272 "2014-06-10 16:43:59.644" "Scanner: "C:\Program Files (x86)\hMailServer\Events\ViruScan.bat" "C:\Program Files (x86)\hMailServer\Data\{ADE153B0-348F-4165-B673-DE43FC0CC7A5}.eml". Return code: 0"
"DEBUG" 3272 "2014-06-10 16:43:59.644" "Applying rules"
"DEBUG" 3272 "2014-06-10 16:43:59.644" "Performing local delivery"
"DEBUG" 3272 "2014-06-10 16:43:59.644" "Local delivery completed"
"DEBUG" 3272 "2014-06-10 16:43:59.644" "Performing external delivery"
"APPLICATION" 3272 "2014-06-10 16:43:59.644" "SMTPDeliverer - Message 122: Relaying to host 192.168.0.4."
"DEBUG" 3272 "2014-06-10 16:43:59.644" "SD::_InitiateExternalConnection"
"DEBUG" 3272 "2014-06-10 16:43:59.644" "Creating session 32"
"DEBUG" 3728 "2014-06-10 16:43:59.660" "SMTPClientConnection::_ParseASCII()"
"SMTPC" 3728 32 "2014-06-10 16:43:59.660" "192.168.0.4" "RECEIVED: 220 primus-incoming.aliaweb1.local Microsoft ESMTP MAIL Service ready at Tue, 10 Jun 2014 16:43:59 +0200"
"SMTPC" 3728 32 "2014-06-10 16:43:59.660" "192.168.0.4" "SENT: HELO TestHMail"
"DEBUG" 3728 "2014-06-10 16:43:59.660" "SMTPClientConnection::~_ParseASCII() - 2"
"DEBUG" 3792 "2014-06-10 16:43:59.660" "SMTPClientConnection::_ParseASCII()"
"SMTPC" 3792 32 "2014-06-10 16:43:59.660" "192.168.0.4" "RECEIVED: 250 primus-incoming.aliaweb1.local Hello [192.168.0.140]"
"SMTPC" 3792 32 "2014-06-10 16:43:59.660" "192.168.0.4" "SENT: MAIL FROM:<testvir-4@foreigndomain-4.cz>"
"DEBUG" 3792 "2014-06-10 16:43:59.660" "SMTPClientConnection::~_ParseASCII() - 4"
"DEBUG" 2164 "2014-06-10 16:43:59.676" "SMTPClientConnection::_ParseASCII()"
"SMTPC" 2164 32 "2014-06-10 16:43:59.676" "192.168.0.4" "RECEIVED: 250 2.1.0 Sender OK"
"DEBUG" 2164 "2014-06-10 16:43:59.676" "SMTPClientConnection::~_ParseASCII() - 6"
"SMTPC" 2164 32 "2014-06-10 16:43:59.676" "192.168.0.4" "SENT: RCPT TO:<kavka@aliaweb.cz>"
"DEBUG" 3252 "2014-06-10 16:43:59.676" "SMTPClientConnection::_ParseASCII()"
"SMTPC" 3252 32 "2014-06-10 16:43:59.676" "192.168.0.4" "RECEIVED: 250 2.1.5 Recipient OK"
"SMTPC" 3252 32 "2014-06-10 16:43:59.676" "192.168.0.4" "SENT: DATA"
"DEBUG" 3252 "2014-06-10 16:43:59.676" "SMTPClientConnection::~_ParseASCII() - 7"
"DEBUG" 1888 "2014-06-10 16:43:59.676" "SMTPClientConnection::_ParseASCII()"
"SMTPC" 1888 32 "2014-06-10 16:43:59.676" "192.168.0.4" "RECEIVED: 354 Start mail input; end with <CRLF>.<CRLF>"
"DEBUG" 1888 "2014-06-10 16:43:59.676" "SMTPClientConnection::~_BEFORE SendFile"
"DEBUG" 1888 "2014-06-10 16:43:59.676" "SMTPClientConnection::~_Continue sendfile"
"DEBUG" 1888 "2014-06-10 16:43:59.676" "SMTPClientConnection::~_SendFile done close file"
"DEBUG" 1888 "2014-06-10 16:43:59.676" "SMTPClientConnection::~_SendFile flushed buffer"
"DEBUG" 1888 "2014-06-10 16:43:59.676" "SMTPClientConnection::~_SendFile DATASENT set"
"SMTPC" 1888 32 "2014-06-10 16:43:59.676" "192.168.0.4" "SENT: [nl]."
"DEBUG" 1888 "2014-06-10 16:43:59.676" "SMTPClientConnection::~_SendFile . sent"
"DEBUG" 1888 "2014-06-10 16:43:59.676" "SMTPClientConnection::~_SendFile DATASENT set"
"DEBUG" 1888 "2014-06-10 16:43:59.676" "SMTPClientConnection::~_AFTER SendFile"
"DEBUG" 3252 "2014-06-10 16:44:00.207" "SMTPClientConnection::_ParseASCII()"
"SMTPC" 3252 32 "2014-06-10 16:44:00.207" "192.168.0.4" "RECEIVED: 250 2.6.0 <64DEFCAF-8410-4DA0-B783-07CA6332B380@mail2.aliaweb.cz> [InternalId=897455] Queued mail for delivery"
"DEBUG" 3252 "2014-06-10 16:44:00.207" "SMTPClientConnection::~_BEFORE SendQUIT"
"SMTPC" 3252 32 "2014-06-10 16:44:00.207" "192.168.0.4" "SENT: QUIT"
"DEBUG" 3252 "2014-06-10 16:44:00.223" "SMTPClientConnection::~_AFTER SendQUIT"
"DEBUG" 3252 "2014-06-10 16:44:00.223" "SMTPClientConnection::~_ParseASCII() - 9"
"DEBUG" 1888 "2014-06-10 16:44:00.223" "SMTPClientConnection::_ParseASCII()"
"SMTPC" 1888 32 "2014-06-10 16:44:00.223" "192.168.0.4" "RECEIVED: 221 2.0.0 Service closing transmission channel"
"DEBUG" 1888 "2014-06-10 16:44:00.223" "Closing TCP/IP socket"
"DEBUG" 3272 "2014-06-10 16:44:00.238" "SD::~_InitiateExternalConnection-5"
"DEBUG" 3272 "2014-06-10 16:44:00.238" "Ending session 32"
"DEBUG" 3272 "2014-06-10 16:44:00.238" "SD::~_DeliverToExternalAccounts-1"
"DEBUG" 3272 "2014-06-10 16:44:00.238" "Collect delivery result"
"DEBUG" 3272 "2014-06-10 16:44:00.238" "Collect delivery result - Done"
"DEBUG" 3272 "2014-06-10 16:44:00.238" "Deleting message"
"DEBUG" 3272 "2014-06-10 16:44:00.254" "Deleting message file."
"APPLICATION" 3272 "2014-06-10 16:44:00.254" "SMTPDeliverer - Message 122: Message delivery thread completed."
"DEBUG" 3136 "2014-06-10 16:44:49.454" "SMTPClientConnection::_ParseASCII()"
"SMTPC" 3136 29 "2014-06-10 16:44:49.454" "217.11.235.242" "RECEIVED: 220 mail2.aliaweb.cz ESMTP"
"SMTPC" 3136 29 "2014-06-10 16:44:49.469" "217.11.235.242" "SENT: HELO TestHMail"
"DEBUG" 3136 "2014-06-10 16:44:49.469" "SMTPClientConnection::~_ParseASCII() - 2"
"DEBUG" 1808 "2014-06-10 16:44:49.469" "SMTPClientConnection::_ParseASCII()"
"SMTPC" 1808 30 "2014-06-10 16:44:49.469" "217.11.235.242" "RECEIVED: 220 mail2.aliaweb.cz ESMTP"
"SMTPC" 1808 30 "2014-06-10 16:44:49.469" "217.11.235.242" "SENT: HELO TestHMail"
"DEBUG" 1808 "2014-06-10 16:44:49.469" "SMTPClientConnection::~_ParseASCII() - 2"
"DEBUG" 1720 "2014-06-10 16:44:49.501" "SMTPClientConnection::_ParseASCII()"
"SMTPC" 1720 29 "2014-06-10 16:44:49.501" "217.11.235.242" "RECEIVED: 250 Hello."
"SMTPC" 1720 29 "2014-06-10 16:44:49.501" "217.11.235.242" "SENT: MAIL FROM:<testvir-5@foreigndomain-5.cz>"
"DEBUG" 1720 "2014-06-10 16:44:49.501" "SMTPClientConnection::~_ParseASCII() - 4"
"DEBUG" 3248 "2014-06-10 16:44:49.501" "SMTPClientConnection::_ParseASCII()"
"SMTPC" 3248 30 "2014-06-10 16:44:49.501" "217.11.235.242" "RECEIVED: 250 Hello."
"SMTPC" 3248 30 "2014-06-10 16:44:49.501" "217.11.235.242" "SENT: MAIL FROM:<testvir-1@foreigndomain-1.cz>"
"DEBUG" 3248 "2014-06-10 16:44:49.516" "SMTPClientConnection::~_ParseASCII() - 4"
"DEBUG" 3312 "2014-06-10 16:44:49.548" "SMTPClientConnection::_ParseASCII()"
"SMTPC" 3312 29 "2014-06-10 16:44:49.548" "217.11.235.242" "RECEIVED: 250 OK"
"DEBUG" 3312 "2014-06-10 16:44:49.548" "SMTPClientConnection::~_ParseASCII() - 6"
"SMTPC" 3312 29 "2014-06-10 16:44:49.563" "217.11.235.242" "SENT: RCPT TO:<admin@kurzy.cz>"
"DEBUG" 3136 "2014-06-10 16:44:49.579" "SMTPClientConnection::_ParseASCII()"
"SMTPC" 3136 30 "2014-06-10 16:44:49.579" "217.11.235.242" "RECEIVED: 250 OK"
"DEBUG" 3136 "2014-06-10 16:44:49.579" "SMTPClientConnection::~_ParseASCII() - 6"
"SMTPC" 3136 30 "2014-06-10 16:44:49.579" "217.11.235.242" "SENT: RCPT TO:<jan.kavka@kurzy.cz>"
"DEBUG" 3248 "2014-06-10 16:44:49.610" "SMTPClientConnection::_ParseASCII()"
"SMTPC" 3248 29 "2014-06-10 16:44:49.610" "217.11.235.242" "RECEIVED: 250 OK"
"SMTPC" 3248 29 "2014-06-10 16:44:49.610" "217.11.235.242" "SENT: DATA"
"DEBUG" 3248 "2014-06-10 16:44:49.610" "SMTPClientConnection::~_ParseASCII() - 7"
"DEBUG" 3928 "2014-06-10 16:44:49.626" "SMTPClientConnection::_ParseASCII()"
"SMTPC" 3928 30 "2014-06-10 16:44:49.626" "217.11.235.242" "RECEIVED: 250 OK"
"SMTPC" 3928 30 "2014-06-10 16:44:49.626" "217.11.235.242" "SENT: DATA"
"DEBUG" 3928 "2014-06-10 16:44:49.626" "SMTPClientConnection::~_ParseASCII() - 7"
"DEBUG" 3440 "2014-06-10 16:44:49.626" "SMTPClientConnection::_ParseASCII()"
"SMTPC" 3440 29 "2014-06-10 16:44:49.626" "217.11.235.242" "RECEIVED: 354 OK, send."
"DEBUG" 3440 "2014-06-10 16:44:49.626" "SMTPClientConnection::~_BEFORE SendFile"
"DEBUG" 3440 "2014-06-10 16:44:49.641" "SMTPClientConnection::~_Continue sendfile"
"DEBUG" 3440 "2014-06-10 16:44:49.641" "SMTPClientConnection::~_SendFile done close file"
"DEBUG" 3440 "2014-06-10 16:44:49.641" "SMTPClientConnection::~_SendFile flushed buffer"
"DEBUG" 3440 "2014-06-10 16:44:49.641" "SMTPClientConnection::~_SendFile DATASENT set"
"SMTPC" 3440 29 "2014-06-10 16:44:49.641" "217.11.235.242" "SENT: [nl]."
"DEBUG" 3440 "2014-06-10 16:44:49.641" "SMTPClientConnection::~_SendFile . sent"
"DEBUG" 3440 "2014-06-10 16:44:49.641" "SMTPClientConnection::~_SendFile DATASENT set"
"DEBUG" 3440 "2014-06-10 16:44:49.641" "SMTPClientConnection::~_AFTER SendFile"
"DEBUG" 3928 "2014-06-10 16:44:49.641" "SMTPClientConnection::_ParseASCII()"
"SMTPC" 3928 30 "2014-06-10 16:44:49.641" "217.11.235.242" "RECEIVED: 354 OK, send."
"DEBUG" 3928 "2014-06-10 16:44:49.641" "SMTPClientConnection::~_BEFORE SendFile"
"DEBUG" 3928 "2014-06-10 16:44:49.641" "SMTPClientConnection::~_Continue sendfile"
"DEBUG" 3928 "2014-06-10 16:44:49.641" "SMTPClientConnection::~_SendFile done close file"
"DEBUG" 3928 "2014-06-10 16:44:49.641" "SMTPClientConnection::~_SendFile flushed buffer"
"DEBUG" 3928 "2014-06-10 16:44:49.641" "SMTPClientConnection::~_SendFile DATASENT set"
"SMTPC" 3928 30 "2014-06-10 16:44:49.641" "217.11.235.242" "SENT: [nl]."
"DEBUG" 3928 "2014-06-10 16:44:49.641" "SMTPClientConnection::~_SendFile . sent"
"DEBUG" 3928 "2014-06-10 16:44:49.641" "SMTPClientConnection::~_SendFile DATASENT set"
"DEBUG" 3928 "2014-06-10 16:44:49.641" "SMTPClientConnection::~_AFTER SendFile"
"DEBUG" 3352 "2014-06-10 16:44:56.157" "SMTPClientConnection::_ParseASCII()"
"SMTPC" 3352 29 "2014-06-10 16:44:56.157" "217.11.235.242" "RECEIVED: 250 Queued (6.469 seconds)"
"DEBUG" 3352 "2014-06-10 16:44:56.157" "SMTPClientConnection::~_BEFORE SendQUIT"
"SMTPC" 3352 29 "2014-06-10 16:44:56.157" "217.11.235.242" "SENT: QUIT"
"DEBUG" 3352 "2014-06-10 16:44:56.157" "SMTPClientConnection::~_AFTER SendQUIT"
"DEBUG" 3352 "2014-06-10 16:44:56.157" "SMTPClientConnection::~_ParseASCII() - 9"
"DEBUG" 3728 "2014-06-10 16:44:56.172" "SMTPClientConnection::_ParseASCII()"
"SMTPC" 3728 30 "2014-06-10 16:44:56.172" "217.11.235.242" "RECEIVED: 250 Queued (6.469 seconds)"
"DEBUG" 3728 "2014-06-10 16:44:56.172" "SMTPClientConnection::~_BEFORE SendQUIT"
"SMTPC" 3728 30 "2014-06-10 16:44:56.172" "217.11.235.242" "SENT: QUIT"
"DEBUG" 3728 "2014-06-10 16:44:56.172" "SMTPClientConnection::~_AFTER SendQUIT"
"DEBUG" 3728 "2014-06-10 16:44:56.172" "SMTPClientConnection::~_ParseASCII() - 9"
"DEBUG" 2164 "2014-06-10 16:45:22.859" "SMTPClientConnection::_ParseASCII()"
"SMTPC" 2164 29 "2014-06-10 16:45:22.859" "217.11.235.242" "RECEIVED: 221 goodbye"
"DEBUG" 2164 "2014-06-10 16:45:22.859" "Closing TCP/IP socket"
"DEBUG" 1888 "2014-06-10 16:45:22.859" "SMTPClientConnection::_ParseASCII()"
"SMTPC" 1888 30 "2014-06-10 16:45:22.859" "217.11.235.242" "RECEIVED: 221 goodbye"
"DEBUG" 1888 "2014-06-10 16:45:22.875" "Closing TCP/IP socket"
"DEBUG" 2512 "2014-06-10 16:45:22.859" "SD::~_InitiateExternalConnection-5"
"DEBUG" 2512 "2014-06-10 16:45:22.875" "Ending session 29"
"DEBUG" 2512 "2014-06-10 16:45:22.875" "SD::~_DeliverToExternalAccounts-1"
"DEBUG" 2512 "2014-06-10 16:45:22.875" "Collect delivery result"
"DEBUG" 2512 "2014-06-10 16:45:22.875" "Collect delivery result - Done"
"DEBUG" 2512 "2014-06-10 16:45:22.875" "Deleting message"
"DEBUG" 2512 "2014-06-10 16:45:22.875" "Deleting message file."
"APPLICATION" 2512 "2014-06-10 16:45:22.890" "SMTPDeliverer - Message 121: Message delivery thread completed."
"DEBUG" 1616 "2014-06-10 16:45:22.875" "SD::~_InitiateExternalConnection-5"
"DEBUG" 1616 "2014-06-10 16:45:22.890" "Ending session 30"
"DEBUG" 1616 "2014-06-10 16:45:22.890" "SD::~_DeliverToExternalAccounts-1"
"DEBUG" 1616 "2014-06-10 16:45:22.890" "Collect delivery result"
"DEBUG" 1616 "2014-06-10 16:45:22.906" "Collect delivery result - Done"
"DEBUG" 1616 "2014-06-10 16:45:22.906" "Deleting message"
"DEBUG" 1616 "2014-06-10 16:45:22.906" "Deleting message file."
"APPLICATION" 1616 "2014-06-10 16:45:22.906" "SMTPDeliverer - Message 123: Message delivery thread completed."


This is log created by VirusScan.bat:
Ut 10.06.2014 16:43:57,83 Start of check file "C:\Program Files (x86)\hMailServer\Data\{ADE153B0-348F-4165-B673-DE43FC0CC7A5}.eml"
Ut 10.06.2014 16:43:57,83 Start of check file "C:\Program Files (x86)\hMailServer\Data\{63FA6B3F-AB3E-466C-A229-45F626E25D6A}.eml"
Ut 10.06.2014 16:43:57,84 Start of check file "C:\Program Files (x86)\hMailServer\Data\{72564A77-5B36-40D4-8F62-FE52E96FEAFE}.eml"
Ut 10.06.2014 16:43:57,86 Start of check file "C:\Program Files (x86)\hMailServer\Data\{4545B892-A8AD-4BCB-85B6-472F9AEB1A0D}.eml"

ECLS Command-line scanner, version 7.0.317.0, (C) 1992-2014 ESET, spol. s r.o.
...

Command line: /base-dir=C:\Program Files\ESET\ESET NOD32 Antivirus /adv-heur /no-boots /arch /log-file=C:\Log\hMail\av140610.log C:\Program Files (x86)\hMailServer\Data\{ADE153B0-348F-4165-B673-DE43FC0CC7A5}.eml

Start scanning 6/10/14 4:43:59 p.m.

End of the scan 6/10/14 4:43:59 p.m.
Total time: 0 sec (0:00:00)
Total: files - 1, objects 1
Infected: files - 0, objects 0
Cured: files - 0, objects 0

Ut 10.06.2014 16:43:59,64 End of check file "C:\Program Files (x86)\hMailServer\Data\{ADE153B0-348F-4165-B673-DE43FC0CC7A5}.eml"


This is content of ViruScan.bat:
@echo off
for /f "tokens=2-4 delims=/ " %%i in ('date/t') do set mmddyyyy=%%i%%j%%k
set yymmdd=%mmddyyyy:~8,2%%mmddyyyy:~3,2%%mmddyyyy:~0,2%
set LogName=%LogDir%hMail\av
set avLog=%LogName%%yymmdd%.log

set AVFolder="C:\Program Files\ESET\ESET NOD32 Antivirus"
set AVExe="C:\Program Files\ESET\ESET NOD32 Antivirus\ecls.exe"

Echo %date% %time% Start of check file %1 >> %avLog%
%AVExe% /base-dir=%AVFolder% /adv-heur /no-boots /arch /log-file=%AVLog% %1
Echo %date% %time% End of check file %1 >> %avLog%

exit /b %erorlevel%



It looks as wrong serialized requirements to run or wait for reply.

HonzaK
English is not my primary language, so please excuse for my English. Thanks.

Post Reply