HmailServer & SpamAssassin : The WinSock error code is 2.

RvdH · Post by **RvdH** » 2015-05-15 10:06

Occasionally I notice a few errors a day in my hMailserver logs, all containing the error message below:

"ERROR"	9164	"DATE & TIME"	Severity: 3 (Medium), Code: HM5157, Source: SpamAssassinClient::OnReadError, Description: There was a communication error with SpamAssassin. hMailServer tried to retrieve data from SpamAssassin but the connection to SpamAssassin was lost. The WinSock error code is 2. Enable debug logging to retrieve more information regarding this problem. The problem could be that SpamAssassin is malfunctioning."
"ERROR"	2436	"DATE & TIME"	"Severity: 2 (High), Code: HM5508, Source: SpamAssassinTestConnect::TestConnect, Description: The SpamAssassin tests did not complete. Please confirm that the configuration (host name and port) is valid and that SpamAssassin is running."

I reviewed the time it takes to scan such messages, because i was thinking it was some sort of timeout...this not seems to be the case, because as you can see in the examples below scan times are very reasonable.
I included both the Error entries in the hmailserver logs as my SpamD log.

Code: Select all

"ERROR"	9164	"2015-05-12 16:27:36.471"	"Severity: 3 (Medium), Code: HM5157, Source: SpamAssassinClient::OnReadError, Description: There was a communication error with SpamAssassin. hMailServer tried to retrieve data from SpamAssassin but the connection to SpamAssassin was lost. The WinSock error code is 2. Enable debug logging to retrieve more information regarding this problem. The problem could be that SpamAssassin is malfunctioning."
"ERROR"	2436	"2015-05-12 16:27:36.471"	"Severity: 2 (High), Code: HM5508, Source: SpamAssassinTestConnect::TestConnect, Description: The SpamAssassin tests did not complete. Please confirm that the configuration (host name and port) is valid and that SpamAssassin is running."

Code: Select all

Tue May 12 16:27:32 2015 [-6960] info: spamd: connection from SERVER [127.0.0.1]:51840 to port 783, fd 6
Tue May 12 16:27:32 2015 [-6960] info: spamd: processing message <79756f667d73013ebdc4a4efba99b240@smtp10.ymlpsrvr.com> for (unknown):0
Tue May 12 16:27:36 2015 [-6960] info: spamd: clean message (-7.4/4.0) for (unknown):0 in 4.1 seconds, 56606 bytes.
Tue May 12 16:27:36 2015 [-6960] info: spamd: result: . -7 - BAYES_00,HTML_FONT_LOW_CONTRAST,HTML_MESSAGE,JAM_SMALL_FONT_SIZE,SPF_HELO_PASS,USER_IN_WHITELIST_TO scantime=4.1,size=56606,user=(unknown),uid=0,required_score=4.0,rhost=Jonkergouw-Infomatisering,raddr=127.0.0.1,rport=51840,mid=<79756f667d73013ebdc4a4efba99b240@smtp10.ymlpsrvr.com>,bayes=0.000000,autolearn=no autolearn_force=no,shortcircuit=no
Tue May 12 16:27:36 2015 [4848] info: prefork: child states: II

Code: Select all

"ERROR"	1488	"2015-05-13 18:53:57.896"	"Severity: 3 (Medium), Code: HM5157, Source: SpamAssassinClient::OnReadError, Description: There was a communication error with SpamAssassin. hMailServer tried to retrieve data from SpamAssassin but the connection to SpamAssassin was lost. The WinSock error code is 2. Enable debug logging to retrieve more information regarding this problem. The problem could be that SpamAssassin is malfunctioning."
"ERROR"	9048	"2015-05-13 18:53:57.896"	"Severity: 2 (High), Code: HM5508, Source: SpamAssassinTestConnect::TestConnect, Description: The SpamAssassin tests did not complete. Please confirm that the configuration (host name and port) is valid and that SpamAssassin is running."

Code: Select all

Wed May 13 18:53:56 2015 [-8288] info: spamd: connection from SERVER [127.0.0.1]:55834 to port 783, fd 6
Wed May 13 18:53:56 2015 [-8288] info: spamd: processing message <555381BD.6000102@ruma-vsm.nl> for (unknown):0
Wed May 13 18:53:57 2015 [-8288] info: spamd: clean message (-1.9/4.0) for (unknown):0 in 1.0 seconds, 17388 bytes.
Wed May 13 18:53:57 2015 [-8288] info: spamd: result: . -1 - BAYES_00,HTML_MESSAGE,T_KAM_HTML_FONT_INVALID scantime=1.0,size=17388,user=(unknown),uid=0,required_score=4.0,rhost=Jonkergouw-Infomatisering,raddr=127.0.0.1,rport=55834,mid=<555381BD.6000102@ruma-vsm.nl>,bayes=0.000000,autolearn=no autolearn_force=no,shortcircuit=no
Wed May 13 18:53:57 2015 [4792] info: prefork: child states: II

Code: Select all

"ERROR"	8724	"2015-05-13 15:27:51.567"	"Severity: 3 (Medium), Code: HM5157, Source: SpamAssassinClient::OnReadError, Description: There was a communication error with SpamAssassin. hMailServer tried to retrieve data from SpamAssassin but the connection to SpamAssassin was lost. The WinSock error code is 2. Enable debug logging to retrieve more information regarding this problem. The problem could be that SpamAssassin is malfunctioning."
"ERROR"	2436	"2015-05-13 15:27:51.582"	"Severity: 2 (High), Code: HM5508, Source: SpamAssassinTestConnect::TestConnect, Description: The SpamAssassin tests did not complete. Please confirm that the configuration (host name and port) is valid and that SpamAssassin is running."

Code: Select all

Wed May 13 15:27:47 2015 [-4092] info: spamd: connection from SERVER [127.0.0.1]:54392 to port 783, fd 6
Wed May 13 15:27:47 2015 [-4092] info: spamd: processing message <79C50FA0-98D6-4F8E-A4AC-44017B116B56@jonkergouw.systemec.nl> for (unknown):0
Wed May 13 15:27:51 2015 [-4092] info: spamd: identified spam (29.5/4.0) for (unknown):0 in 4.5 seconds, 5362 bytes.
Wed May 13 15:27:51 2015 [-4092] info: spamd: result: Y 29 - BAYES_99,BAYES_999,CUSTOM_MANY_BL,DATE_IN_PAST_12_24,DEAR_SOMETHING,HTML_MESSAGE,MIME_HTML_ONLY,MSGID_FROM_MTA_HEADER,RCVD_IN_ANONMAILS,RCVD_IN_BRBL_LASTEXT,RCVD_IN_HOSTKARMA_BL,RCVD_IN_PBL,RCVD_IN_UCEPROTECT1,RDNS_NONE,URIBL_DBL_SPAM,XPRIO scantime=4.5,size=5362,user=(unknown),uid=0,required_score=4.0,rhost=Jonkergouw-Infomatisering,raddr=127.0.0.1,rport=54392,mid=<79C50FA0-98D6-4F8E-A4AC-44017B116B56@jonkergouw.systemec.nl>,bayes=1.000000,autolearn=no autolearn_force=no,shortcircuit=no
Wed May 13 15:27:51 2015 [5524] info: prefork: child states: II

Code: Select all

"ERROR"	3440	"2015-05-15 03:52:10.958"	"Severity: 3 (Medium), Code: HM5157, Source: SpamAssassinClient::OnReadError, Description: There was a communication error with SpamAssassin. hMailServer tried to retrieve data from SpamAssassin but the connection to SpamAssassin was lost. The WinSock error code is 2. Enable debug logging to retrieve more information regarding this problem. The problem could be that SpamAssassin is malfunctioning."
"ERROR"	3208	"2015-05-15 03:52:10.958"	"Severity: 2 (High), Code: HM5508, Source: SpamAssassinTestConnect::TestConnect, Description: The SpamAssassin tests did not complete. Please confirm that the configuration (host name and port) is valid and that SpamAssassin is running."

Code: Select all

Fri May 15 03:52:08 2015 [-5764] info: spamd: connection from SERVER [127.0.0.1]:55908 to port 783, fd 6
Fri May 15 03:52:08 2015 [-5764] info: spamd: processing message <20150515_015230_090410.noreply@2dehands.be> for (unknown):0
Fri May 15 03:52:10 2015 [-5764] info: spamd: clean message (0.4/4.0) for (unknown):0 in 2.0 seconds, 95395 bytes.
Fri May 15 03:52:10 2015 [-5764] info: spamd: result: . 0 - BAYES_00,DKIM_SIGNED,HTML_MESSAGE,JAM_LONG_LINK,RCVD_IN_MSPIKE_H4,RCVD_IN_MSPIKE_WL,T_DKIM_INVALID scantime=2.0,size=95395,user=(unknown),uid=0,required_score=4.0,rhost=Jonkergouw-Informatisering,raddr=127.0.0.1,rport=55908,mid=<20150515_015230_090410.noreply@2dehands.be>,bayes=0.000000,autolearn=no autolearn_force=no,shortcircuit=no
Fri May 15 03:52:11 2015 [56] info: prefork: child states: II

Anyone knows what causes this, and more importantly...how to fix?

jimimaseye · Post by **jimimaseye** » 2015-05-15 11:45

I have never seen this winsock error 2 before (and even googling struggles to find reference to it)

Are you running the JAm SA For Windows? If so THEY say that there is a known bug in their free version of the software (something to do with memory leaks) that requires the service to be restarted. (In fairness I have never seen problems and suspect they just say this to get you to buy their 'paid' version - but having said that my SA gets stopped and restarted everynight anyway for the rule updates to take effect).

Have you enabled DEBUG and checked the logs (as it suggests you do) to see if it gives any more clues?
I assume normally its running without a problem, right? (and that this happens only occasionally?)

RvdH · Post by **RvdH** » 2015-05-15 12:07

Yes, this only happens only occasionally (1 to 3 times a day)

I use JAM SpamAssassin for Windows v3.4.0
spamd.exe is ran with these parameters:

Code: Select all

--allow-tell --syslog "C:\Logs\spamd.log" --max-children=5 --min-children=1 --min-spare=1 --max-spare=2 --max-conn-per-child=200 --timeout-child=30 --timeout-tcp=30 --nouser-config

