could not read from amavisd socket /var/amavis/amavisd.sock: No error: 0

[Fabian Wenk]

Hello Damian

On 26.12.2023 10:09, Damian wrote:
>> amavisd-milter then does log this line:
>> could not read from amavisd socket /var/amavis/amavisd.sock: No error: 0
> 
> The amavisd-milter code is:
> 
>> logqidmsg(mlfi, LOG_ERR, "could not read from amavisd socket %s: %s",     
>>     amavisd_socket, strerror(errno));
>> logqidmsg(mlfi, LOG_DEBUG, "amavisd response line %s", mlfi->mlfi_amabuf);
> 
> Apparently there could be a response line. Can you turn on debug mode?

During my tests I also had debug enabled for both independently but did 
not see anything useful. I have now tried to replicate it with a simple 
e-mail through telnet:

fabian at flashback:~/ % telnet mail.home4u.ch 25
Trying 2001:8a8:1005:1::2...
Connected to mail.home4u.ch.
Escape character is '^]'.
220 batman.home4u.ch ESMTP Sendmail 8.17.2/8.17.2; Tue, 26 Dec 2023 
17:08:59 +0100 (CET)
ehlo flashback.wenks.ch
250-batman.home4u.ch Hello flashback.wenks.ch 
[IPv6:2001:8a8:1005:1:0:0:0:4], pleased to meet you
250-ENHANCEDSTATUSCODES
250-PIPELINING
250-8BITMIME
250-SIZE 30000000
250-DSN
250-ETRN
250-STARTTLS
250-DELIVERBY
250 HELP
mail from: <test at home4u.ch>
250 2.1.0 <test at home4u.ch>... Sender ok
rcpt to: <fabian at wenks.ch>
250 2.1.5 <fabian at wenks.ch>... Recipient ok
data
354 Enter mail, end with "." on a line by itself
Subject: Test with 2 DKIM Sigs
From: test at home4u.ch
To: fabian at wenks.ch
DKIM-Signature: v=1; a=rsa-sha256; q=dns/txt; c=relaxed/relaxed;
	Signature stuff stole from an other email, so removed;
DKIM-Signature: v=1; a=ed25519-sha256; q=dns/txt; c=relaxed/relaxed;
	Signature stuff stole from an other email, so removed;

Test with 2 DKIM Sigs
.
250 2.0.0 3BQG2Gtp038253 Message accepted for delivery
quit
221 2.0.0 batman.home4u.ch closing connection
Connection closed by foreign host.
fabian at flashback:~/ %


With the -P (but not yet debug) option to amavisd-milter this gets logged:

Dec 26 16:56:50 batman amavisd-milter[64918]: 3BQFtEiN037254: could not 
read from amavisd socket /var/amavis/amavisd.sock: No error: 0
Dec 26 16:56:50 batman amavis[64869]: Net::Server: Child process 5270 
exited with status 0 - signal was 6

And then with additional '-d 9' option to amavisd-milter and '$log_level 
= 5;' in amavisd.conf I do get this in the log (more details including 
Sendmail and SpamAssassin which is not run with amavis, but later in 
deliver process):

Dec 26 17:02:16 batman amavisd-milter[38234]: flashback.wenks.ch: Daemon 
name: IPv6
Dec 26 17:03:27 batman sm-mta[64131]: 3BQG2Gtp038253: 
from=<test at home4u.ch>, size=1498, class=0, nrcpts=1, 
msgid=<202312261602.3BQG2Gtp038253 at batman.home4u.ch>, proto=ESMTP, 
daemon=IPv6, relay=flashback.wenks.ch [IPv6:2001:8a8:1005:1:0:0:0:4]
Dec 26 17:03:27 batman amavisd-milter[38234]: 3BQG2Gtp038253: could not 
read from amavisd socket /var/amavis/amavisd.sock: No error: 0
Dec 26 17:03:27 batman amavis[38204]: Net::Server: Child process 38225 
exited with status 0 - signal was 6
Dec 26 17:03:27 batman amavis[38204]: sd_notify (no socket): 
STATUS=Starting child process(es), ready for work.
Dec 26 17:03:28 batman spamd[5276]: spamd: connection from ::1 
[::1]:16463 to port 783, fd 5
Dec 26 17:03:28 batman spamd[5276]: spamd: processing message 
<202312261602.3BQG2Gtp038253 at batman.home4u.ch> for spamd:58
Dec 26 17:03:28 batman spamd[86118]: prefork: child states: BIIII
Dec 26 17:03:28 batman spamd[86118]: spamd: handled cleanup of child pid 
[5276] due to SIGCHLD: DIED, signal 4 (0004)
Dec 26 17:03:28 batman sm-mta[64131]: 3BQG2Gtp038253: 
to=<fabian at wenks.ch>, delay=00:00:44, xdelay=00:00:01, mailer=cyrus, 
pri=31498, dsn=2.0.0, stat=Sent
Dec 26 17:03:28 batman spamd[86118]: spamd: server successfully spawned 
child process, pid 38316
Dec 26 17:03:28 batman spamd[86118]: prefork: child states: IIIII


