"Connection to Spamassassin was lost" errors

[katip]

I come across to unscanned messages (spams), not frequently but 1-3 times a day. otherwise SA is working perfectly.
recent occurrence:

HMS tells:

Code: Select all

"ERROR"	1800	"2017-05-03 15:26:41.494"	"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"	2692	"2017-05-03 15:26:41.494"	"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 spamd tells (HMS is ~1 sec behind, so this should be the concurrent moment and some suspicious entries 10 secs before) :

Code: Select all

Wed May  3 15:26:31 2017 [3832] info: prefork: child states: III
Wed May  3 15:26:31 2017 [3832] info: prefork: adjust: 3 idle children more than 2 maximum idle children. Decreasing spamd children: -1496 killed.
Wed May  3 15:26:31 2017 [-1496] info: spamd: child got SIGINT, exiting
Wed May  3 15:26:33 2017 [3832] info: spamd: handled cleanup of child pid [-1496]: exit 0
(...some usual connection and processing entries..)
Wed May  3 15:26:42 2017 [3832] info: prefork: child states: BB
Wed May  3 15:26:42 2017 [3832] info: spamd: server successfully spawned child process, pid -3304
Wed May  3 15:26:42 2017 [3832] info: prefork: adjust: 0 idle children less than 1 minimum idle children. Increasing spamd children: -3304 started.
Wed May  3 15:26:42 2017 [3832] info: prefork: child states: BBI
(...goes on with usual connection and processing entries..)

HMS and SA/ClamAV are on seperate VMs in same Hyper-V box. so, any physical connection failure is out of possibility.
debugging is a pain. this is a busy production server.

thanks for any advise (tweak suggestions?) without debugging option first - if possible.

[jimimaseye]

Known problem. Reported and discussed many times. No answer or solution yet. Even Jam (of SA For Windows) have been involved and concluded its HMS. Hopefully there are attempts to address it in 5.7. Detailed info: viewtopic.php?t=28227 ("Binkle" is from Jam).

Youll just have to ignore it.

[SorenR]

Code: Select all

Wed May  3 15:26:31 2017 [3832] info: prefork: child states: III
Wed May  3 15:26:31 2017 [3832] info: prefork: adjust: 3 idle children more than 2 maximum idle children. Decreasing spamd children: -1496 killed.
Wed May  3 15:26:31 2017 [-1496] info: spamd: child got SIGINT, exiting
Wed May  3 15:26:33 2017 [3832] info: spamd: handled cleanup of child pid [-1496]: exit 0
(...some usual connection and processing entries..)
Wed May  3 15:26:42 2017 [3832] info: prefork: child states: BB
Wed May  3 15:26:42 2017 [3832] info: spamd: server successfully spawned child process, pid -3304
Wed May  3 15:26:42 2017 [3832] info: prefork: adjust: 0 idle children less than 1 minimum idle children. Increasing spamd children: -3304 started.
Wed May  3 15:26:42 2017 [3832] info: prefork: child states: BBI
(...goes on with usual connection and processing entries..)

You removed the interesting bits... There are no errors in the above log, only housekeeping.

Any of them lines looking anything like...

Code: Select all

Tue Feb  7 06:31:41 2017 [-3992] info: spamd: connection from datacenter.acme.inc [127.0.0.1]:3059 to port 783, fd 6
Tue Feb  7 06:31:41 2017 [-3992] info: spamd: processing message <OF3D9D98A7.C308F75C-ONC12580C0.001E5564@cfp.dk> for (unknown):0
Tue Feb  7 06:39:32 2017 [-3992] info: spamd: clean message (-2.6/3.0) for (unknown):0 in 470.6 seconds, 712208 bytes.
Tue Feb  7 06:39:32 2017 [-3992] info: spamd: result: . -2 - BAYES_00,RCVD_IN_DNSWL_LOW,RCVD_IN_MSPIKE_H3,TIME_LIMIT_EXCEEDED,T_OBFU_PDF_ATTACH scantime=470.6,size=712208,user=(unknown),uid=0,required_score=3.0,rhost=datacenter.acme.inc,raddr=127.0.0.1,rport=3059,mid=<OF3D9D98A7.C308F75C-ONC12580C0.001E5564@cfp.dk>,bayes=0.000000,autolearn=unavailable

I get the error if it takes too long to process... For some unknown reason my timeout limits are giving me the finger

[jimimaseye]

Any of them lines looking anything like...

Code: Select all