In spamassassin local.conf

Code: Select all

# Specifies a limit on elapsed time in seconds that SpamAssassin is allowed to spend 
# before providing a result. The value may be fractional and must not be negative, zero is interpreted as unlimited. 
# The default is 300 seconds for consistency with the spamd default setting of --timeout-child .
time_limit 30

I run a self-written customized service (Something like JAM SpamAssassin in a Box) that restarts the spamd.exe every X specified minutes/hours, but the issues above are not related to this automatic restarts. FYI, the service i wrote first checks if spamd.exe processor usage is 0% before restarting, if it higher then the restart is delayed. Automatic sa-update are applied exactly the same, download updates every X specified hours, then again check if spamd.exe processor usage is 0% before restarting, if it higher then the restart is delayed.

I do not think it is related to the bug you mention because spamd after such error continues without further errors, it looks like it occurs completely randomly

I don't have DEBUG enabled (yet) as this is a production server with quite a few users/domains

jimimaseye · Post by **jimimaseye** » 2015-05-15 12:31

I too use SA 3.4 from Jam.

I can only assume therefore that a limit is being reached due to one of the config parameters you are using. I personally dont get your error so all I can do for you (without further reading up on your choice of parameters which you can do yourself) is point you to my setup. I use considerably less by configuration:

viewtopic.php?f=21&t=28133

in short, I ONLY use

Code: Select all

 -l -s "c:\path to\spamd.log" --round-robin --timeout-child=85

as the spamd parameters and I have no such 'time limit' in my LOCAL.CF.

Maybe this helps.

(I acknowledge that maybe your system and throughput of mail might be a lot higher than mine and that you have 'tweaked' specifically for what you think will help your hardware. Even so....)

RvdH · Post by **RvdH** » 2015-05-15 12:38

I don't think it is related to the command line arguments I pass either, most of them hold the default values

https://spamassassin.apache.org/full/3. ... spamd.html

--max-children=5 #default setting
--min-children=1 #default setting
--min-spare=1 #default setting
--max-spare=2 #default setting
--max-conn-per-child=200 #default setting
--timeout-child=30 #NON default
--timeout-tcp=30 #default setting

I am bit surprised you use the --round-robin option though, as this uses traditional prefork algorithm

Code: Select all

--round-robin
By default, spamd will attempt to keep a small number of "hot" child processes as busy as possible, and keep any others as idle as possible, using something similar to the Apache httpd server scaling algorithm. This is accomplished by the master process coordinating the activities of the children. This switch will disable this scaling algorithm, and the behaviour seen in the 3.0.x versions will be used instead, where all processes receive an equal load and no scaling takes place.

jimimaseye · Post by **jimimaseye** » 2015-05-15 12:48

Well its all above my head, my friend. But even so... I dont have that problem. So if you are dismissing the other parameters (because they seem reasonable or are default anyway), then that leaves roundrobin as the only difference. So maybe as a diagnostic you could try it. You never know what you may find.

Spamassassin is no ones speciality here on the HMS forum and in fairness you will likely get less offerings from other people of tailoring it than you have had from me (and as you can see I am WELL away from being an 'expert' on it). Hopefully someone else may be able to recognise the same problem and offere advice but I havent seen anyone mention this before (so wouldnt expect it).

So now, my advice:

a, try ROUNDROBIN and see what happens
b, try a Spamassassin expert forum (Im sure there is one).
c, enable DEBUG logging (but I know this will create huge logs that often dont show anything useful, so may be undesirable)

RvdH · Post by **RvdH** » 2015-05-15 12:57

FYI, i just checked the parameters JAM SpamAssassin in a Box uses

Code: Select all

<?xml version="1.0" encoding="UTF-8"?>
<GlobalOptions Version="2" AppVersion="2.11" Type="TSpamdOptions">
	<AllowTell>True</AllowTell>
	<ConfigPath></ConfigPath>
	<SiteConfigPath></SiteConfigPath>
	<AllowedIPs>127.0.0.1</AllowedIPs>
	<ListenIP>127.0.0.1</ListenIP>
	<ListenPort>783</ListenPort>
	<MaxChildren>5</MaxChildren>
	<MinChildren>1</MinChildren>
	<MaxSpare>2</MaxSpare>
	<MinSpare>1</MinSpare>
	<MaxConnPerChild>200</MaxConnPerChild>
	<RoundRobin>False</RoundRobin>
	<TimeoutChild>300</TimeoutChild>
	<TimeoutTcp>30</TimeoutTcp>
	<SysLog>C:\ProgramData\JAM Software\spamdService\sa-logs\SpamD.log</SysLog>
	<Debug>False</Debug>
	<Local>False</Local>
	<Tag>0</Tag>
</GlobalOptions>

Not saying you cant be right, but as you see they don't use RoundRobin either

jimimaseye · Post by **jimimaseye** » 2015-05-15 13:02

This doesnt mean anything and certainly doesnt help you with your problem.

My point is that I dont have the problem, and I use roundrobin. *I* dont know if the fact that I dont have the problem is related or not to using roundrobin. I only know that *you* DO have the problem and also you DONT use roundrobin.

Therefore, for diagnostics and to rule it out.....

RvdH · Post by **RvdH** » 2015-05-15 16:45

I enabled the DEBUG option, have not had to wait long for it to reoccur

Code: Select all

"ERROR"	3424	"2015-05-15 16:22:21.795"	"Severity: 3 (Medium), Code: HM5157, Source: SpamAssassinClient::OnReadError, Description: There was a communication error with SpamAssassin. hMailServer tried to retrieve data from SpamAssassin but the connection to SpamAssassin was lost. The WinSock error code is 2. Enable debug logging to retrieve more information regarding this problem. The problem could be that SpamAssassin is malfunctioning."
"ERROR"	3192	"2015-05-15 16:22:21.811"	"Severity: 2 (High), Code: HM5508, Source: SpamAssassinTestConnect::TestConnect, Description: The SpamAssassin tests did not complete. Please confirm that the configuration (host name and port) is valid and that SpamAssassin is running."

Code: Select all

Fri May 15 16:22:17 2015 [-7948] info: spamd: connection from Jonkergouw-Informatisering [127.0.0.1]:57174 to port 783, fd 6
Fri May 15 16:22:17 2015 [-7948] info: spamd: processing message <16b7fd09dc74241e08be71222ed21a01@mail.gmail.com> for (unknown):0
Fri May 15 16:22:21 2015 [-7948] info: spamd: clean message (-2.6/4.0) for (unknown):0 in 4.2 seconds, 90263 bytes.
Fri May 15 16:22:21 2015 [-7948] info: spamd: result: . -2 - BAYES_00,HTML_IMAGE_RATIO_06,HTML_MESSAGE,RCVD_IN_DNSWL_LOW,RCVD_IN_MSPIKE_H3,RCVD_IN_MSPIKE_WL scantime=4.2,size=90263,user=(unknown),uid=0,required_score=4.0,rhost=Jonkergouw-Informatisering,raddr=127.0.0.1,rport=57174,mid=<16b7fd09dc74241e08be71222ed21a01@mail.gmail.com>,bayes=0.000000,autolearn=no autolearn_force=no,shortcircuit=no
Fri May 15 16:22:21 2015 [2684] info: prefork: child states: II

Code: Select all

"SMTPD" 3376 30194 "2015-05-15 16:22:16.382" "209.85.214.178" "SENT: 220 jonkergouw.systemec.nl ESMTP"
"SMTPD" 3424 30194 "2015-05-15 16:22:16.507" "209.85.214.178" "RECEIVED: EHLO mail-ob0-f178.google.com"
"SMTPD" 3424 30194 "2015-05-15 16:22:16.507" "209.85.214.178" "SENT: 250-jonkergouw.systemec.nl[nl]250-SIZE 40960000[nl]250-AUTH LOGIN[nl]250 HELP"
"SMTPD" 3376 30194 "2015-05-15 16:22:16.632" "209.85.214.178" "RECEIVED: MAIL FROM:<***@***> SIZE=90103"
"SMTPD" 3376 30194 "2015-05-15 16:22:16.710" "209.85.214.178" "SENT: 250 OK"
"SMTPD" 3424 30194 "2015-05-15 16:22:16.835" "209.85.214.178" "RECEIVED: RCPT TO:<***@***>"
"SMTPD" 3424 30194 "2015-05-15 16:22:16.928" "209.85.214.178" "SENT: 250 OK"
"SMTPD" 3468 30194 "2015-05-15 16:22:17.053" "209.85.214.178" "RECEIVED: DATA"
"SMTPD" 3468 30194 "2015-05-15 16:22:17.053" "209.85.214.178" "SENT: 354 OK, send."
"SMTPD" 3192 30194 "2015-05-15 16:22:21.889" "209.85.214.178" "SENT: 250 Queued (4.768 seconds)"

"DEBUG" 3376 "2015-05-15 16:22:16.382" "TCP connection started for session 30194"
"DEBUG" 3376 "2015-05-15 16:22:16.647" "Spam test: SpamTestHeloHost, Score: 0"
"DEBUG" 3376 "2015-05-15 16:22:16.679" "Spam test: SpamTestMXRecords, Score: 0"
"DEBUG" 3376 "2015-05-15 16:22:16.710" "Spam test: SpamTestSPF, Score: 0"
"DEBUG" 3376 "2015-05-15 16:22:16.710" "Total spam score: 0"
"DEBUG" 3468 "2015-05-15 16:22:17.053" "Executing event OnSMTPData"
"DEBUG" 3468 "2015-05-15 16:22:17.053" "Event completed"
"DEBUG" 3472 "2015-05-15 16:22:17.490" "Adding task AsynchronousTask to work queue Asynchronous task queue"
"DEBUG" 3192 "2015-05-15 16:22:17.490" "Executing task AsynchronousTask in work queue Asynchronous task queue"
"DEBUG" 3192 "2015-05-15 16:22:17.505" "Spam test: SpamTestDKIM, Score: 0"
"DEBUG" 3192 "2015-05-15 16:22:17.505" "Creating session 30202"
"DEBUG" 3472 "2015-05-15 16:22:17.505" "TCP connection started for session 30202"
"DEBUG" 3472 "2015-05-15 16:22:17.505" "Sending message to SpamAssassin. Session 30202, File: E:\Email\Data\{96F91FA7-23F0-4B79-B245-DD44BA4CCE85}.eml"
"DEBUG" 3424 "2015-05-15 16:22:21.717" "Parsing response from SpamAssassin. Session 30202"
"DEBUG" 3424 "2015-05-15 16:22:21.811" "The read operation failed. Bytes transferred: 0 Remote IP: 127.0.0.1, Session: 30202, Code: 2, Message: End of file"
"DEBUG" 3424 "2015-05-15 16:22:21.811" "Ending session 30202"
"DEBUG" 3192 "2015-05-15 16:22:21.811" "Spam test: SpamTestSpamAssassin, Score: 0"
"DEBUG" 3192 "2015-05-15 16:22:21.811" "Total spam score: 0"
"DEBUG" 3192 "2015-05-15 16:22:21.811" "Saving message: {96F91FA7-23F0-4B79-B245-DD44BA4CCE85}.eml"

