Timeout problem on postfix reinjection socket

[Konrad Rzepecki]

    Hi

On one of my server I have amavis 2.7.0, postfix 2.8.7 and problem with 
amavis...

 From time to time amavisd complains about broken pipe on 
/var/spool/postfix/public/smtpa unix socket. Curious is that this happen 
most likely on second child check (about 90-95% times). Switching to 
inet socket doesn't help.

I've big problem with /var filesystem on this server so I cannot provide 
real workflow logs. However, thankfully offline period, I have some time 
to investigate it.

It seem that amavis try to reuse connection that postfix already close 
due to smtp_quit_timeout (default 300s). Logs below shows that, amavis 
try to send SMTP command on socket without checking its activity. And 
after receive error message (issued long time ago), it tried to write 
closed socket which cause SIGPIPE.


So I have question, is any configuration option to limit max time amavis 
try to reuse connection?
Or maybe this is a bug, and amavis should always check if connection is 
active? - If so, please fix it.


For now I make workaround by "setting smtp_quit_timeout=1200s" (not 
tested yet). But I have no guarantee that amavis not try to reuse socket 
after 20 minutes of inactivity. So this make this problem only less like 
to happen, but not fix it.


Example amavis log:
(09631-02) get_deadline fwd_init - deadline in 470.9 s, set to 471.000 s
(09631-02) smtp session reuse (smtp:/var/spool/postfix/public/smtpa), 1 
transactions so far
(09631-02) establish_or_refresh, state: ehlo
(09631-02) smtp cmd> NOOP
(09631-02) rw_loop: needline=0, flush=1, wr=1, timeout=15
(09631-02) rw_loop: receiving
(09631-02) rw_loop read 53 chars< 421 4.4.2 xxx.pl Error: timeout 
exceeded\r\n
(09631-02) rw_loop: sending
(09631-02) smtp NOOP failed (idle 973.0 s): Error writing to socket: 
Broken pipe at /usr/sbin/amavisd line 6843.
(09631-02) Amavis::Out::SMTP::Session close, disconnecting
(09631-02) rw_loop: needline=0, flush=1, wr=1, timeout=15
(09631-02) rw_loop: receiving
(09631-02) rw_loop read: got eof
(09631-02) rw_loop: sending
(09631-02) mail_via_smtp: session failed: Error writing to socket: 
Broken pipe at /usr/sbin/amavisd line 6843.
(09631-02) get_deadline fwd-end-chkpnt - deadline in 470.9 s, set to 
330.000 s
(09631-02) prolong_timer fwd-end-chkpnt: timer 330, was 0, deadline in 
470.9 s
(09631-02) (!)FWD from <xxx at xxx.pl> -> <xxx at dentonet.pl>, 451 4.5.0 From 
MTA() during fwd-connect (Error writing to socket: Broken pipe at 
/usr/sbin/amavisd line 6843.): id=09631-02

Related postfix log:
timeout after END-OF-MESSAGE from localhost[127.0.0.1]


-- 
    Konrad Rzepecki