Tue Feb  7 06:31:41 2017 [-3992] info: spamd: connection from datacenter.acme.inc [127.0.0.1]:3059 to port 783, fd 6
Tue Feb  7 06:31:41 2017 [-3992] info: spamd: processing message <OF3D9D98A7.C308F75C-ONC12580C0.001E5564@cfp.dk> for (unknown):0
Tue Feb  7 06:39:32 2017 [-3992] info: spamd: clean message (-2.6/3.0) for (unknown):0 in 470.6 seconds, 712208 bytes.
Tue Feb  7 06:39:32 2017 [-3992] info: spamd: result: . -2 - BAYES_00,RCVD_IN_DNSWL_LOW,RCVD_IN_MSPIKE_H3,TIME_LIMIT_EXCEEDED,T_OBFU_PDF_ATTACH scantime=470.6,size=712208,user=(unknown),uid=0,required_score=3.0,rhost=datacenter.acme.inc,raddr=127.0.0.1,rport=3059,mid=<OF3D9D98A7.C308F75C-ONC12580C0.001E5564@cfp.dk>,bayes=0.000000,autolearn=unavailable

I get the error if it takes too long to process... For some unknown reason my timeout limits are giving me the finger

This doesnt apply to me. Most recent example:

Error:

"ERROR" 2800 "2017-04-27 12:11:18.721" "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" 1856 "2017-04-27 12:11:18.909" "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."

SPAMD:
[quote]Thu Apr 27 12:11:16 2017 [-3192] info: spamd: connection from mailserver [127.0.0.1]:64411 to port 783, fd 6
Thu Apr 27 12:11:16 2017 [-3192] info: spamd: processing message <F639F648-BB65-4099-8454-3E8A741B4206@reflekt-events.net> for (unknown):0
Thu Apr 27 12:11:18 2017 [-3192] info: spamd: clean message (-2.1/3.0) for (unknown):0 in 1.9 seconds, 27358 bytes.
Thu Apr 27 12:11:18 2017 [-3192] info: spamd: result: . -2 - BAYES_00,DKIM_SIGNED,DKIM_VALID,HTML_MESSAGE,RCVD_IN_DNSWL_NONE,RCVD_IN_HOSTKARMA_YE,RCVD_IN_MSPIKE_H2,RCVD_IN_SORBS_SPAM,SUBJ_ALL_CAPS,URG_BIZ scantime=1.9,size=27358,user=(unknown),uid=0,required_score=3.0,rhost=mailserver,raddr=127.0.0.1,rport=64411,mid=<F639F648-BB65-4099-8454-3E8A741B4206@reflekt-events.net>,bayes=0.000000,autolearn=no autolearn_force=no,shortcircuit=no
Thu Apr 27 12:11:20 2017 [-3700] info: spamd: connection from mailserver [127.0.0.1]:64415 to port 783, fd 6
Thu Apr 27 12:11:20 2017 [-3700] info: spamd: processing message <84d0db4eb3f84b3c96075694a5f74efe@DH1MX001.beaulieu.local> for (unknown):0
Thu Apr 27 12:11:21 2017 [-3700] info: spamd: clean message (-3.0/3.0) for (unknown):0 in 0.9 seconds, 141275 bytes.
Thu Apr 27 12:11:21 2017 [-3700] info: spamd: result: . -2 - BAYES_00,FROM_WORDY_SHORT,HTML_MESSAGE,MIME_HTML_ONLY,RCVD_IN_DNSWL_NONE,RCVD_IN_HOSTKARMA_YE,RCVD_IN_MSPIKE_H2,SPF_PASS,T_OBFU_PDF_ATTACH scantime=0.9,size=141275,user=(unknown),uid=0,required_score=3.0,rhost=mailserver,raddr=127.0.0.1,rport=64415,mid=<84d0db4eb3f84b3c96075694a5f74efe@DH1MX001.beaulieu.local>,bayes=0.000000,autolearn=ham autolearn_force=no,shortcircuit=no[/quote]

Scan times completed in less than 2 seconds. (Similar to other random quick checks of other previous errors Ive just done to be sure)

[mattg]

Just checked my logs

Since 1 April, I've had 10 single occurrences of this, none so far this month, only ever one per day at most.
( I use SpamAssassin on a virtual Ubuntu on my network).

Interestingly most are just a few minutes after midnight, or a few minutes after midday. Don't know the relevance of that, I have no scripts that particularly ran at these times.

I have these settings in my hMailserver.ini

Code: Select all

SAMinTimeout=180
; 30 seconds is default

SAMaxTimeout=280
; 90 seconds is default

I've just updated them to 240 /360

[katip]

I get the error if it takes too long to process... For some unknown reason my timeout limits are giving me the finger

hmm, i checked all log of yesterday. average time is 4,1 secs, max. 21,7 secs, anyways below than default min. (30 secs).

viewtopic.php?t=28227 , yes, interesting reading. let's keep waiting for HMS 5.7.
thanks.