2

I have a Postfix, Postgrey, Spamassassin, amavisd-new, dovecot setup.

When I send an e-mail through the system, the log file goes completely nuts.

I can't find any info to explain what the log lines mean, so I'm not sure what the best thing is to post here. It looks like it's going back to some information from when I installed the servers 6 months ago and providing log lines for enormous numbers of messages that were previously processed.

This is leading to huge log files (my mail.log.1 was switched this morning and is 331 Gb.) mail.log is currently up to 34 Gb.

Here is a sample of the lines that are being logged. There are thousands of lines like this with the date after "spamfilter:" incrementing until it reaches the current date.

Apr  2 10:31:26 oss2 spamfilter: Sat Oct 15 13:11:34 2016 [2758] info: spamd: connection from ip6-localhost [::1]:54602 to port 783, fd 5
Apr  2 10:31:26 oss2 spamfilter: Sat Oct 15 13:11:34 2016 [2758] info: spamd: processing message (unknown) for spamd:5001
Apr  2 10:31:26 oss2 spamfilter: Sat Oct 15 13:11:36 2016 [2758] info: spamd: clean message (2.8/5.0) for spamd:5001 in 2.2 seconds, 52500 bytes.
Apr  2 10:31:26 oss2 spamfilter: Sat Oct 15 13:11:36 2016 [2758] info: spamd: result: . 2 - BAYES_00,DKIM_SIGNED,DKIM_VALID,DKIM_VALID_AU,HTML_MESSAGE,MISSING_MID,NORMAL_HTTP_TO_IP,NO_RECEIVED,NO_RELAYS,RAZOR2_CF_RANGE_51_100,RAZOR2_CF_RANGE_E8_51_100,RAZOR2_CHECK,URIBL_BLOCKED,URI_DQ_UNSUB scantime=2.2,size=52500,user=spamd,uid=5001,required_score=5.0,rhost=ip6-localhost,raddr=::1,rport=54602,mid=(unknown),bayes=0.000000,autolearn=no autolearn_force=no
Apr  2 10:31:26 oss2 spamfilter: Sat Oct 15 13:11:36 2016 [2756] info: prefork: child states: II
Apr  2 10:31:26 oss2 spamfilter: Sat Oct 15 13:16:39 2016 [2758] info: spamd: connection from ip6-localhost [::1]:54668 to port 783, fd 5
Apr  2 10:31:26 oss2 spamfilter: Sat Oct 15 13:16:39 2016 [2758] info: spamd: processing message <0.0.4C.42D.1D226E3EE36EFD0.0@smtp9.valisetour.com> for spamd:5001
Apr  2 10:31:26 oss2 spamfilter: Sat Oct 15 13:16:41 2016 [2758] info: spamd: clean message (-1.8/5.0) for spamd:5001 in 1.8 seconds, 11325 bytes.
Apr  2 10:31:26 oss2 spamfilter: Sat Oct 15 13:16:41 2016 [2758] info: spamd: result: . -1 - BAYES_00,DKIM_SIGNED,DKIM_VALID,DKIM_VALID_AU,HTML_MESSAGE,NO_RECEIVED,NO_RELAYS,PP_MIME_FAKE_ASCII_TEXT,URIBL_BLOCKED scantime=1.8,size=11325,user=spamd,uid=5001,required_score=5.0,rhost=ip6-localhost,raddr=::1,rport=54668,mid=<0.0.4C.42D.1D226E3EE36EFD0.0@smtp9.valisetour.com>,bayes=0.000000,autolearn=no autolearn_force=no
Apr  2 10:31:26 oss2 spamfilter: Sat Oct 15 13:16:41 2016 [2756] info: prefork: child states: II
Apr  2 10:31:26 oss2 spamfilter: Sat Oct 15 13:17:12 2016 [2758] info: spamd: connection from ip6-localhost [::1]:54698 to port 783, fd 5
Apr  2 10:31:26 oss2 spamfilter: Sat Oct 15 13:17:12 2016 [2758] info: spamd: processing message <0.0.61.22E.1D226E4025142E0.0@smtp9.valisetour.com> for spamd:5001
Apr  2 10:31:26 oss2 spamfilter: Sat Oct 15 13:17:12 2016 [2759] info: spamd: connection from ip6-localhost [::1]:54700 to port 783, fd 5
Apr  2 10:31:26 oss2 spamfilter: Sat Oct 15 13:17:12 2016 [2759] info: spamd: processing message <0.0.61.22E.1D226E4025142E0.0@smtp9.valisetour.com> for spamd:5001
Apr  2 10:31:26 oss2 spamfilter: Sat Oct 15 13:17:14 2016 [2758] info: spamd: clean message (-1.8/5.0) for spamd:5001 in 1.6 seconds, 11288 bytes.
Apr  2 10:31:26 oss2 spamfilter: Sat Oct 15 13:17:14 2016 [2758] info: spamd: result: . -1 - BAYES_00,DKIM_SIGNED,DKIM_VALID,DKIM_VALID_AU,HTML_MESSAGE,NO_RECEIVED,NO_RELAYS,PP_MIME_FAKE_ASCII_TEXT,URIBL_BLOCKED scantime=1.6,size=11288,user=spamd,uid=5001,required_score=5.0,rhost=ip6-localhost,raddr=::1,rport=54698,mid=<0.0.61.22E.1D226E4025142E0.0@smtp9.valisetour.com>,bayes=0.000000,autolearn=no autolearn_force=no
Apr  2 10:31:26 oss2 spamfilter: Sat Oct 15 13:17:14 2016 [2756] info: prefork: child states: IB
Apr  2 10:31:26 oss2 spamfilter: Sat Oct 15 13:17:14 2016 [2759] info: spamd: clean message (-1.8/5.0) for spamd:5001 in 1.7 seconds, 11288 bytes.
Apr  2 10:31:26 oss2 spamfilter: Sat Oct 15 13:17:14 2016 [2759] info: spamd: result: . -1 - BAYES_00,DKIM_SIGNED,DKIM_VALID,DKIM_VALID_AU,HTML_MESSAGE,NO_RECEIVED,NO_RELAYS,PP_MIME_FAKE_ASCII_TEXT,URIBL_BLOCKED scantime=1.7,size=11288,user=spamd,uid=5001,required_score=5.0,rhost=ip6-localhost,raddr=::1,rport=54700,mid=<0.0.61.22E.1D226E4025142E0.0@smtp9.valisetour.com>,bayes=0.000000,autolearn=no autolearn_force=no
Apr  2 10:31:26 oss2 spamfilter: Sat Oct 15 13:17:14 2016 [2756] info: prefork: child states: II
Apr  2 10:31:26 oss2 spamfilter: Sat Oct 15 13:20:21 2016 [2758] info: spamd: connection from ip6-localhost [::1]:54760 to port 783, fd 5
Apr  2 10:31:26 oss2 spamfilter: Sat Oct 15 13:20:21 2016 [2758] info: spamd: processing message <000601d2269a$90c7d4c0$c93956a9@LocalHost4dh> for spamd:5001
Apr  2 10:31:26 oss2 spamfilter: Sat Oct 15 13:20:23 2016 [2758] info: spamd: clean message (3.8/5.0) for spamd:5001 in 2.0 seconds, 5992 bytes.
Apr  2 10:31:26 oss2 spamfilter: Sat Oct 15 13:20:23 2016 [2758] info: spamd: result: . 3 - BAYES_05,HTML_MESSAGE,MIME_HTML_ONLY,NO_RECEIVED,NO_RELAYS,RATWARE_OUTLOOK_NONAME,URIBL_BLOCKED,URIBL_PH_SURBL scantime=2.0,size=5992,user=spamd,uid=5001,required_score=5.0,rhost=ip6-localhost,raddr=::1,rport=54760,mid=<000601d2269a$90c7d4c0$c93956a9@LocalHost4dh>,bayes=0.029870,autolearn=no autolearn_force=no
Apr  2 10:31:26 oss2 spamfilter: Sat Oct 15 13:20:23 2016 [2756] info: prefork: child states: II