jimimaseye · Post by **jimimaseye** » 2015-05-15 17:14

Your LOG file you have posted stopped at

Code: Select all

"DEBUG" 3472 "2015-05-15 16:22:17.505" "Sending message to SpamAssassin. Session 30202, File: E:\Email\Data\{96F91FA7-23F0-4B79-B245-DD44BA4CCE85}.eml"

Where is the rest from 16:22:17 onwards?

RvdH · Post by **RvdH** » 2015-05-15 17:37

Don.t know what you mean, as you can see spamassassin took 4.2 seconds

"DEBUG" 3192 "2015-05-15 16:22:17.505" "Creating session 30202"
"DEBUG" 3472 "2015-05-15 16:22:17.505" "TCP connection started for session 30202"
"DEBUG" 3472 "2015-05-15 16:22:17.505" "Sending message to SpamAssassin. Session 30202, File: E:\Email\Data\{96F91FA7-23F0-4B79-B245-DD44BA4CCE85}.eml"
"DEBUG" 3424 "2015-05-15 16:22:21.717" "Parsing response from SpamAssassin. Session 30202"
"ERROR" 3424 "2015-05-15 16:22:21.795" "Severity: 3 (Medium), Code: HM5157, Source: SpamAssassinClient::OnReadError, Description: There was a communication error with SpamAssassin. hMailServer tried to retrieve data from SpamAssassin but the connection to SpamAssassin was lost. The WinSock error code is 2. Enable debug logging to retrieve more information regarding this problem. The problem could be that SpamAssassin is malfunctioning."
"DEBUG" 3424 "2015-05-15 16:22:21.811" "The read operation failed. Bytes transferred: 0 Remote IP: 127.0.0.1, Session: 30202, Code: 2, Message: End of file"
"DEBUG" 3424 "2015-05-15 16:22:21.811" "Ending session 30202"
"ERROR" 3192 "2015-05-15 16:22:21.811" "Severity: 2 (High), Code: HM5508, Source: SpamAssassinTestConnect::TestConnect, Description: The SpamAssassin tests did not complete. Please confirm that the configuration (host name and port) is valid and that SpamAssassin is running."

superman20 · Post by **superman20** » 2015-05-19 21:30

RvdH,
I, too, am having the exact same problem. I am a Windows programmer by profession and I have spent a few hours trying to debug this problem. Unfortunately, I haven't yet found a root cause and have not had time to pursue it further. I'm not certain whether it is on the hMailServer side or the SpamAssassin side. I have turned on full debugging on both sides. SpamAssassin shows no unusual activity during the time that hMailServer reports the error. In fact, SpamAssassin normally reports successful completion when hMailServer reports the error. I have been getting the error 0-3 times per day (usually 2 times per day) at random times each day. I am using JAM Software's free version and I always restart SpamAssassin every day using an automated script. I have tried all combinations of startup parameters for SpamAssassin and none of them seem to affect the error. I'm currently leaning toward some sort of lower level network error, but cannot say for sure.

If I ever get time, I'm thinking of writing a middle-man app to sit between hMailServer and SpamAssassin so I can have full diagnostic control (at the sockets layer) of the communication between the 2 in hopes of gaining a better understanding of the problem.

Sorry my post isn't actually helpful, but at least you are not alone. This error is annoying as it results in spam getting through every time it happens. I wish hMailServer had a SpamAssassin retry feature if there is a failure. In my experience, e-mail that comes in seconds after this error are processes correctly so it seems a retry from hMailServer's side would at least band-aid this problem.

jimimaseye · Post by **jimimaseye** » 2015-05-19 21:34

Superman, do you use 'roundrobin' for your spamd?

superman20 · Post by **superman20** » 2015-05-19 22:14

I do not use 'roundrobin'. I tried with and without it and I get the error either way.

jimimaseye · Post by **jimimaseye** » 2015-05-19 22:17

Thats that ruled out then. I hope you find the issue within your windows socket monitoring - I think thats where the error is myself.

superman20 · Post by **superman20** » 2015-05-19 22:27

RvdH,
I'd like to know what Operating System and Network Card and Driver you are using. Mine is on Windows Web Server 2008 R2, NVIDIA nForce Networking Controller, Windows Driver 1.0.1.211 dated 10/17/2008.

Thanks.

RvdH · Post by **RvdH** » 2015-05-20 13:34

OS: Windows Server 2012, on VMware vSphere Enterprise Cluster
NIC: vmxnet3 Ethernet Adapter
Driver version: VMware Inc. 28-8-2013

spamd.exe process is restarted every hour, i tried adjusting the Threading option under hmailserver perfomance settings increasing the 'Max number of asynchronous task threads' to 45 without noticeable success

Yesterday i had 4 more of these errors,

Code: Select all

"ERROR"	3456	"2015-05-19 07:27:46.468"	"Severity: 3 (Medium), Code: HM5157, Source: SpamAssassinClient::OnReadError, Description: There was a communication error with SpamAssassin. hMailServer tried to retrieve data from SpamAssassin but the connection to SpamAssassin was lost. The WinSock error code is 2. Enable debug logging to retrieve more information regarding this problem. The problem could be that SpamAssassin is malfunctioning."
"ERROR"	3192	"2015-05-19 07:27:46.531"	"Severity: 2 (High), Code: HM5508, Source: SpamAssassinTestConnect::TestConnect, Description: The SpamAssassin tests did not complete. Please confirm that the configuration (host name and port) is valid and that SpamAssassin is running."
"ERROR"	3464	"2015-05-19 09:50:07.837"	"Severity: 3 (Medium), Code: HM5157, Source: SpamAssassinClient::OnReadError, Description: There was a communication error with SpamAssassin. hMailServer tried to retrieve data from SpamAssassin but the connection to SpamAssassin was lost. The WinSock error code is 2. Enable debug logging to retrieve more information regarding this problem. The problem could be that SpamAssassin is malfunctioning."
"ERROR"	3168	"2015-05-19 09:50:07.852"	"Severity: 2 (High), Code: HM5508, Source: SpamAssassinTestConnect::TestConnect, Description: The SpamAssassin tests did not complete. Please confirm that the configuration (host name and port) is valid and that SpamAssassin is running."
"ERROR"	3416	"2015-05-19 21:53:35.350"	"Severity: 3 (Medium), Code: HM5157, Source: SpamAssassinClient::OnReadError, Description: There was a communication error with SpamAssassin. hMailServer tried to retrieve data from SpamAssassin but the connection to SpamAssassin was lost. The WinSock error code is 2. Enable debug logging to retrieve more information regarding this problem. The problem could be that SpamAssassin is malfunctioning."
"ERROR"	3152	"2015-05-19 21:53:35.397"	"Severity: 2 (High), Code: HM5508, Source: SpamAssassinTestConnect::TestConnect, Description: The SpamAssassin tests did not complete. Please confirm that the configuration (host name and port) is valid and that SpamAssassin is running."
"ERROR"	3484	"2015-05-19 22:39:37.386"	"Severity: 3 (Medium), Code: HM5157, Source: SpamAssassinClient::OnReadError, Description: There was a communication error with SpamAssassin. hMailServer tried to retrieve data from SpamAssassin but the connection to SpamAssassin was lost. The WinSock error code is 2. Enable debug logging to retrieve more information regarding this problem. The problem could be that SpamAssassin is malfunctioning."
"ERROR"	3152	"2015-05-19 22:39:37.386"	"Severity: 2 (High), Code: HM5508, Source: SpamAssassinTestConnect::TestConnect, Description: The SpamAssassin tests did not complete. Please confirm that the configuration (host name and port) is valid and that SpamAssassin is running."

today, until now just one

Code: Select all

"ERROR"	3392	"2015-05-20 10:40:10.331"	"Severity: 3 (Medium), Code: HM5157, Source: SpamAssassinClient::OnReadError, Description: There was a communication error with SpamAssassin. hMailServer tried to retrieve data from SpamAssassin but the connection to SpamAssassin was lost. The WinSock error code is 2. Enable debug logging to retrieve more information regarding this problem. The problem could be that SpamAssassin is malfunctioning."
"ERROR"	3152	"2015-05-20 10:40:10.331"	"Severity: 2 (High), Code: HM5508, Source: SpamAssassinTestConnect::TestConnect, Description: The SpamAssassin tests did not complete. Please confirm that the configuration (host name and port) is valid and that SpamAssassin is running."

superman20 · Post by **superman20** » 2015-05-20 14:53

I don't know if this is a clue, but I don't always get complete HM5157/HM5508 pairs. For example, I received 3.5 events yesterday. Notice the "half" event at 9:58. Also, just for information, hMailServer/SpamAssassin correctly processed spam immediately following some of these events at 08:21:29, 14:49:22 and 17:03:17.

Code: Select all

