[Postfixbuch-users] hängende amavisd-new Prozesse

[Oliver Pürsten]

Am 11.07.2011 17:08, schrieb Thomas Schwenski:
> Hallo Oliver,
>
>> Nach dem letzten größerem Software Update habe ich extreme Probleme mit
>> hängenden Amavis Child Prozessen. Das stellt sich im top dann so dar:
>>
>>    PID USERNAME   THR PRI NICE   SIZE    RES STATE   C   TIME   WCPU COMMAND
>> 38403 vscan        1 118    0   864M   806M CPU0    0   1:18 100.00% perl
>>
>> Wenn einer der Child Prozesse 100% erreicht hat macht der Amavisd nix mehr.
>
> ...
>
>
>> Meine Vermutung geht in Richtung Perl, da vorher perl 5.8.9 installiert
>> war und nach dem letzten Update jetzt v. 5.10.1 in Einsatz ist.
>
> Was sagen denn Deine Logfiles (/var/log/mail.log&  /var/log/syslog) dazu?
>
>
> Thomas
>
Moin Thomas!

ich habe das ganze mal provoziert (nanny ausgemacht) und dabei kam folgendes raus.

Die Prozesse schaukeln sich immer mehr auf, erst auf 100% (s.o.) dann steigt der Speicherbedarft 
stetig weiter an. Irgendwann kommt das System dann zum Stillstand, was im TOP dann wie folgt aussieht:

last pid: 99963;  load averages:  2.17,  2.64,  2.94          up 75+19:43:09  09:35:19
174 processes: 3 running, 171 sleeping
CPU: 26.1% user,  0.0% nice,  0.6% system,  0.1% interrupt, 73.2% idle
Mem: 1948M Active, 322M Inact, 1297M Wired, 168M Cache, 417M Buf, 195M Free
Swap: 8192M Total, 6863M Used, 1328M Free, 83% Inuse

   PID USERNAME   THR PRI NICE   SIZE    RES STATE   C   TIME   WCPU COMMAND
91853 vscan        1 118    0  4164M   738M CPU3    3  77:31 100.00% perl
94243 vscan        1 118    0  2944M  1131M CPU6    6  42:55 100.00% perl

Im Maillog sieht das ganze dann wie folgt aus:

Jul 12 09:30:03 server3 amavis[99405]: (99405-05) smtp session rundown all sessions, idle 0.6 s, 
smtp:[127.0.0.1]:10025, state ehlo
Jul 12 09:30:03 server3 amavis[99549]: (99549-03) smtp session rundown all sessions, idle 0.4 s, 
smtp:[127.0.0.1]:10025, state ehlo
Jul 12 09:30:03 server3 amavis[99405]: (99405-05) smtp session rundown, sending QUIT
Jul 12 09:30:03 server3 amavis[99549]: (99549-03) smtp session rundown, sending QUIT
Jul 12 09:30:03 server3 amavis[99636]: (99636-01) smtp session rundown all sessions, idle 23.6 s, 
smtp:[127.0.0.1]:10025, state ehlo
Jul 12 09:30:03 server3 amavis[99636]: (99636-01) smtp session rundown, sending QUIT
Jul 12 09:30:03 server3 amavis[99636]: (99636-01) smtp session rundown, closing session 
smtp:[127.0.0.1]:10025
Jul 12 09:30:03 server3 amavis[47046]: Net::Server: 2011/07/12-09:30:03 Server closing!
Jul 12 09:30:03 server3 amavis[99100]: (99100-10) (!)TempDir removal: tempdir is to be PRESERVED: 
/var/amavis/tmp/amavis-20110712T092544-99100
Jul 12 09:30:03 server3 amavis[99671]: (99671-01) (!)TempDir removal: tempdir is to be PRESERVED: 
/var/amavis/tmp/amavis-20110712T093002-99671
Jul 12 09:30:04 server3 amavis[99549]: (99549-03) smtp session rundown, closing session 
smtp:[127.0.0.1]:10025
Jul 12 09:30:04 server3 amavis[99549]: (99549-03) (!)TempDir removal: tempdir is to be PRESERVED: 
/var/amavis/tmp/amavis-20110712T092915-99549
Jul 12 09:30:04 server3 amavis[99405]: (99405-05) smtp session rundown, closing session 
smtp:[127.0.0.1]:10025
Jul 12 09:30:04 server3 amavis[99405]: (99405-05) (!)TempDir removal: tempdir is to be PRESERVED: 
/var/amavis/tmp/amavis-20110712T092816-99405

... und denn is Ende, im Logfile kommt nichts mehr. Evtl. kommt dann noch dies:

Jul 12 09:36:36 server3 postfix/qmgr[87666]: warning: connect to transport private/smtp_amavis: No 
such file or directory

... aber auch nicht zwingend.

Der Betrieb lässt sich dann wie folgt wiederherstellen:

- 100% Prozesse killen, dann scheint der amavisd sich selbst neu zu starten und ist auch wieder via 
Port 10024 zu erreichen, allerdings kein Mailverkehr.
- Postfix neustarten und dann läuft alles wieder.

Ich werde das heute im Laufe des Tages weiter beobachten, sollte sich am Verhalten was ändern dann 
schicke ich die neuen Info's hinterher.

-- 
Gruß, Oliver