On Thu, 22 Apr 2004, Nigel Horne wrote:
> I have a theory. To test it please let me know if removing the --local option
> fixes the problem.
Hello Nigel.
After upgrading my main mailservers to 0.70 I have been able to test
this.
Using
/usr/local/sbin/clamav-milter --local --outgoing \
--postmaster-only --headers /var/run/clamd/clmilter.sock
I had runaway processes on those two servers after 9 and 14 hours.
I then restarted clamav-milter without the --local option, and now 30
hours later they are still running just fine.
While using --local I started "ktrace"ing the processes. Here is what
the output of
sudo kdump -f /home/thing/ktrace.out -R -p 4344
looks like. (4344 is the PID of the runaway process)
4344 clamav-milter 1082798411.384537 RET fork 0
4344 clamav-milter 1082798411.384605 CALL close(0x3)
4344 clamav-milter 1082798411.384609 RET close 0
4344 clamav-milter 1082798411.384612 CALL close(0x4)
4344 clamav-milter 1082798411.384614 RET close 0
4344 clamav-milter 1082798411.384624 CALL pipe(0x2afc9194)
4344 clamav-milter 1082798411.384632 RET pipe 0
4344 clamav-milter 1082798411.384638 CALL fcntl(0x3,0x3,0)
4344 clamav-milter 1082798411.384641 RET fcntl 2
4344 clamav-milter 1082798411.384643 CALL fcntl(0x3,0x4,0x6)
4344 clamav-milter 1082798411.384646 RET fcntl 0
4344 clamav-milter 1082798411.384648 CALL fcntl(0x4,0x3,0)
4344 clamav-milter 1082798411.384650 RET fcntl 2
4344 clamav-milter 1082798411.384653 CALL fcntl(0x4,0x4,0x6)
4344 clamav-milter 1082798411.384655 RET fcntl 0
4344 clamav-milter 1082798411.384773 CALL fcntl(0x8,0x3,0)
4344 clamav-milter 1082798411.384777 RET fcntl -1 errno 9 Bad file descriptor
4344 clamav-milter 1082798411.384781 CALL fcntl(0x8,0x3,0)
4344 clamav-milter 1082798411.384784 RET fcntl -1 errno 9 Bad file descriptor
4344 clamav-milter 1082798411.384787 CALL fcntl(0x8,0x3,0)
4344 clamav-milter 1082798411.384789 RET fcntl -1 errno 9 Bad file descriptor
4344 clamav-milter 1082798411.384792 CALL fcntl(0x8,0x3,0)
4344 clamav-milter 1082798411.384795 RET fcntl -1 errno 9 Bad file descriptor
4344 clamav-milter 1082798411.384798 CALL fcntl(0x8,0x3,0)
4344 clamav-milter 1082798411.384800 RET fcntl -1 errno 9 Bad file descriptor
4344 clamav-milter 1082798411.384803 CALL fcntl(0x8,0x3,0)
4344 clamav-milter 1082798411.384805 RET fcntl -1 errno 9 Bad file descriptor
This fcntl(8, F_GETFL, 0) is then repeated millions of times until the
process is killed. Every 100ms a few other lines occur:
4344 clamav-milter 1082798411.978828 PSIG SIGPROF caught handler=0xafd6010 mask=0x0
4344 clamav-milter 1082798411.978847 CALL gettimeofday(0x2afc91a8,0)
4344 clamav-milter 1082798411.978850 RET gettimeofday 0
4344 clamav-milter 1082798411.978853 CALL sigprocmask(0x3,0)
4344 clamav-milter 1082798411.978856 RET sigprocmask -65793/0xfffefeff
4344 clamav-milter 1082798411.978859 CALL sigreturn(0x3c0496b0)
4344 clamav-milter 1082798411.978862 RET sigreturn JUSTRETURN
According to `date -r 1082798411` all this happened at
Sat Apr 24 11:20:11 CEST 2004.
>From /var/log/clamd (I use syslog):
Apr 24 11:20:11 goliat clamd[14928]: stream: Worm.SomeFool.Q FOUND
And from /var/log/maillog: (anonymized)
Apr 24 11:20:11 goliat sm-mta[27938]: i3O9K6F9027938: from=<[EMAIL PROTECTED]>,
size=38898, class=0, nrcpts=1, msgid=<[EMAIL PROTECTED]>, proto=ESMTP, daemon=MTA,
relay=somehost.dk [someip]
Apr 24 11:20:11 goliat clamav-milter[5033]: i3O9K6F9027938: stream: Worm.SomeFool.Q
FOUND Intercepted virus from <[EMAIL PROTECTED]> to <[EMAIL PROTECTED]>
Apr 24 11:24:11 goliat sm-mta[27938]: i3O9K6F9027938: Milter (clmilter): timeout
before data read
Apr 24 11:24:11 goliat sm-mta[27938]: i3O9K6F9027938: Milter (clmilter): to error state
Apr 24 11:24:11 goliat sm-mta[27938]: i3O9K6F9027938: Milter: data, reject=451 4.7.1
Please try again later
Apr 24 11:24:11 goliat sm-mta[27938]: i3O9K6F9027938: to=<[EMAIL PROTECTED]>,
delay=00:04:04, pri=30264, stat=Please try again later
The parent process is 5033. Here is another fork it dit previously:
5033 clamav-milter 1082795332.593959 CALL poll(0x3c00c200,0x2,0x12a)
6102 clamav-milter 1082795332.594035 RET fork 0
6102 clamav-milter 1082795332.594108 CALL close(0x3)
6102 clamav-milter 1082795332.594112 RET close 0
6102 clamav-milter 1082795332.594114 CALL close(0x4)
6102 clamav-milter 1082795332.594116 RET close 0
6102 clamav-milter 1082795332.594126 CALL pipe(0x2afc9194)
6102 clamav-milter 1082795332.594135 RET pipe 0
6102 clamav-milter 1082795332.594142 CALL fcntl(0x3,0x3,0)
6102 clamav-milter 1082795332.594145 RET fcntl 2
6102 clamav-milter 1082795332.594147 CALL fcntl(0x3,0x4,0x6)
6102 clamav-milter 1082795332.594149 RET fcntl 0
6102 clamav-milter 1082795332.594152 CALL fcntl(0x4,0x3,0)
6102 clamav-milter 1082795332.594154 RET fcntl 2
6102 clamav-milter 1082795332.594156 CALL fcntl(0x4,0x4,0x6)
6102 clamav-milter 1082795332.594159 RET fcntl 0
6102 clamav-milter 1082795332.594276 CALL fcntl(0x3e,0x3,0)
6102 clamav-milter 1082795332.594280 RET fcntl -1 errno 9 Bad file descriptor
6102 clamav-milter 1082795332.594286 PSIG SIGSEGV SIG_DFL code 1 addr=0x61532048
trapno=1
6102 clamav-milter 1082795332.594289 PSIG SIGSEGV SIG_DFL code 0 addr=0x0 trapno=0
5033 clamav-milter 1082795332.594391 PSIG SIGCHLD caught handler=0xafd6010 mask=0x0
5033 clamav-milter 1082795332.594395 RET poll -1 errno 4 Interrupted system call
Same pattern seen many times.
I have put the first ~200K lines of second number 1082798411 at
http://thing.dk/kdump.1082798411.gz.
That includes the original infected mail, the report sent to
postmaster and the runaway forked process.
Need more info? Please ask.
Best regards,
Søren Thing.
-------------------------------------------------------
This SF.net email is sponsored by: The Robotic Monkeys at ThinkGeek
For a limited time only, get FREE Ground shipping on all orders of $35
or more. Hurry up and shop folks, this offer expires April 30th!
http://www.thinkgeek.com/freeshipping/?cpg297
_______________________________________________
Clamav-users mailing list
[EMAIL PROTECTED]
https://lists.sourceforge.net/lists/listinfo/clamav-users