"ERROR"	3320	"2015-05-19 08:21:27.615"	"Severity: 3 (Medium), Code: HM5157, Source: SpamAssassinClient::OnReadError, Description: There was a communication error with SpamAssassin. hMailServer tried to retrieve data from SpamAssassin but the connection to SpamAssassin was lost. The WinSock error code is 2. Enable debug logging to retrieve more information regarding this problem. The problem could be that SpamAssassin is malfunctioning."
"ERROR"	1984	"2015-05-19 08:21:27.615"	"Severity: 2 (High), Code: HM5508, Source: SpamAssassinTestConnect::TestConnect, Description: The SpamAssassin tests did not complete. Please confirm that the configuration (host name and port) is valid and that SpamAssassin is running."
"ERROR"	876	"2015-05-19 09:58:10.630"	"Severity: 2 (High), Code: HM5508, Source: SpamAssassinTestConnect::TestConnect, Description: The SpamAssassin tests did not complete. Please confirm that the configuration (host name and port) is valid and that SpamAssassin is running."
"ERROR"	2148	"2015-05-19 14:49:18.834"	"Severity: 3 (Medium), Code: HM5157, Source: SpamAssassinClient::OnReadError, Description: There was a communication error with SpamAssassin. hMailServer tried to retrieve data from SpamAssassin but the connection to SpamAssassin was lost. The WinSock error code is 2. Enable debug logging to retrieve more information regarding this problem. The problem could be that SpamAssassin is malfunctioning."
"ERROR"	1984	"2015-05-19 14:49:18.834"	"Severity: 2 (High), Code: HM5508, Source: SpamAssassinTestConnect::TestConnect, Description: The SpamAssassin tests did not complete. Please confirm that the configuration (host name and port) is valid and that SpamAssassin is running."
"ERROR"	2968	"2015-05-19 17:03:11.787"	"Severity: 3 (Medium), Code: HM5157, Source: SpamAssassinClient::OnReadError, Description: There was a communication error with SpamAssassin. hMailServer tried to retrieve data from SpamAssassin but the connection to SpamAssassin was lost. The WinSock error code is 2. Enable debug logging to retrieve more information regarding this problem. The problem could be that SpamAssassin is malfunctioning."
"ERROR"	2288	"2015-05-19 17:03:11.787"	"Severity: 2 (High), Code: HM5508, Source: SpamAssassinTestConnect::TestConnect, Description: The SpamAssassin tests did not complete. Please confirm that the configuration (host name and port) is valid and that SpamAssassin is running."

jimimaseye · Post by **jimimaseye** » 2015-05-20 15:28

This isnt a new problem. It is something that does/has happened in the past to others. Even I and our other senior contributor have had similar (and I no longer have it).

Have a read ALL through this: viewtopic.php?f=7&t=27450 and in particular look for your HM5508 code - you might find something useful.

RvdH · Post by **RvdH** » 2015-05-20 15:54

superman20 wrote:I don't know if this is a clue, but I don't always get complete HM5157/HM5508 pairs. For example, I received 3.5 events yesterday. Notice the "half" event at 9:58. Also, just for information, hMailServer/SpamAssassin correctly processed spam immediately following some of these events at 08:21:29, 14:49:22 and 17:03:17.

I (until now) always get complete HM5157/HM5508 pairs... like yours spamd.exe seems to succesfully process messages after the event occured, eg:

Code: Select all

"ERROR"	3392	"2015-05-20 10:40:10.331"	"Severity: 3 (Medium), Code: HM5157, Source: SpamAssassinClient::OnReadError, Description: There was a communication error with SpamAssassin. hMailServer tried to retrieve data from SpamAssassin but the connection to SpamAssassin was lost. The WinSock error code is 2. Enable debug logging to retrieve more information regarding this problem. The problem could be that SpamAssassin is malfunctioning."
"ERROR"	3152	"2015-05-20 10:40:10.331"	"Severity: 2 (High), Code: HM5508, Source: SpamAssassinTestConnect::TestConnect, Description: The SpamAssassin tests did not complete. Please confirm that the configuration (host name and port) is valid and that SpamAssassin is running."

Wed May 20 10:40:08 2015 [-7908] info: spamd: connection from Jonkergouw-Informatisering [127.0.0.1]:53786 to port 783, fd 6
Wed May 20 10:40:08 2015 [-7908] info: spamd: processing message <121488-fe6489b3432f4e68b5058369d78ea6ec@mailing.eindhovenairport.nl> for (unknown):0
Wed May 20 10:40:10 2015 [-7908] info: spamd: clean message (-1.9/4.0) for (unknown):0 in 1.4 seconds, 34577 bytes.
Wed May 20 10:40:10 2015 [-7908] info: spamd: result: . -1 - BAYES_00,HTML_FONT_LOW_CONTRAST,HTML_IMAGE_RATIO_08,HTML_MESSAGE,RCVD_IN_DNSWL_NONE scantime=1.4,size=34577,user=(unknown),uid=0,required_score=4.0,rhost=Jonkergouw-Informatisering,raddr=127.0.0.1,rport=53786,mid=<121488-fe6489b3432f4e68b5058369d78ea6ec@mailing.eindhovenairport.nl>,bayes=0.000000,autolearn=no autolearn_force=no,shortcircuit=no
Wed May 20 10:40:10 2015 [6616] info: prefork: child states: II
Wed May 20 10:40:19 2015 [-7908] info: spamd: connection from Jonkergouw-Informatisering [127.0.0.1]:53794 to port 783, fd 6
Wed May 20 10:40:19 2015 [-7908] info: spamd: processing message <20150520_084044_008912.info@dar.globcit.com> for (unknown):0
Wed May 20 10:40:20 2015 [-7908] info: spamd: identified spam (50.5/4.0) for (unknown):0 in 1.7 seconds, 2021 bytes.
Wed May 20 10:40:20 2015 [-7908] info: spamd: result: Y 50 - BAYES_99,BAYES_999,CUSTOM_MANY_BL,CUSTOM_MANY_URIBL,HTML_MESSAGE,HTML_MIME_NO_HTML_TAG,JAM_POTENZ_BD,KAM_VERY_BLACK_DBL,MIME_HTML_ONLY,RAZOR2_CF_RANGE_51_100,RAZOR2_CF_RANGE_E8_51_100,RAZOR2_CHECK,RCVD_IN_ANONMAILS,RCVD_IN_BLKSRV,RCVD_IN_BRBL_LASTEXT,RCVD_IN_DNSBL_INPS_DE,RCVD_IN_HOSTKARMA_BL,RCVD_IN_HOSTKARMA_BR,RCVD_IN_JUSTSPAM,RCVD_IN_NIX_SPAM,RCVD_IN_PSBL,RCVD_IN_RP_RNBL,RCVD_IN_SBL_CSS,RCVD_IN_SORBS_SPAM,RCVD_IN_UCEPROTECT1,URIBL_BLACK,URIBL_DBL_SPAM,URIBL_JP_SURBL,URIBL_WS_SURBL,USER_IN_WHITELIST_TO scantime=1.7,size=2021,user=(unknown),uid=0,required_score=4.0,rhost=Jonkergouw-Informatisering,raddr=127.0.0.1,rport=53794,mid=<20150520_084044_008912.info@dar.globcit.com>,bayes=1.000000,autolearn=no autolearn_force=no,shortcircuit=no
Wed May 20 10:40:20 2015 [6616] info: prefork: child states: II
Wed May 20 10:41:19 2015 [-7908] info: spamd: connection from Jonkergouw-Informatisering [127.0.0.1]:53800 to port 783, fd 6
Wed May 20 10:41:19 2015 [-7908] info: spamd: processing message <WM!dabfac50797a2b0cebe6210e18c42c73e0fdd4860037f28c81c55cd2026177850ad5b8c5d3e5f7bb0f4958a97ecbb150!@relay1.virclean.nl> for (unknown):0
Wed May 20 10:41:20 2015 [-7908] info: spamd: clean message (-1.1/4.0) for (unknown):0 in 1.2 seconds, 398392 bytes.
Wed May 20 10:41:20 2015 [-7908] info: spamd: result: . -1 - BAYES_00,HTML_MESSAGE,PDF_ATTACHED,RCVD_IN_DNSWL_NONE scantime=1.2,size=398392,user=(unknown),uid=0,required_score=4.0,rhost=Jonkergouw-Informatisering,raddr=127.0.0.1,rport=53800,mid=<WM!dabfac50797a2b0cebe6210e18c42c73e0fdd4860037f28c81c55cd2026177850ad5b8c5d3e5f7bb0f4958a97ecbb150!@relay1.virclean.nl>,bayes=0.000000,autolearn=no autolearn_force=no,shortcircuit=no
Wed May 20 10:41:20 2015 [6616] info: prefork: child states: II

A DNS problem looks out of the question as the failing event in SpamAssassin only took 1.4 seconds to process

superman20 · Post by **superman20** » 2015-05-20 16:38

My results are very similar to RvdH. Also, I have been having this problem from day 1 (about 6 months now as I recently switch to hMailServer from Alt-N products) and I have also been running my own local caching DNS server from day 1 (as I hate all shared DNS servers). Also, according to my statistics for the last 30 days, 98% of scanned e-mail takes less than 2 seconds. My overall average scan time is 1.7 seconds with a peak of 17 seconds. With the 4 errors I had yesterday, the scan times were all very fast (0.9, 0.7, 0.9, 0.8 seconds). So, it doesn't seem to be a DNS or scan time issue. Just for information, my server is acting solely as a gateway for 4 domains and processes roughly 1,000 emails per day of which only 200-300 are non-spam.

Matt2k · Post by **Matt2k** » 2015-06-28 20:51

I get 10-30 of these a day. Spamd.log reports a successful analysis well under 30 seconds. hMailServer says the connection was broken and lets the email pass through. Most scan times only take a couple seconds.

hMailServer needs a retry feature for un-analyzed emails, please

JAM's software restarts every 60 minutes which causes a similar problem, but these are not happening on those intervals. (I also increased JAM's restart interval to 300 minutes)

Thank you

binkle · Post by **binkle** » 2015-12-30 13:50

Hi,
the restarts of SpamAssassin are usually set to be done every 60 minutes.
Additionally the restart is skipped if spamd has a CPU usage > 1%.
Further more the spamd shutdown triggered for such an restart is no process killing, it's sending the shutdown signal to spamd, which results in a regular spamd shutdown, nothing is foced to be killed.
This prevents any kind of aborting running scans and other issues like such an socket error.