I'm sure this behaviour is wrong, but I've no idea why it's doing this. I've looked through several Spamassassin config tutorials, but nothing is giving me a clue on where to look.

If someone could tell me how to fix this, that would be fantastic. Failing that, could let me know why it would be repeating these log lines for every e-mail being processed and where I might starting looking for a solution.

If more info is required, just let me know what you need. I don't want to flood this post with config files and more log info that is unnecessary.

Spuggiehawk
  • 59
  • 1
  • 8

1 Answers1

2

With enormous gratitude to the knowledgeable guys on the Spamassassin users mailing list, I finally got to the bottom of this problem and sorted it out.

Through my mail server configuration process, I had ended up with a helper script /usr/bin/spamfilter.sh

That script was writing to a log file (/var/log/spamassassin/spamd.log) that wasn't included in the logrotate system. The logrotate.d directory contains a config file to rotate /var/log/spamd.log. This (typo?) meant that it was perpetually growing.

Each time a new message was processed by the system, all the content from that log file was getting read in and re-logged to both mail.log and syslog.

I have resolved the problem by fixing the reference in spamfilter.sh to use the /var/log/spamd.log file, which will be rotated on a daily basis, thus preventing a large build-up of messages for re-logging.

I hope this proves to be helpful to others, but I would like to thank the following users from the Spamassassin users mailing list specifically for their help and expert suggestions:

  • Kevin McGrail
  • John Hardin
  • Dave Wreski
  • ap-ml
  • Tom Hendrikx

Fantastic work guys. Thank you so much.

Spuggiehawk
  • 59
  • 1
  • 8
  • 2
    Your answer does not contain any useful information on how to fix the problem. You mention script without showing it. – Roman Jul 29 '18 at 17:39
  • The spamfilter.sh script I mentioned is one that gets created when installing spamassassin. The problem was probably quite specific to my configuration, but the principle of an incorrectly named log file is explained along with how to solve it. – Spuggiehawk Aug 07 '18 at 07:43