And this I see in the console where I did restart amavisd-new and 
amavisd-milter daemons:

Starting amavisd_milter.
batman:~/ # [0] got cmd 'O' len 12
[0] cur 0 new 1 nextmask 2
[0] milter_negotiate: mta_actions=0x1ff, mta_flags=0x1fffff 
actions=0x1d, flags=0x300
[0] got cmd 'D' len 151
[0] cur 1 new ffffffff nextmask 2004
[0] got cmd 'C' len 35
[0] cur 1 new 2 nextmask 2004
[0] mi_engine: mi_rd_cmd error (2)
[0] got cmd 'O' len 12
[0] cur 0 new 1 nextmask 2
[0] milter_negotiate: mta_actions=0x1ff, mta_flags=0x1fffff 
actions=0x1d, flags=0x300
[0] got cmd 'D' len 158
[0] cur 1 new ffffffff nextmask 2004
[0] got cmd 'C' len 51
[0] cur 1 new 2 nextmask 2004
[0] got cmd 'D' len 1
[0] cur 2 new ffffffff nextmask 2018
[0] got cmd 'H' len 19
[0] cur 2 new 3 nextmask 2018
[0] got cmd 'D' len 119
[0] cur 3 new ffffffff nextmask 2018
[0] got cmd 'M' len 17
[0] cur 3 new 4 nextmask 2018
[0] got cmd 'D' len 54
[0] cur 4 new ffffffff nextmask 3020
[0] got cmd 'R' len 18
[0] cur 4 new 5 nextmask 3020
[0] got cmd 'O' len 12
[0] cur 0 new 1 nextmask 2
[0] milter_negotiate: mta_actions=0x1ff, mta_flags=0x1fffff 
actions=0x1d, flags=0x300
[0] got cmd 'D' len 163
[0] cur 1 new ffffffff nextmask 2004
[0] got cmd 'C' len 56
[0] cur 1 new 2 nextmask 2004
[0] got cmd 'D' len 1
[0] cur 2 new ffffffff nextmask 2018
[0] got cmd 'H' len 10
[0] cur 2 new 3 nextmask 2018
[0] mi_engine: mi_rd_cmd error (2)
[0] got cmd 'L' len 32
[0] cur 5 new 7 nextmask 37e0
[0] got cmd 'L' len 20
[0] cur 7 new 7 nextmask 1180
[0] got cmd 'L' len 19
[0] cur 7 new 7 nextmask 1180
[0] got cmd 'L' len 829
[0] cur 7 new 7 nextmask 1180
[0] got cmd 'L' len 568
[0] cur 7 new 7 nextmask 1180
[0] got cmd 'N' len 0
[0] cur 7 new 8 nextmask 1180
[0] got cmd 'B' len 25
[0] cur 8 new 9 nextmask 1600
[0] got cmd 'D' len 57
[0] cur 9 new ffffffff nextmask 1600
[0] got cmd 'E' len 0
[0] cur 9 new a nextmask 1600
[0] mi_engine: mi_rd_cmd error (2)
[0] got cmd 'O' len 12
[0] cur 0 new 1 nextmask 2
[0] milter_negotiate: mta_actions=0x1ff, mta_flags=0x1fffff 
actions=0x1d, flags=0x300
[0] got cmd 'D' len 128
[0] cur 1 new ffffffff nextmask 2004
[0] got cmd 'C' len 39
[0] cur 1 new 2 nextmask 2004
[0] got cmd 'D' len 1
[0] cur 2 new ffffffff nextmask 2018
[0] got cmd 'H' len 10
[0] cur 2 new 3 nextmask 2018
[0] got cmd 'D' len 104
[0] cur 3 new ffffffff nextmask 2018
[0] got cmd 'H' len 10
[0] cur 3 new 3 nextmask 2018
[0] mi_engine: mi_rd_cmd error (2)


Best regards,
Fabian