However, I've never heard of a "Socket error 2". The smallest windows socket error code is "6" (See: https://msdn.microsoft.com/de-de/librar ... s.85).aspx)
and common windows socket error codes are all greater than 1000.

Do you have any antivirus or other software running which may interfere with the SpamAssassin TCP connections?

Greetings,
Harald

jimimaseye · Post by **jimimaseye** » 2015-12-30 14:29

I rarely get them, but get them I do. As it happens, just this very morning it happened:
HMS log:

Code: Select all

"ERROR"	2100	"2015-12-30 05:57:35.981"	"Severity: 3 (Medium), Code: HM5157, Source: SpamAssassinClient::OnReadError, Description: There was a communication error with SpamAssassin. hMailServer tried to retrieve data from SpamAssassin but the connection to SpamAssassin was lost. The WinSock error code is 2. Enable debug logging to retrieve more information regarding this problem. The problem could be that SpamAssassin is malfunctioning."

"ERROR"	4008	"2015-12-30 05:57:36.215"	"Severity: 2 (High), Code: HM5508, Source: SpamAssassinTestConnect::TestConnect, Description: The SpamAssassin tests did not complete. Please confirm that the configuration (host name and port) is valid and that SpamAssassin is running."

And that is on the same Server running both HMS and Spamassassin and it is without any other activity happening. It was processing a single email message that arrived (and happened to be a high scoring spam message - coincidence?):

Spamd log:

Code: Select all

Wed Dec 30 05:57:34 2015 [-5092] info: spamd: connection from Mailserver [127.0.0.1]:54480 to port 783, fd 6
Wed Dec 30 05:57:34 2015 [-5092] info: spamd: processing message <cmu-lmtpd-17324-1451454992-1@ms7.hostvue.com> for (unknown):0
Wed Dec 30 05:57:35 2015 [-5092] info: spamd: identified spam (16.5/3.0) for (unknown):0 in 1.5 seconds, 2370 bytes.
Wed Dec 30 05:57:35 2015 [-5092] info: spamd: result: Y 16 - BAYES_95,BODY_URI_ONLY,DSN_NO_MIMEVERSION,FSL_HELO_BARE_IP_2,RCVD_HELO_IP_MISMATCH,RCVD_IN_BRBL_LASTEXT,RCVD_IN_MSPIKE_BL,RCVD_IN_MSPIKE_L5,RCVD_IN_PBL,RCVD_IN_XBL,RCVD_NUMERIC_HELO,RDNS_NONE scantime=1.5,size=2370,user=(unknown),uid=0,required_score=3.0,rhost=Mailserver,raddr=127.0.0.1,rport=54480,mid=<cmu-lmtpd-17324-1451454992-1@ms7.hostvue.com>,bayes=0.983823,autolearn=no autolearn_force=no

Now it does remain a mystery to me why it happens (albeit rarely) when the majority of the time it doesnt (even when busy). Obviously 'hMailserver' is claiming that Spamassassin is the culprit, but from what Harald has said there is an implication that it cant be that (and maybe it is Windows or Hmailserver). Given this, will we ever get to conclude the cause? Hmmmm.....

binkle · Post by **binkle** » 2015-12-30 14:40

Have you ever tried to

Enable debug logging to retrieve more information regarding this problem.

Does that give more details?
The most confusing thing about this error message is that socket error code of "2".

Is there any hMailServer developer active in this thread who may say more about that error message?

jimimaseye · Post by **jimimaseye** » 2015-12-30 14:48

Personally I will not enable DEBUG to try and catch this as it happens too rarely - with DEBUG enabled the log files become extortionately large with no clear benefit to a 'functioning' system and could be just clogging things up for weeks or months on the rare off chance this error happens.

As for the developer active in this forum? Erm........

binkle · Post by **binkle** » 2015-12-30 14:52

hm.. you answered before I edited

Digging a bit in the code of hMailServer shows that the error code is provided as comming from boost::system::error_code.
So the error code actually is no socket error, it's the windows system error 2: no_such_file_or_directory (see: http://stackoverflow.com/questions/2978 ... e-number-2)

For sure, this has noting to do with SpamAssassin. It must be an hMailServer internal issue.

binkle · Post by **binkle** » 2015-12-30 14:55

As for the developer active in this forum? Erm........

Sorry

jimimaseye · Post by **jimimaseye** » 2015-12-30 14:57

Thanks for the information Harald. So we are now looking at a windows error that is a result of "The system cannot find the file specified." So we have now moved on to the question.....WHAT file cannot be found and WHY?

jimimaseye · Post by **jimimaseye** » 2015-12-30 15:05

