Hi,
We are experiencing issue with our SME Server.
Version installed: 7.5.1
All updates installed
Basically, some morning (not everyday - but always in the morning between 10H30 to 12H00), we have problems sending outgoing message.
Outlook client keep email seating in the Outbox, and Thunderbird is timing out - cannot communicate in time with our SMTP server.
We can ping the server and receive incoming emails.
When this happens lasttime, I did connect via ssh and checked the qpsmtpd log file "in live". I could see a lot of strange messages like the following once:
2011-12-21 11:05:24.540492500 4581 Too many connections: 40 >= 40. Waiting one second.
2011-12-21 11:05:25.543264500 4581 Too many connections: 40 >= 40. Waiting one second.
2011-12-21 11:05:26.546045500 4581 Too many connections: 40 >= 40. Waiting one second.
2011-12-21 11:05:27.547838500 4581 Too many connections: 40 >= 40. Waiting one second.
2011-12-21 11:05:28.549638500 4581 Too many connections: 40 >= 40. Waiting one second.
2011-12-21 11:05:29.551553500 4581 Too many connections: 40 >= 40. Waiting one second.
2011-12-21 11:05:30.553251500 4581 Too many connections: 40 >= 40. Waiting one second.
2011-12-21 11:05:31.555046500 4581 Too many connections: 40 >= 40. Waiting one second.
2011-12-21 11:05:32.103031500 20709 Connection Timed Out
2011-12-21 11:05:32.556879500 4581 cleaning
I have also checked other log file at the same time, and I have found the following messages:
In spamd log file: => error: FuzzyOcr:
What is this ?
2011-12-21 11:04:36.444509500 Dec 21 11:04:36.444 [6582] warn: plugin: eval failed: bayes: (in learn) locker: safe_lock: cannot create lockfile /var/spool/spamd/.spamassassin/bayes.mutex: Permission denied
2011-12-21 11:04:36.451102500 Dec 21 11:04:36.451 [6582] info: spamd: identified spam (26.4/2.0) for qpsmtpd:1005 in 15.2 seconds, 3929 bytes.
2011-12-21 11:04:36.452270500 Dec 21 11:04:36.452 [6582] info: spamd: result: Y 26 - DKIM_ADSP_CUSTOM_MED,FORGED_YAHOO_RCVD,FREEMAIL_FROM,JM_SOUGHT_2,LONGWORDS,NML_ADSP_CUSTOM_MED,RAZOR2_CF_RANGE_51_100,RAZOR2_CF_RANGE_E8_51_100,RAZOR2_CHECK,RCVD_IN_BRBL_LASTEXT,RCVD_IN_PBL,RCVD_IN_SORBS_WEB,RCVD_IN_XBL,RDNS_NONE,URIBL_DBL_SPAM,URIBL_JP_SURBL,URIBL_SBL,URIBL_SC_SURBL,URIBL_WS_SURBL scantime=15.2,size=3929,user=qpsmtpd,uid=1005,required_score=2.0,rhost=localhost,raddr=127.0.0.1,rport=33757,mid=<20111221105541.9482.qmail@www.jtmmd.com>,autolearn=unavailable
2011-12-21 11:04:38.366522500 Dec 21 11:04:38.365 [4862] info: prefork: child states: BBBBB
2011-12-21 11:04:38.366529500 Dec 21 11:04:38.365 [4862] info: prefork: server reached --max-children setting, consider raising it
2011-12-21 11:04:38.369926500 Dec 21 11:04:38.370 [6582] info: spamd: connection from localhost [127.0.0.1] at port 33758
2011-12-21 11:04:38.386595500 Dec 21 11:04:38.386 [6582] info: spamd: checking message <1147339406.46877.1324464940422.JavaMail.root@tptrwd10s> for qpsmtpd:1005
2011-12-21 11:04:49.506023500 Dec 21 11:04:49.501 [6582] info: pyzor: [21058] error: TERMINATED, signal 15 (000f)
2011-12-21 11:04:49.547764500 Dec 21 11:04:49.547 [6582] warn: plugin: eval failed: bayes: (in learn) locker: safe_lock: cannot create lockfile /var/spool/spamd/.spamassassin/bayes.mutex: Permission denied
2011-12-21 11:04:49.554112500 Dec 21 11:04:49.553 [6582] info: spamd: clean message (-2.6/2.0) for qpsmtpd:1005 in 11.2 seconds, 1531 bytes.
2011-12-21 11:04:49.555180500 Dec 21 11:04:49.555 [6582] info: spamd: result: . -2 - RP_MATCHES_RCVD,SPF_PASS scantime=11.2,size=1531,user=qpsmtpd,uid=1005,required_score=2.0,rhost=localhost,raddr=127.0.0.1,rport=33758,mid=<1147339406.46877.1324464940422.JavaMail.root@tptrwd10s>,autolearn=unavailable
2011-12-21 11:04:51.134912500 Dec 21 11:04:51.133 [4862] info: prefork: child states: BBBBB
2011-12-21 11:04:51.134919500 Dec 21 11:04:51.134 [4862] info: prefork: server reached --max-children setting, consider raising it
2011-12-21 11:04:51.138808500 Dec 21 11:04:51.138 [6582] info: spamd: connection from localhost [127.0.0.1] at port 33759
2011-12-21 11:04:51.707932500 Dec 21 11:04:51.708 [6582] info: spamd: checking message <0.0.2FD.AA5.1CCBFCF144E886C.0@mta29.pur3.net> for qpsmtpd:1005
2011-12-21 11:04:59.008531500 Dec 21 11:04:59.008 [6582] warn: Exception: incomplete data at /usr/lib/perl5/vendor_perl/5.8.5/i386-linux-thread-multi/Net/DNS/RR.pm line 600, <GEN409> line 280.
2011-12-21 11:04:59.008887500 Dec 21 11:04:59.009 [6582] warn: caught at /usr/lib/perl5/vendor_perl/5.8.5/Mail/SpamAssassin/DnsResolver.pm line 457
2011-12-21 11:04:59.213258500 Dec 21 11:04:59.213 [6582] warn: Exception: incomplete data at /usr/lib/perl5/vendor_perl/5.8.5/i386-linux-thread-multi/Net/DNS/RR.pm line 600, <GEN409> line 280.
2011-12-21 11:04:59.213603500 Dec 21 11:04:59.213 [6582] warn: caught at /usr/lib/perl5/vendor_perl/5.8.5/Mail/SpamAssassin/DnsResolver.pm line 457
2011-12-21 11:06:11.682803500 Dec 21 11:06:11.682 [6582] info: pyzor: [21309] error: TERMINATED, signal 15 (000f)
2011-12-21 11:06:11.719487500 Dec 21 11:06:11.719 [6582] info: spamd: identified spam (2.3/2.0) for qpsmtpd:1005 in 80.6 seconds, 23632 bytes.
2011-12-21 11:06:11.720655500 Dec 21 11:06:11.720 [6582] info: spamd: result: Y 2 - DKIM_SIGNED,DKIM_VALID,HTML_IMAGE_RATIO_06,HTML_MESSAGE,MONEY_BACK,RP_MATCHES_RCVD,URI_NO_WWW_BIZ_CGI scantime=80.6,size=23632,user=qpsmtpd,uid=1005,required_score=2.0,rhost=localhost,raddr=127.0.0.1,rport=33759,mid=<0.0.2FD.AA5.1CCBFCF144E886C.0@mta29.pur3.net>,autolearn=no
2011-12-21 11:06:13.741224500 Dec 21 11:06:13.740 [4862] info: prefork: child states: BBBBB
2011-12-21 11:06:13.741231500 Dec 21 11:06:13.740 [4862] info: prefork: server reached --max-children setting, consider raising it
2011-12-21 11:06:13.744675500 Dec 21 11:06:13.744 [6582] info: spamd: connection from localhost [127.0.0.1] at port 33763
2011-12-21 11:06:13.781735500 Dec 21 11:06:13.781 [6582] info: spamd: checking message <urn.correios.msg.20111221105541f8ebaa4212c54c02b0732cd0d63c3de3@1324464942949.rte-svc-eu-1c-i-c69c82b0.eu-west-1.amazon.com> for qpsmtpd:1005
2011-12-21 11:06:32.538692500 Dec 21 11:06:32.535 [6582] info: pyzor: [21358] error: TERMINATED, signal 15 (000f)
2011-12-21 11:06:32.611236500 Dec 21 11:06:32.611 [6582] warn: plugin: eval failed: bayes: (in learn) locker: safe_lock: cannot create lockfile /var/spool/spamd/.spamassassin/bayes.mutex: Permission denied
2011-12-21 11:06:32.616699500 Dec 21 11:06:32.616 [6582] info: spamd: clean message (-9.8/2.0) for qpsmtpd:1005 in 18.9 seconds, 15716 bytes.
2011-12-21 11:06:32.617775500 Dec 21 11:06:32.617 [6582] info: spamd: result: . -9 - DKIM_SIGNED,DKIM_VALID,DKIM_VALID_AU,HTML_MESSAGE,RP_MATCHES_RCVD,SINGLE_HEADER_1K,SPF_PASS,T_FRT_CONTACT,T_REMOTE_IMAGE,USER_IN_DEF_SPF_WL scantime=18.9,size=15716,user=qpsmtpd,uid=1005,required_score=2.0,rhost=localhost,raddr=127.0.0.1,rport=33763,mid=<urn.correios.msg.20111221105541f8ebaa4212c54c02b0732cd0d63c3de3@1324464942949.rte-svc-eu-1c-i-c69c82b0.eu-west-1.amazon.com>,autolearn=unavailable
2011-12-21 11:06:35.133546500 Dec 21 11:06:35.132 [4862] info: prefork: child states: BBBBB
2011-12-21 11:06:35.133553500 Dec 21 11:06:35.132 [4862] info: prefork: server reached --max-children setting, consider raising it
2011-12-21 11:06:35.137443500 Dec 21 11:06:35.137 [6582] info: spamd: connection from localhost [127.0.0.1] at port 33772
2011-12-21 11:06:37.308391500 Dec 21 11:06:37.308 [6582] info: spamd: checking message <30D795F4FE085F48BC69BF0C058971C2C21F55@LHRDMX01.Signet-Intl.local> for qpsmtpd:1005
2011-12-21 11:07:18.457639500 Dec 21 11:07:18.454 [7690] info: pyzor: [21429] error: TERMINATED, signal 15 (000f)
2011-12-21 11:07:18.542973500 Dec 21 11:07:18.543 [7690] error: FuzzyOcr: Error running preprocessor(ppmtopgm): /usr/bin/ppmtopgm
2011-12-21 11:07:18.544038500 Dec 21 11:07:18.544 [7690] warn: FuzzyOcr: Errors in Scanset "ocrad-decolorize-invert"
2011-12-21 11:07:18.544568500 Dec 21 11:07:18.544 [7690] warn: FuzzyOcr: Return code: 2048, Error: save_execute: Insecure dependency in exec while running with -T switch at /usr/lib/perl5/site_perl/5.8.5/Mail/SpamAssassin/Plugin/FuzzyOcr/Misc.pm line 172.
2011-12-21 11:07:18.545000500 Dec 21 11:07:18.545 [7690] warn: FuzzyOcr: save_execute: Insecure dependency in exec while running with -T switch at /usr/lib/perl5/site_perl/5.8.5/Mail/SpamAssassin/Plugin/FuzzyOcr/Misc.pm line 172.
2011-12-21 11:07:18.545430500 Dec 21 11:07:18.545 [7690] warn: FuzzyOcr: Skipping scanset because of errors, trying next...
2011-12-21 11:07:18.995462500 Dec 21 11:07:18.995 [7690] error: FuzzyOcr: Error running preprocessor(ppmtopgm): /usr/bin/ppmtopgm
2011-12-21 11:07:18.996511500 Dec 21 11:07:18.996 [7690] warn: FuzzyOcr: Errors in Scanset "ocrad-decolorize"
2011-12-21 11:07:18.997193500 Dec 21 11:07:18.997 [7690] warn: FuzzyOcr: Return code: 2048, Error: save_execute: Insecure dependency in exec while running with -T switch at /usr/lib/perl5/site_perl/5.8.5/Mail/SpamAssassin/Plugin/FuzzyOcr/Misc.pm line 172.
2011-12-21 11:07:18.997625500 Dec 21 11:07:18.997 [7690] warn: FuzzyOcr: save_execute: Insecure dependency in exec while running with -T switch at /usr/lib/perl5/site_perl/5.8.5/Mail/SpamAssassin/Plugin/FuzzyOcr/Misc.pm line 172.
2011-12-21 11:07:18.998060500 Dec 21 11:07:18.998 [7690] warn: FuzzyOcr: Skipping scanset because of errors, trying next...
During this period were we cannot send emails - some of them managed to go out - the server is very busy - CPU > 90 %, even 100 %.
Can someone suggest something ?
Thanks.
2 Replies
1915 Views