search

mpaperno / spampd

SpamPD - Spam Proxy Daemon. A spam-filtering SMTP/LMTP proxy server using SpamAssassin in Perl. Since 2002.
GNU General Public License v3.0
34 stars 10 forks source link

`spampd` exit code 1 with no apparent error in debug logs #41

Open bilogic opened 5 months ago

bilogic commented 5 months ago

Logs

Jun 27 13:01:40.726 [35782] dbg: dns: entering helper-app run mode
Jun 27 13:01:43.820 [35782] dbg: dns: leaving helper-app run mode
Jun 27 13:01:43.821 [35782] dbg: razor2: part=0 noresponse
Jun 27 13:01:43.821 [35782] dbg: razor2: results: spam? 0
Jun 27 13:01:43.821 [35782] dbg: razor2: results: engine 8, highest cf score: 0
Jun 27 13:01:43.821 [35782] dbg: razor2: results: engine 4, highest cf score: 0
Jun 27 13:01:43.822 [35782] dbg: rules: running meta tests; score so far=1.206
Jun 27 13:01:43.822 [35782] dbg: rules: flush_evalstr (run_generic_tests) compiling 346 chars of Mail::SpamAssassin::Plugin::Check::_meta_tests_20_1
Jun 27 13:01:43.822 [35782] dbg: rules: run_generic_tests - compiling eval code: meta, priority 20
Jun 27 13:01:43.822 [35782] dbg: rules: compiled meta tests
Jun 27 13:01:43.823 [35782] dbg: check: running tests for priority: 30
Jun 27 13:01:43.823 [35782] dbg: rules: running head tests; score so far=1.206
Jun 27 13:01:43.823 [35782] dbg: rules: flush_evalstr (run_generic_tests) compiling 343 chars of Mail::SpamAssassin::Plugin::Check::_head_tests_30_1
Jun 27 13:01:43.824 [35782] dbg: rules: run_generic_tests - compiling eval code: head, priority 30
Jun 27 13:01:43.824 [35782] dbg: rules: compiled head tests
Jun 27 13:01:43.824 [35782] dbg: rules: running body tests; score so far=1.206
Jun 27 13:01:43.824 [35782] dbg: rules: flush_evalstr (run_generic_tests) compiling 286 chars of Mail::SpamAssassin::Plugin::Check::_body_tests_30_1
Jun 27 13:01:43.825 [35782] dbg: rules: run_generic_tests - compiling eval code: body, priority 30
Jun 27 13:01:43.825 [35782] dbg: rules: compiled body tests
Jun 27 13:01:43.825 [35782] dbg: rules: running uri tests; score so far=1.206
Jun 27 13:01:43.825 [35782] dbg: rules: flush_evalstr (run_generic_tests) compiling 284 chars of Mail::SpamAssassin::Plugin::Check::_uri_tests_30_1
Jun 27 13:01:43.826 [35782] dbg: rules: run_generic_tests - compiling eval code: uri, priority 30
Jun 27 13:01:43.826 [35782] dbg: rules: compiled uri tests
Jun 27 13:01:43.826 [35782] dbg: rules: running body_eval tests; score so far=1.206
Jun 27 13:01:43.826 [35782] dbg: rules: running rawbody tests; score so far=1.206
Jun 27 13:01:43.826 [35782] dbg: rules: flush_evalstr (run_generic_tests) compiling 292 chars of Mail::SpamAssassin::Plugin::Check::_rawbody_tests_30_1
Jun 27 13:01:43.827 [35782] dbg: rules: run_generic_tests - compiling eval code: rawbody, priority 30
Jun 27 13:01:43.827 [35782] dbg: rules: compiled rawbody tests
Jun 27 13:01:43.827 [35782] dbg: rules: running full tests; score so far=1.206
Jun 27 13:01:43.828 [35782] dbg: rules: flush_evalstr (run_generic_tests) compiling 321 chars of Mail::SpamAssassin::Plugin::Check::_full_tests_30_1
Jun 27 13:01:43.828 [35782] dbg: rules: run_generic_tests - compiling eval code: full, priority 30
Jun 27 13:01:43.828 [35782] dbg: rules: compiled full tests
Jun 27 13:01:43.828 [35782] dbg: rules: running full_eval tests; score so far=1.206
Jun 27 13:01:43.829 [35782] dbg: rules: run_eval_tests - compiling eval code: 13, priority 30
Jun 27 13:01:43.829 [35782] dbg: util: current PATH is: /bin:/usr/bin:/sbin:/usr/sbin:/usr/local/bin:/usr/local/sbin
Jun 27 13:01:43.830 [35782] dbg: util: executable for pyzor was found at /bin/pyzor
Jun 27 13:01:43.830 [35782] dbg: pyzor: pyzor is available: /bin/pyzor
Jun 27 13:01:43.830 [35782] dbg: util: secure_tmpfile created a temporary file /tmp/.spamassassin35782apwr0htmp
Jun 27 13:01:43.830 [35782] dbg: check: create_fulltext_tmpfile, written 1443 bytes to file /tmp/.spamassassin35782apwr0htmp
Jun 27 13:01:43.830 [35782] dbg: dns: entering helper-app run mode
Jun 27 13:01:43.831 [35782] dbg: pyzor: opening pipe: /bin/pyzor --homedir /etc/spamassassin/pyzor check < /tmp/.spamassassin35782apwr0htmp
Jun 27 13:01:43.834 [35783] dbg: util: get_user_groups: uid is 0
Jun 27 13:01:43.835 [35783] info: util: setuid: ruid=0 euid=0 rgid=0 0 egid=0 0
Jun 27 13:01:44.255 [35782] dbg: pyzor: [35783] finished: exit 1
Jun 27 13:01:44.255 [35782] dbg: pyzor: got response: public.pyzor.org:24441 (200, 'OK') 0 0
Jun 27 13:01:44.256 [35782] dbg: dns: leaving helper-app run mode
Jun 27 13:01:44.256 [35782] dbg: check: tagrun - tag PYZOR is now ready, value: Reported 0 times.
Jun 27 13:01:44.257 [35782] dbg: rules: running meta tests; score so far=1.206
Jun 27 13:01:44.257 [35782] dbg: rules: flush_evalstr (run_generic_tests) compiling 346 chars of Mail::SpamAssassin::Plugin::Check::_meta_tests_30_1
Jun 27 13:01:44.257 [35782] dbg: rules: run_generic_tests - compiling eval code: meta, priority 30
Jun 27 13:01:44.257 [35782] dbg: rules: compiled meta tests
Jun 27 13:01:44.258 [35782] dbg: check: running tests for priority: 500
Jun 27 13:01:44.258 [35782] dbg: dns: harvest_dnsbl_queries
Jun 27 13:01:44.258 [35782] dbg: async: timing: 0.005 . askdns:A:compiling.spamassassin.taint.org.fresh.fmb.la.
Jun 27 13:01:44.259 [35782] dbg: rules: running head tests; score so far=1.206
Jun 27 13:01:44.259 [35782] dbg: rules: flush_evalstr (run_generic_tests) compiling 345 chars of Mail::SpamAssassin::Plugin::Check::_head_tests_500_1
Jun 27 13:01:44.260 [35782] dbg: rules: run_generic_tests - compiling eval code: head, priority 500
Jun 27 13:01:44.260 [35782] dbg: rules: compiled head tests
Jun 27 13:01:44.260 [35782] dbg: rules: running body tests; score so far=1.206
Jun 27 13:01:44.260 [35782] dbg: rules: flush_evalstr (run_generic_tests) compiling 288 chars of Mail::SpamAssassin::Plugin::Check::_body_tests_500_1
Jun 27 13:01:44.260 [35782] dbg: rules: run_generic_tests - compiling eval code: body, priority 500
Jun 27 13:01:44.261 [35782] dbg: rules: compiled body tests
Jun 27 13:01:44.261 [35782] dbg: rules: running uri tests; score so far=1.206
Jun 27 13:01:44.261 [35782] dbg: rules: flush_evalstr (run_generic_tests) compiling 286 chars of Mail::SpamAssassin::Plugin::Check::_uri_tests_500_1
Jun 27 13:01:44.261 [35782] dbg: rules: run_generic_tests - compiling eval code: uri, priority 500
Jun 27 13:01:44.261 [35782] dbg: rules: compiled uri tests
Jun 27 13:01:44.262 [35782] dbg: rules: running rawbody tests; score so far=1.206
Jun 27 13:01:44.262 [35782] dbg: rules: flush_evalstr (run_generic_tests) compiling 294 chars of Mail::SpamAssassin::Plugin::Check::_rawbody_tests_500_1
Jun 27 13:01:44.262 [35782] dbg: rules: run_generic_tests - compiling eval code: rawbody, priority 500
Jun 27 13:01:44.262 [35782] dbg: rules: compiled rawbody tests
Jun 27 13:01:44.263 [35782] dbg: rules: running full tests; score so far=1.206
Jun 27 13:01:44.263 [35782] dbg: rules: flush_evalstr (run_generic_tests) compiling 323 chars of Mail::SpamAssassin::Plugin::Check::_full_tests_500_1
Jun 27 13:01:44.263 [35782] dbg: rules: run_generic_tests - compiling eval code: full, priority 500
Jun 27 13:01:44.263 [35782] dbg: rules: compiled full tests
Jun 27 13:01:44.263 [35782] dbg: rules: running meta tests; score so far=1.206
Jun 27 13:01:44.265 [35782] dbg: rules: meta test DIGEST_MULTIPLE has undefined dependency 'DCC_CHECK'
Jun 27 13:01:44.273 [35782] dbg: rules: meta test FSL_BULK_SIG has undefined dependency 'DCC_CHECK'
Jun 27 13:01:44.288 [35782] dbg: rules: flush_evalstr (add_evalstr) compiling 60050 chars of Mail::SpamAssassin::Plugin::Check::_meta_tests_500_1
Jun 27 13:01:44.296 [35782] dbg: rules: flush_evalstr (add_evalstr) compiling 60026 chars of Mail::SpamAssassin::Plugin::Check::_meta_tests_500_2
Jun 27 13:01:44.304 [35782] dbg: rules: flush_evalstr (add_evalstr) compiling 60114 chars of Mail::SpamAssassin::Plugin::Check::_meta_tests_500_3
Jun 27 13:01:44.312 [35782] dbg: rules: flush_evalstr (add_evalstr) compiling 61390 chars of Mail::SpamAssassin::Plugin::Check::_meta_tests_500_4
Jun 27 13:01:44.322 [35782] dbg: rules: flush_evalstr (run_generic_tests) compiling 22104 chars of Mail::SpamAssassin::Plugin::Check::_meta_tests_500_5
Jun 27 13:01:44.325 [35782] dbg: rules: run_generic_tests - compiling eval code: meta, priority 500
Jun 27 13:01:44.325 [35782] dbg: rules: compiled meta tests
Jun 27 13:01:44.328 [35782] dbg: check: is spam? score=4.368 required=5
Jun 27 13:01:44.328 [35782] dbg: check: tests=MISSING_DATE,MISSING_HEADERS,MISSING_SUBJECT,NO_RECEIVED,NO_RELAYS
Jun 27 13:01:44.328 [35782] dbg: check: subtests=__BODY_TEXT_LINE,__DKIM_DEPENDABLE,__EMPTY_BODY,__E_LIKE_LETTER(160),__GATED_THROUGH_RCVD_REMOVER,__HAS_FROM,__HAS_MESSAGE_ID,__HAS_MSGID,__KHOP_NO_FULL_NAME,__LOWER_E(160),__MISSING_REF,__MISSING_REPLY,__MSGID_OK_DIGITS,__MSGID_OK_HOST,__MSOE_MID_WRONG_CASE,__NONEMPTY_BODY,__NOT_SPOOFED,__SANE_MSGID,__SUBJECT_EMPTY,__SUBJ_SHORT,__TO_NO_ARROWS_R,__UNUSABLE_MSGID (Total Subtest Hits: 340 / Deduplicated Total Hits: 22)
Jun 27 13:01:44.329 [35782] dbg: check: tagrun - tag SENDERDOMAIN is still blocking action 2
Jun 27 13:01:44.329 [35782] dbg: check: tagrun - tag DKIMDOMAIN is still blocking action 1
Jun 27 13:01:44.329 [35782] dbg: check: tagrun - tag LASTEXTERNALHELO is still blocking action 0
Jun 27 13:01:44.330 [35782] dbg: plugin: Mail::SpamAssassin::Plugin::Bayes=HASH(0x558a1782bcc0) implements 'learner_close', priority 0