Sorry, I have just looked back in this thread. One poster (RvDH viewtopic.php?p=175696#p175696) did actually post the logs with DEBUG enabled. Im afraid it doesnt give us any more information other than is seems to not receive back the file it sent:

Code: Select all

"DEBUG" 3192 "2015-05-15 16:22:17.505" "Creating session 30202"
"DEBUG" 3472 "2015-05-15 16:22:17.505" "TCP connection started for session 30202"
"DEBUG" 3472 "2015-05-15 16:22:17.505" "Sending message to SpamAssassin. Session 30202, File: E:\Email\Data\{96F91FA7-23F0-4B79-B245-DD44BA4CCE85}.eml"
"DEBUG" 3424 "2015-05-15 16:22:21.717" "Parsing response from SpamAssassin. Session 30202"
"ERROR" 3424 "2015-05-15 16:22:21.795" "Severity: 3 (Medium), Code: HM5157, Source: SpamAssassinClient::OnReadError, Description: There was a communication error with SpamAssassin. hMailServer tried to retrieve data from SpamAssassin but the connection to SpamAssassin was lost. The WinSock error code is 2. Enable debug logging to retrieve more information regarding this problem. The problem could be that SpamAssassin is malfunctioning."
"DEBUG" 3424 "2015-05-15 16:22:21.811" "The read operation failed. Bytes transferred: 0 Remote IP: 127.0.0.1, Session: 30202, Code: 2, Message: End of file"

binkle · Post by **binkle** » 2015-12-30 15:29

I'm not very familiar with C++ code, so please correct me if I'm wrong:
SpamAssassinClient.cpp#L147

Code: Select all

      // Append output to the file
      size_t written_bytes = 0;
         result_->Write(pBuf, written_bytes);

Doesn't this ensure the file should exist in any case?
So why can accessing this temp file cause "no_such_file_or_directory"

RvdH · Post by **RvdH** » 2015-12-30 16:34

Unfortunatly only martin can tell i guess...C++ is not my 'thing' either

Occasionly i also get a 'WinSock error code is 10054' as well, but this only seems te be triggered if hmailserver passes a message to spamassassin on the exact same time spamassassin is being restarted.

@harald
I have written my own custom SpamAssassin Restart service in C#, like yours it restarts only if spamd.exe process is consuming 0% CPU but I also count the ammount of active connections on port 783, and only restart the service if there are no connections on port 783, it delays restarting as long CPU is higher > 0 or connections on port 783 is > 0

The above addition reduced the '10054' winSock errors dramaticly

mattg · Post by **mattg** » 2015-12-30 16:50

Perhaps the temp file is removed by Antivirus software??

binkle · Post by **binkle** » 2015-12-30 16:54

count the amount of active connections on port 783

this is really nice idea.
I put it on the list for being implemented for SpamAssassin in a Box.
Thanks!

jimimaseye · Post by **jimimaseye** » 2015-12-30 16:57

Perhaps the temp file is removed by Antivirus software??

Not on my system. Clamav wasn't any good at detecting and removing things that I knew should have been detected and removed and anyway I don't have it doing such actions.

RvdH · Post by **RvdH** » 2015-12-30 17:26

mattg wrote:Perhaps the temp file is removed by Antivirus software??

Nope, if you read back the topic, especially where i had debug enabled you notice the file is delivered and passed trough SpamAssassin correctly and within time

mattg · Post by **mattg** » 2015-12-30 17:50

What has spamassassin checking got to do with Antivirus software installed on your machine, that may have scanned the temp folder and removed this item as it was written?

Do you have Antivirus software installed on this machine? Has the ./hmailserver/temp folder been excluded from scanning?

I'm just looking for possible reasons why a temp file may not be found...

jimimaseye · Post by **jimimaseye** » 2015-12-30 17:55

jimimaseye wrote:
Perhaps the temp file is removed by Antivirus software??
Not on my system. Clamav wasn't any good at detecting and removing things that I knew should have been detected and removed and anyway I don't have it doing such actions.

In other words...I do not have any realtime AV protection running so there isnt any AV software to remove the file. And the box doesnt have any other purpose or do anything else other than HMS and SA (.....especially at 5:50am!)

RvdH · Post by **RvdH** » 2015-12-30 17:58

Back then i do not think i had any antivirus installed.

Meanwhile i installed (free) Avast for Business as virusscanner but i don't do anything with avast when a virus is found, eg: /P=4 flag so hmailserver itself can handle this. both ./Temp and ./Data directories are excluded

RvdH · Post by **RvdH** » 2015-12-30 18:04

mattg wrote:What has spamassassin checking got to do with Antivirus software installed on your machine, that may have scanned the temp folder and removed this item as it was written?

Do you have Antivirus software installed on this machine? Has the ./hmailserver/temp folder been excluded from scanning?

I'm just looking for possible reasons why a temp file may not be found...

Maybe i misunderstood you, but i was referring to it being delivered to the client eventually... If a virusscanner removed the tempfile wouldn't this mean it wouldn't be delivered to client as well?

mattg · Post by **mattg** » 2015-12-30 19:21

I was thinking that hMailserver made a temp file of the SA report, and added that to the original message.

I really don't know, just putting forward some ideas.

I've only had SA for a couple of weeks, but I too have a couple of these errors

Code: Select all

"ERROR"	4780	"2015-12-22 10:18:13.168"	"Severity: 3 (Medium), Code: HM5157, Source: SpamAssassinClient::OnReadError, Description: There was a communication error with SpamAssassin. hMailServer tried to retrieve data from SpamAssassin but the connection to SpamAssassin was lost. The WinSock error code is 2. Enable debug logging to retrieve more information regarding this problem. The problem could be that SpamAssassin is malfunctioning."
"ERROR"	5028	"2015-12-22 10:18:13.170"	"Severity: 2 (High), Code: HM5508, Source: SpamAssassinTestConnect::TestConnect, Description: The SpamAssassin tests did not complete. Please confirm that the configuration (host name and port) is valid and that SpamAssassin is running."

and

Code: Select all

"ERROR"	4788	"2015-12-28 03:07:31.790"	"Severity: 3 (Medium), Code: HM5157, Source: SpamAssassinClient::OnReadError, Description: There was a communication error with SpamAssassin. hMailServer tried to retrieve data from SpamAssassin but the connection to SpamAssassin was lost. The WinSock error code is 2. Enable debug logging to retrieve more information regarding this problem. The problem could be that SpamAssassin is malfunctioning."
"ERROR"	5028	"2015-12-28 03:07:31.790"	"Severity: 2 (High), Code: HM5508, Source: SpamAssassinTestConnect::TestConnect, Description: The SpamAssassin tests did not complete. Please confirm that the configuration (host name and port) is valid and that SpamAssassin is running."

In more detail

Code: Select all

"TCPIP"	5028	"2015-12-28 03:07:24.989"	"Connecting to 192.168.0.198:783..."
"DEBUG"	4784	"2015-12-28 03:07:24.989"	"TCP connection started for session 9245"
"DEBUG"	4784	"2015-12-28 03:07:24.989"	"Sending message to SpamAssassin. Session 9245, File: C:\hMailServer\Data\{5CEDD516-0B5C-4FB5-9D70-C93FC08F8AFD}.eml"
"DEBUG"	4788	"2015-12-28 03:07:28.197"	"Creating session 9246"
"TCPIP"	4788	"2015-12-28 03:07:28.197"	"TCP - 193.226.85.187 connected to 192.168.0.199:25."
"DEBUG"	4788	"2015-12-28 03:07:28.197"	"TCP connection started for session 9244"
"SMTPD"	4788	9244	"2015-12-28 03:07:28.197"	"193.226.85.187"	"SENT: 220 mx.mydomain.com.au ESMTP"
"SMTPD"	4784	9244	"2015-12-28 03:07:28.583"	"193.226.85.187"	"RECEIVED: EHLO OtherDomain.com"
"SMTPD"	4784	9244	"2015-12-28 03:07:28.583"	"193.226.85.187"	"SENT: 250-mx.mydomain.com.au[nl]250-SIZE[nl]250-STARTTLS[nl]250-AUTH LOGIN[nl]250 HELP"
"SMTPD"	4816	9244	"2015-12-28 03:07:28.952"	"193.226.85.187"	"RECEIVED: MAIL From:<user@OtherDomain.com>"
"TCPIP"	4816	"2015-12-28 03:07:29.169"	"DNS lookup: 187.85.226.193.bl.spamcop.net, 0 addresses found: (none), Match: False"
"TCPIP"	4816	"2015-12-28 03:07:29.216"	"DNS lookup: 187.85.226.193.zen.spamhaus.org, 1 addresses found: 127.0.0.4, Match: True"
"DEBUG"	4816	"2015-12-28 03:07:29.216"	"Spam test: SpamTestDNSBlackLists, Score: 3"
"DEBUG"	4816	"2015-12-28 03:07:29.955"	"Spam test: SpamTestHeloHost, Score: 0"
"DEBUG"	4816	"2015-12-28 03:07:30.688"	"Spam test: SpamTestMXRecords, Score: 0"
"DEBUG"	4788	"2015-12-28 03:07:31.790"	"Parsing response from SpamAssassin. Session 9245"
"ERROR"	4788	"2015-12-28 03:07:31.790"	"Severity: 3 (Medium), Code: HM5157, Source: SpamAssassinClient::OnReadError, Description: There was a communication error with SpamAssassin. hMailServer tried to retrieve data from SpamAssassin but the connection to SpamAssassin was lost. The WinSock error code is 2. Enable debug logging to retrieve more information regarding this problem. The problem could be that SpamAssassin is malfunctioning."
"DEBUG"	4788	"2015-12-28 03:07:31.790"	"Executing event OnError"
"DEBUG"	4788	"2015-12-28 03:07:31.790"	"Event completed"
"DEBUG"	4788	"2015-12-28 03:07:31.790"	"The read operation failed. Bytes transferred: 0 Remote IP: 192.168.0.198, Session: 9245, Code: 2, Message: End of file"
"DEBUG"	4788	"2015-12-28 03:07:31.790"	"Ending session 9245"
"ERROR"	5028	"2015-12-28 03:07:31.790"	"Severity: 2 (High), Code: HM5508, Source: SpamAssassinTestConnect::TestConnect, Description: The SpamAssassin tests did not complete. Please confirm that the configuration (host name and port) is valid and that SpamAssassin is running."
"DEBUG"	5028	"2015-12-28 03:07:31.790"	"Executing event OnError"
"DEBUG"	5028	"2015-12-28 03:07:31.790"	"Event completed"
"DEBUG"	5028	"2015-12-28 03:07:31.790"	"Spam test: SpamTestSpamAssassin, Score: 0"
"DEBUG"	5028	"2015-12-28 03:07:31.790"	"Total spam score: 0"
"DEBUG"	5028	"2015-12-28 03:07:31.790"	"Executing event OnAcceptMessage"
"DEBUG"	5028	"2015-12-28 03:07:31.806"	"Event completed"
"DEBUG"	5028	"2015-12-28 03:07:31.806"	"Saving message: {5CEDD516-0B5C-4FB5-9D70-C93FC08F8AFD}.eml"

I've since increased the SA Timeout values in the hMailserver.ini Settings

jimimaseye · Post by **jimimaseye** » 2015-12-30 19:36

mattg wrote: I've only had SA for a couple of weeks, but I too have a couple of these errors

So soon. I have had only 3 in the whole of 2015. And only 1 in 2014 (since upgrading from 5.3.3 - prior to then quite a few more). Is it worth comparing various environmental settings?

RvdH · Post by **RvdH** » 2015-12-31 02:07

I have approx 3 a 4 a day, yes for real....on my home server running hmailserver I rarely notice issues like this, but on a production server +400 clients, 5000 mails each day i see this behavior and faults (too) much

jimimaseye · Post by **jimimaseye** » 2015-12-31 09:04

I cant help thinking its a windows operating system issue and the fault lies with MS. My initial thought would have been about it hitting some limit (you have 400+ clients/5000 emails) but that cant be the case because I have 10 clients and in this period nearly zero emails and still it happened yesterday. So what else? I think we really need Martin to consider and review HMS and its role in this as Harald has already reviewed his software and ruled out Spamassassin as the cause.

mattg · Post by **mattg** » 2016-01-01 00:45

jimimaseye wrote:... as Harald has already reviewed his software and ruled out Spamassassin as the cause.

It certainly isn't the fault of JAM's spamassassin implentation. I don't use that.
I use a Ubuntu Server VM with SpamAssassin and ClamAV loaded on them.

jimimaseye · Post by **jimimaseye** » 2016-01-17 18:59

Just had another one. In this example it is definitely a case of it erroring when receiving a message qualifying for high spam score:

Error is at 15:40:

17/01/2016 15:40:11
Severity: 3 (Medium)
Code: HM5157
Source: SpamAssassinClient::OnReadError
Description: There was a communication error with SpamAssassin. hMailServer tried to retrieve data from SpamAssassin but the connection to SpamAssassin was lost. The WinSock error code is 2. Enable debug logging to retrieve more information regarding this problem. The problem could be that SpamAssassin is malfunctioning.

A message in at 15:40 has the headers:

Return-Path: abasing@shamakova.ru
X-hMailServer-ExternalAccount: POPdaily
Return-Path: <>
.
.
.
Received: from unknown (HELO localhost) (abasing@shamakova.ru@166.178.62.105) by 58.126.122.200
with ESMTPA; Mon, 18 Jan 2016 00:43:19 +0900
X-Originating-IP: 166.178.62.105
From: abasing@shamakova.ru
To: user@mydomain.com
Subject: Inflame your impulse to maximum
Date: Mon, 18 Jan 2016 00:31:03 +0900
Message-ID: <cmu-lmtpd-17949-1453045169-1@ms7.hostvue.com>

and SPAMD.log shows:

Sun Jan 17 15:40:10 2016 [-2224] info: spamd: connection from Mailserver [127.0.0.1]:61917 to port 783, fd 6
Sun Jan 17 15:40:10 2016 [-2224] info: spamd: processing message <cmu-lmtpd-17949-1453045169-1@ms7.hostvue.com> for (unknown):0
Sun Jan 17 15:40:11 2016 [-2224] info: spamd: identified spam (26.2/3.0) for (unknown):0 in 0.9 seconds, 2426 bytes.
Sun Jan 17 15:40:11 2016 [-2224] info: spamd: result: Y 26 - BAYES_95,BODY_URI_ONLY,DSN_NO_MIMEVERSION,FSL_HELO_BARE_IP_2,RAZOR2_CF_RANGE_51_100,RAZOR2_CF_RANGE_E8_51_100,RAZOR2_CHECK,RCVD_IN_BRBL_LASTEXT,RCVD_IN_MSPIKE_BL,RCVD_IN_MSPIKE_L5,RCVD_IN_PBL,RCVD_IN_XBL,RCVD_NUMERIC_HELO,RCVD_VIA_APNIC,RDNS_NONE,URIBL_BLACK,URIBL_DBL_SPAM,URIBL_JP_SURBL,URIBL_SBL,URIBL_SBL_A,URIBL_WS_SURBL scantime=0.9,size=2426,user=(unknown),uid=0,required_score=3.0,rhost=Decroserver,raddr=127.0.0.1,rport=61917,mid=<cmu-lmtpd-17949-1453045169-1@ms7.hostvue.com>,bayes=0.964608,autolearn=spam autolearn_force=no

So the MessageID (bold highlight) shows this is the correct message in error. And the Spamd log shows that Spamassassin received and evaluated the message successfully. In fact it was that exact SECOND (15:40:11) that spamd finished and HMS then errored (suggesting not even a timeout with any credible threshold was exceeded).

Brings us back to the error being with HMS or maybe the OS killing the socket connection for some reason. But as Binkle has said above it doesnt look like it is Spamassassin and so the error message suggesting so is definitely misleading.

Tell you what though, look at the message header above: it has an emtpy RETURN-PATH. Hmmmm.....

(Thankfully for me, my email gets scanned twice by spamassassin - it already has my host email providers SA scan results (although they are on 3.3.1 and dont have my customised rules). So even if my own SA scoring fails (like above) the message still has SA headers in it that my rules can work off.)

Post by **martin** » 2016-01-18 08:27

I'll see if I can somehow reproduce this issue. Maybe it's related to message size?

jimimaseye · Post by **jimimaseye** » 2016-01-18 10:05

martin wrote:I'll see if I can somehow reproduce this issue. Maybe it's related to message size?

I dont think it is. Its not true you have implied its LARGE emails that cause the problem but the email I quoted previously above is tiny. Here is the message source as collected and parsed to SA (there is nothing unique about this):

--- Start of complete message source ----

Code: Select all

Return-Path: abasing@shamakova.ru
X-hMailServer-ExternalAccount: POPdaily
Return-Path: <>
Received: from mailin3.hostvue.com (mailin3.hostvue.com [196.26.30.111]) (authenticated
 user=user@mydomain.com bits=0) by ms7.hostvue.com (Cyrus v2.4.16-Kolab-2.4.16-1.el6)
 with LMTPSA (version=TLSv1/SSLv3 cipher=DHE-RSA-AES256-GCM-SHA384 bits=256/256
 verify=YES); Sun, 17 Jan 2016 15:39:29 +0000
X-Sieve: CMU Sieve 2.4
X-Spam-Checker-Version: SpamAssassin 3.3.1 (2010-03-16) on mailin7.hostvue.com
X-Spam-Flag: YES
X-Spam-Level: ********************
X-Spam-Status: Yes, score=20.9 required=3.0 tests=BAYES_99,BAYES_999, BODY_URI_ONLY,FSL_HELO_BARE_IP_2,MISSING_MID,RCVD_IN_BRBL_LASTEXT,RCVD_IN_PBL,
 RCVD_IN_XBL,RCVD_NUMERIC_HELO,RDNS_NONE,URIBL_DBL_SPAM,URIBL_SBL
 autolearn=spam version=3.3.1
X-Spam-Report: 
 *  6.1 BAYES_99 BODY: Bayes spam probability is 99 to 100%
 *      [score: 1.0000]
 *  2.0 RCVD_NUMERIC_HELO Received: contains an IP address used for HELO
 *  3.3 RCVD_IN_PBL RBL: Received via a relay in Spamhaus PBL
 *      [58.126.122.200 listed in zen.spamhaus.org]
 *  0.4 RCVD_IN_XBL RBL: Received via a relay in Spamhaus XBL
 *  1.4 RCVD_IN_BRBL_LASTEXT RBL: RCVD_IN_BRBL_LASTEXT
 *      [58.126.122.200 listed in bb.barracudacentral.org]
 *  2.5 URIBL_DBL_SPAMContains a spam URL listed in the DBL blocklist
 *      [URIs: tjdcvixx.ru]
 *  0.2 BAYES_999 BODY: Bayes spam probability is 99.9 to 100%
 *      [score: 1.0000]
 *  1.6 URIBL_SBL Contains an URL's NS IP listed in the SBL blocklist
 *      [URIs: tjdcvixx.ru] *  0.5 MISSING_MID Missing Message-Id: header
 *  0.8 RDNS_NONE Delivered to internal network by a host with no rDNS
 *  1.6 FSL_HELO_BARE_IP_2 FSL_HELO_BARE_IP_2
 *  0.4 BODY_URI_ONLY Message body is only a URI in one line of text or for
 *      an image
Received: from [58.126.122.200] (helo=58.126.122.200) by mailin3.hostvue.com with smtp
 (Exim 4.85) id 1aKpQO-0005uX-BK for user@mydomain.com; Sun, 17 Jan 2016
 15:39:29 +0000
Received: from unknown (HELO localhost) (abasing@shamakova.ru@166.178.62.105) by 58.126.122.200
 with ESMTPA; Mon, 18 Jan 2016 00:43:19 +0900
X-Originating-IP: 166.178.62.105
From: abasing@shamakova.ru
To: user@mydomain.com
Subject: Inflame your impulse to maximum
Date: Mon, 18 Jan 2016 00:31:03 +0900
Message-ID: <cmu-lmtpd-17949-1453045169-1@ms7.hostvue.com>

Show your power to your partner http://comedown.tjdcvixx.ru/

--- End of complete message source ----

RvdH · Post by **RvdH** » 2016-01-28 01:44

"ERROR" 3632 "2016-01-26 13:21:06.005" "Severity: 3 (Medium), Code: HM5157, Source: SpamAssassinClient::OnReadError, Description: There was a communication error with SpamAssassin. hMailServer tried to retrieve data from SpamAssassin but the connection to SpamAssassin was lost. The WinSock error code is 2. Enable debug logging to retrieve more information regarding this problem. The problem could be that SpamAssassin is malfunctioning."
"ERROR" 3196 "2016-01-26 13:21:06.021" "Severity: 2 (High), Code: HM5508, Source: SpamAssassinTestConnect::TestConnect, Description: The SpamAssassin tests did not complete. Please confirm that the configuration (host name and port) is valid and that SpamAssassin is running."
"ERROR" 3644 "2016-01-26 14:21:41.707" "Severity: 3 (Medium), Code: HM5157, Source: SpamAssassinClient::OnReadError, Description: There was a communication error with SpamAssassin. hMailServer tried to retrieve data from SpamAssassin but the connection to SpamAssassin was lost. The WinSock error code is 3. Enable debug logging to retrieve more information regarding this problem. The problem could be that SpamAssassin is malfunctioning."
"ERROR" 3192 "2016-01-26 14:21:41.707" "Severity: 2 (High), Code: HM5508, Source: SpamAssassinTestConnect::TestConnect, Description: The SpamAssassin tests did not complete. Please confirm that the configuration (host name and port) is valid and that SpamAssassin is running."
"ERROR" 3612 "2016-01-26 16:40:53.017" "Severity: 3 (Medium), Code: HM5157, Source: SpamAssassinClient::OnReadError, Description: There was a communication error with SpamAssassin. hMailServer tried to retrieve data from SpamAssassin but the connection to SpamAssassin was lost. The WinSock error code is 2. Enable debug logging to retrieve more information regarding this problem. The problem could be that SpamAssassin is malfunctioning."
"ERROR" 3196 "2016-01-26 16:40:53.095" "Severity: 2 (High), Code: HM5508, Source: SpamAssassinTestConnect::TestConnect, Description: The SpamAssassin tests did not complete. Please confirm that the configuration (host name and port) is valid and that SpamAssassin is running."

Another variant just popped up in yesterdays log, The WinSock error code is 3 ???

Code: Select all

Tue Jan 26 13:21:00 2016 [-8776] info: spamd: connection from MyMailServer [127.0.0.1]:51175 to port 783, fd 6
Tue Jan 26 13:21:00 2016 [-8776] info: spamd: processing message <4566311.36761.1453810859833.JavaMail.mailbot@m7.mailplus.nl> for (unknown):0
Tue Jan 26 13:21:06 2016 [-8776] info: spamd: clean message (-3.9/4.0) for (unknown):0 in 5.3 seconds, 87912 bytes.
Tue Jan 26 13:21:06 2016 [-8776] info: spamd: result: . -3 - BAYES_00,DKIM_SIGNED,DKIM_VALID,HTML_MESSAGE,LOCAL_INFOUSMEBIZ,RCVD_IN_DNSWL_NONE,RCVD_IN_HOSTKARMA_W,RCVD_IN_MSPIKE_H4,RCVD_IN_MSPIKE_WL,SPF_HELO_PASS scantime=5.3,size=87912,user=(unknown),uid=0,required_score=4.0,rhost=MyMailServer,raddr=127.0.0.1,rport=51175,mid=<4566311.36761.1453810859833.JavaMail.mailbot@m7.mailplus.nl>,bayes=0.000000,autolearn=no autolearn_force=no,shortcircuit=no
Tue Jan 26 13:21:06 2016 [7424] info: prefork: child states: II

Tue Jan 26 14:21:40 2016 [-9120] info: spamd: connection from MyMailServer [127.0.0.1]:51932 to port 783, fd 6
Tue Jan 26 14:21:40 2016 [-9120] info: spamd: processing message <38BCB789-E37F-47BF-A8D2-66A6266AC77D@MyMailServer> for (unknown):0
Tue Jan 26 14:21:41 2016 [-9120] info: spamd: identified spam (19.7/4.0) for (unknown):0 in 1.1 seconds, 523982 bytes.
Tue Jan 26 14:21:41 2016 [-9120] info: spamd: result: Y 19 - BAYES_50,CUSTOM_MANY_BL,HTML_FONT_LOW_CONTRAST,HTML_MESSAGE,HTML_OFF_PAGE,MIME_HTML_ONLY,MISSING_MIMEOLE,RCVD_IN_BRBL_LASTEXT,RCVD_IN_DNSBL_INPS_DE,RCVD_IN_JUSTSPAM,RCVD_IN_XBL,SPF_HELO_FAIL,T_KAM_HTML_FONT_INVALID,T_REMOTE_IMAGE,XPRIO,ZIP_ATTACHED scantime=1.1,size=523982,user=(unknown),uid=0,required_score=4.0,rhost=MyMailServer,raddr=127.0.0.1,rport=51932,mid=<38BCB789-E37F-47BF-A8D2-66A6266AC77D@jonkergouw.systemec.nl>,bayes=0.499809,autolearn=no autolearn_force=no,shortcircuit=no
Tue Jan 26 14:21:41 2016 [1348] info: prefork: child states: II

Tue Jan 26 16:40:48 2016 [-8800] info: spamd: connection from MyMailServer [127.0.0.1]:51462 to port 783, fd 6
Tue Jan 26 16:40:48 2016 [-8800] info: spamd: processing message <01d1584f$Blat.v2.7.6$e95997b0$783452a26978@mandrillapp.com> for (unknown):0
Tue Jan 26 16:40:53 2016 [-8800] info: spamd: clean message (-2.8/4.0) for (unknown):0 in 4.4 seconds, 53679 bytes.
Tue Jan 26 16:40:53 2016 [-8800] info: spamd: result: . -2 - BAYES_00,DKIM_SIGNED,DKIM_VALID,DKIM_VALID_AU,HIDE_WIN_STATUS,HTML_FONT_LOW_CONTRAST,HTML_MESSAGE,RCVD_IN_DNSWL_NONE,RCVD_IN_IADB_DK,RCVD_IN_IADB_LISTED,RCVD_IN_IADB_RDNS,RCVD_IN_IADB_SENDERID,RCVD_IN_IADB_SPF,RCVD_IN_IADB_VOUCHED,SPF_HELO_PASS,URIBL_GREY scantime=4.4,size=53679,user=(unknown),uid=0,required_score=4.0,rhost=MyMailServer,raddr=127.0.0.1,rport=51462,mid=<01d1584f$Blat.v2.7.6$e95997b0$783452a26978@mandrillapp.com>,bayes=0.000000,autolearn=no autolearn_force=no,shortcircuit=no
Tue Jan 26 16:40:53 2016 [7840] info: prefork: child states: II

Dravion · Post by **Dravion** » 2016-01-28 05:45

Try this command on a elevated command propmpt

netsh int ip reset

Restart Windows and report back.

Post by **martin** » 2016-01-30 19:56

I dont think it is. Its not true you have implied its LARGE emails that cause the problem but the email I quoted previously above is tiny.

When I wrote that maybe it's related to size, I didn't mean it was related to the message being large, but some other property related to the size. For example, hMailServer sends X bytes at a time to SpamAssassin, and maybe the issue occurs if the message size is evenly dividable by X (just as an example).

If anyone here got an .eml file where the issue is reproducible, i would appreciate if you would zip it up and send it to me at martin@hmailserver.com.

RvdH · Post by **RvdH** » 2016-01-31 15:48

martin wrote:
I dont think it is. Its not true you have implied its LARGE emails that cause the problem but the email I quoted previously above is tiny.
When I wrote that maybe it's related to size, I didn't mean it was related to the message being large, but some other property related to the size. For example, hMailServer sends X bytes at a time to SpamAssassin, and maybe the issue occurs if the message size is evenly dividable by X (just as an example).

If anyone here got an .eml file where the issue is reproducible, i would appreciate if you would zip it up and send it to me at martin@hmailserver.com.

I don't have the original messages, only the spam messages listed but these include the hmailserver / client added (Avast) headers

superman20 · Post by **superman20** » 2016-03-25 05:47

I finally got some time to investigate this problem more. First, I've always assumed this was a SpamAssassin problem and so I upgraded to the current Jam Software version (based on Strawberry Perl) hoping that things would be different. They are not. I still get 1 - 3 of these errors every day at random times. So, I wrote a "proxy" program to site between hMailServer and SpamAssassin. This would allow me to have full TCP control of information between the two. I just captured one of these errors and what I see in my proxy program is that SpamAssassin correctly processes the mail and sends a properly formatted message back. My proxy program sends the full response to hMailServer with complete success. No errors or warnings. Note that my program uses the Windows Winsock API directly (no wrappers of any kind) and I check every function called for errors. The proxy program sees the whole process complete successfully but hMailServer still reports Error 2. After digging through hMailServer's source for a limited amount of time, I see it uses the boost library for asynchronous IO. Error code 2 is the boost EOF (End Of File) error. Unfortunately, I'm not a boost user and I'm not familiar with it. My limited research finds this in the boost docs (http://www.boost.org/doc/libs/1_60_0/do ... reams.html) which says:

The end of a stream can cause read, async_read, read_until or async_read_until functions to violate their contract. E.g. a read of N bytes may finish early due to EOF.

I'm not entirely sure how to interpret that. I know I send complete information to hMailServer (and I also immediately do a "graceful" close with shutdown(SD_SEND), just like SpamAssassin does, after sending). Perhaps boost is not returning the full socket buffer because it processes the close too quickly? Perhaps one could still read more data from the buffer even after a close is seen? Also, I see discussions in boost forums hinting that the EOF shouldn't be treated as a hard error (but there seems to be a great deal of confusion about this).
Unfortunately, I can't tell if there is a bug in hMailServer's code because I don't know the nuances of asynchronous IO with boost. Hopefully this information will be helpful to the developer and we can figure out how to address the issue.

Dravion · Post by **Dravion** » 2016-03-25 12:50

Good research.
Yeah, sometimes its a burden if you fall for a Framework like Boost because Errors can be nested and Operating System Errors can be truncated, reformatted or replaced by nonsense error codes and/or messages. Thats why in general i try to avoid layers and frameworks if possible. Debugging the insane OpenSSL errors can be a Nightmare to.

superman20 · Post by **superman20** » 2016-04-12 14:52

Sorry for the delayed update, but I've been really busy at work. I have discovered through my proxy program that I, too, occasionally get the socket close notification (or EOF as Boost calls it) BEFORE I have read all the information on the socket. In these circumstances, I can continue reading information from the socket after receiving the close notification (or EOF). So, I'm starting to believe that hMailServer does indeed have a bug. I think it should attempt to read more information from the socket after it receives the close notification if it hasn't read all the information it is expecting. If there is indeed nothing left on the socket, Winsock will return a successful read of zero bytes. To somewhat test this theory (without modifying and compiling hMailServer myself), I have changed my proxy program to delay sending any close notifications until 5 seconds after I receive them. I am hoping this will prevent hMailServer from seeing a close event (EOF) before it has had a chance to read all of the data on the socket. I have been running this way for 24 hours now and so far hMailServer has not had an Error 2 episodes. I will report back in a few more days, but know that I have never had a 24 hour period without an Error 2 since I started hMailServer over a year ago.

jimimaseye · Post by **jimimaseye** » 2016-05-02 12:07

https://github.com/hmailserver/hmailserver/issues/167

sckramer2 · Post by **sckramer2** » 2016-06-09 15:55

Code: Select all

"ERROR"	2628	"2016-06-09 08:56:35.935"	"Severity: 2 (High), Code: HM5508, Source: SpamAssassinTestConnect::TestConnect, Description: The SpamAssassin tests did not complete. Please confirm that the configuration (host name and port) is valid and that SpamAssassin is running."

Code: Select all

Thu Jun  9 08:56:33 2016 [-3980] info: spamd: connection from ANAKIN [127.0.0.1]:58522 to port 783, fd 7
Thu Jun  9 08:56:33 2016 [-3980] info: spamd: processing message <196970706093125-9f339ccc1d8891594b052d468c1b5255scott@cds.com> for (unknown):0
Thu Jun  9 08:56:35 2016 [-3980] info: spamd: identified spam (6.2/3.0) for (unknown):0 in 2.2 seconds, 6474 bytes.
Thu Jun  9 08:56:35 2016 [-3980] info: spamd: result: Y 6 - BAYES_99,BAYES_999,JAM_DO_STH_HERE,JAM_PHARMACY_BD,KAM_ASCII_DIVIDERS,RDNS_NONE scantime=2.2,size=6474,user=(unknown),uid=0,required_score=3.0,rhost=ANAKIN,raddr=127.0.0.1,rport=58522,mid=<196970706093125-9f339ccc1d8891594b052d468c1b5255scott@cds.com>,bayes=1.000000,autolearn=no autolearn_force=no
Thu Jun  9 08:56:36 2016 [2452] info: prefork: child states: II

Code: Select all

X-Spam-Checker-Version: SpamAssassin 3.4.1 (2015-04-28) on ANAKIN
X-Spam-Flag: YES
X-Spam-Level: ******
X-Spam-Status: Yes, score=6.9 required=3.0 tests=AWL,BAYES_99,BAYES_999,
        JAM_DO_STH_HERE,JAM_PHARMACY_BD,KAM_ASCII_DIVIDERS,KAM_LAZY_DOMAIN_SECURITY,
        RDNS_NONE autolearn=no autolearn_force=no version=3.4.1
X-Spam-Report:
        *  3.5 BAYES_99 BODY: Bayes spam probability is 99 to 100%
        *      [score: 1.0000]
        *  0.5 JAM_DO_STH_HERE BODY: Body contains Click/Order/Press... Here
        *  0.1 JAM_PHARMACY_BD BODY: Body contains pharmacy, medication etc
        *  0.5 BAYES_999 BODY: Bayes spam probability is 99.9 to 100%
        *      [score: 1.0000]
        *  0.8 KAM_ASCII_DIVIDERS Spam that uses ascii formatting tricks
        *  0.8 RDNS_NONE Delivered to internal network by a host with no rDNS
        *  1.0 KAM_LAZY_DOMAIN_SECURITY Sending domain does not have any
        *      anti-forgery methods
        * -0.3 AWL AWL: Adjusted score from AWL reputation of From: address
X-Spam-Bayes: bayes=1.0000,N=590(497-10+129),ham=(repeat, lab, respiratory,
        superb, enjoys),spam=(H*p:D*top, figure, blood, cooking, Good)

Anything new on this? I've tried many things in the last year or 3 there's always a few ridiculous spams a day that make it through because of this... re-scanned this .eml & it was an easy positive that scanned in a few seconds.

SorenR · Post by **SorenR** » 2016-06-09 16:31

sckramer2 wrote:
Code: Select all
X-Spam-Checker-Version: SpamAssassin 3.4.1 (2015-04-28) on ANAKIN

And you are certain it's not due to the fact that ANAKIN join the Dark Side and become DARTH VADER later in life ??

jimimaseye · Post by **jimimaseye** » 2016-06-09 17:17

This winsock error code 2 is still under review. There are hopes for remedy in 5.7. Meanwhile it woukd seem that it is the specific environment that makes it worse for some than others. I only have it three or four times a year.

sckramer2 · Post by **sckramer2** » 2016-06-09 18:04

Ugh, not getting windsock error-- We'll need the force to finally fix this!

Anyone try a workaround... i.e. scripting a retry? Thanks!