Command

/usr/sbin/spampd -d --setsid --pid=/var/run/spampd/spampd.pid --tagall --port=10025 --host=127.0.0.1 --relayport=10026 --relayhost=127.0.0.1 --children=3 --logsock=unix --maxsize=2000 --user=spampd --group=spampd

I'm trying to contain miab in docker and spampd would keep restarting, so I dug into it and found the command. The command exits with 1 when I echo $?, but I can't seem to identify the issue from the logs.

The closest I can pick out is pyzor seems to exit with 1.

Would be most grateful if someone can point it out to me. Thank you.

rsmoorthy commented 3 weeks ago

Same problem faced by me too. I am also running inside docker

mpaperno commented 3 weeks ago

I don't really have any way to troubleshoot this. And I don't see anything amiss in that log besides strange pyzor exit 1 but then seems to report that it's OK. 🤷🏼

Does it still crash if Pyzor is disabled?

Does someone have a Docker container I can try it in?

rsmoorthy commented 3 weeks ago

Thanks for responding. Right now, I have a way to move forward - where it does not crash -- when I start it from command line, instead of let it starting it via systemd.

When started via systemd, it shows:

Oct 31 19:33:03 <host> systemd[1]: Starting Spam Proxy Daemon...
Oct 31 19:33:03 <host> systemd[1]: Started Spam Proxy Daemon.
Oct 31 19:33:08 <host> spampd[4246]: Process Backgrounded
Oct 31 19:33:08 <host> spampd[4246]: 2024/10/31-19:33:08 SpamPD (type Net::Server::PreForkSimple) starting! pid(4246)
Oct 31 19:33:08 <host> spampd[4246]: Binding to TCP port 10025 on host 127.0.0.1 with IPv4
Oct 31 19:33:08 <host> spampd[4246]: Setting gid to "120 120"
Oct 31 19:33:08 <host> spampd[4246]: Setting uid to "116"
Oct 31 19:33:08 <host> spampd[4246]: 2024/10/31-19:33:08 Server closing!
Oct 31 19:33:09 <host> systemd[1]: spampd.service: Deactivated successfully.
Oct 31 19:33:09 <host> systemd[1]: spampd.service: Consumed 2.042s CPU time.

You can see it is crashing. after 2s

But if you run this from command line like:

# export SPAMPD_ARGS="--pid=/var/run/spampd/spampd.pid --tagall --port=10025 --host=127.0.0.1 --relayport=10026 --relayhost=127.0.0.1 --children=3 --logsock=unix --maxsize=2000 --user=spampd --group=spampd"
# /usr/sbin/spampd --setsid $SPAMPD_ARGS

this starts fine.

Right now, I haven't spent more time. But I will do it this weekend and share more details.

mpaperno commented 3 weeks ago

Thanks for the added details.

Which SpamPD version are you running? Seems like older than current release (from the logs)? If so, I recommend trying 2.61 which has bug fixes and lots of logging improvements which may help here. It should be a drop-in replacement for the current script.

Please do update, when you have time, on how it works out or what new you can learn, thanks! -Max