On 02/09/2019 16.03, Per Jessen wrote:
Carlos E. R. wrote:
MemoryLimit=500M TimeoutSec=300s
Result after start succeeds is:
[snip]
Which is indeed what I wanted! Bingo!
Interesting experiment. How long does it take to scan an email now?
One with virii, instantly: <2.6> 2019-09-02 16:25:52 Telcontar postfix 4022 - - E4CD6320B4A: from=<cer@Isengard.valinor>, size=408087, nrcpt=1 (queue active) <2.6> 2019-09-02 16:25:52 Telcontar postfix 3162 - - disconnect from Isengard.valinor[192.168.1.16] ehlo=1 mail=1 rcpt=1 data=1 quit=1 commands=5 <2.6> 2019-09-02 16:25:52 Telcontar amavis 3937 - - (03937-05) LMTP [127.0.0.1]:10024 /var/spool/amavis/tmp/amavis-20190902T130130-03937-Cu9e3pu9: <cer@Isengard.valinor> -> <cer@Telcontar.valinor> SIZE=408087 Received: from Telcontar.valinor ([127.0.0.1]) by localhost (telcontar.valinor [127.0.0.1]) (amavisd-new, port 10024) with LMTP for <cer@telcontar.valinor>; Mon, 2 Sep 2019 16:25:52 +0200 (CEST) <2.6> 2019-09-02 16:25:53 Telcontar amavis 3937 - - (03937-05) Checking: ddPNTIuWd5YP MYNETS [192.168.1.16] <cer@Isengard.valinor> -> <cer@Telcontar.valinor> <2.6> 2019-09-02 16:25:53 Telcontar amavis 3937 - - (03937-05) p.path BANNED:1 cer@Telcontar.valinor: "P=p003,L=1,M=multipart/mixed | P=p002,L=1/2,M=application/octet-stream,T=exe,T=exe-ms,N=virisample", matching_key="(?^:^\\.(exe-ms|dll)$)" <2.6> 2019-09-02 16:25:55 Telcontar clamd 30239 - - /var/spool/amavis/tmp/amavis-20190902T130130-03937-Cu9e3pu9/parts/p004: Win.Worm.N-74 FOUND <2.6> 2019-09-02 16:25:55 Telcontar clamd 30239 - - /var/spool/amavis/tmp/amavis-20190902T130130-03937-Cu9e3pu9/parts/p002: Win.Worm.N-74 FOUND <2.6> 2019-09-02 16:25:55 Telcontar amavis 3937 - - (03937-05) local delivery: <> -> virus-quarantine, mbx=/var/spool/amavis/virusmails/virus-ddPNTIuWd5YP <2.6> 2019-09-02 16:25:55 Telcontar postfix 3173 - - connect from localhost[127.0.0.1] I'll try now a healthy windows executable. [...] yes, it takes much longer: 2.6> 2019-09-02 16:30:56 Telcontar postfix 3437 - - connect from Isengard.valinor[192.168.1.16] <2.6> 2019-09-02 16:30:56 Telcontar postfix 3437 - - 97451320B4A: client=Isengard.valinor[192.168.1.16] <2.6> 2019-09-02 16:30:56 Telcontar postfix 3441 - - 97451320B4A: message-id=<alpine.LSU.2.21.1909021630300.11050@Isengard.valinor> <2.6> 2019-09-02 16:30:56 Telcontar postfix 4022 - - 97451320B4A: from=<cer@Isengard.valinor>, size=21665824, nrcpt=1 (queue active) <2.6> 2019-09-02 16:30:56 Telcontar postfix 3437 - - disconnect from Isengard.valinor[192.168.1.16] ehlo=1 mail=1 rcpt=1 data=1 quit=1 commands=5 <2.6> 2019-09-02 16:30:57 Telcontar amavis 3939 - - (03939-05) LMTP [127.0.0.1]:10024 /var/spool/amavis/tmp/amavis-20190902T130850-03939-Cgk2L9yY: <cer@Isengard.valinor> -> <cer@Telcontar.valinor> SIZE=21665824 Received: from Telcontar.valinor ([127.0.0.1]) by localhost (telcontar.valinor [127.0.0.1]) (amavisd-new, port 10024) with LMTP for <cer@telcontar.valinor>; Mon, 2 Sep 2019 16:30:57 +0200 (CEST) <2.6> 2019-09-02 16:30:57 Telcontar amavis 3939 - - (03939-05) Checking: J0be6HvIx64w MYNETS [192.168.1.16] <cer@Isengard.valinor> -> <cer@Telcontar.valinor> <2.6> 2019-09-02 16:30:57 Telcontar amavis 3939 - - (03939-05) p.path BANNED:1 cer@Telcontar.valinor: "P=p003,L=1,M=multipart/mixed | P=p002,L=1/2,M=application/x-executable,T=exe,T=exe-ms,N=Restorer7.exe", matching_key="(?^:^\\.(exe-ms|dll)$)" <2.6> 2019-09-02 16:31:46 Telcontar dovecot - - - imap(cer)<3323><CNLOy5KRZLh/AAAB>: Logged out in=3973 out=10314 deleted=0 expunged=0 trashed=0 hdr_count=0 hdr_bytes=0 body_count=0 body_bytes=0 <2.6> 2019-09-02 16:32:16 Telcontar dovecot - - - imap-login: Login: user=<cer>, method=PLAIN, rip=127.0.0.1, lip=127.0.0.1, mpid=3498, TLS, session=<RFyq1pKRerh/AAAB> <2.6> 2019-09-02 16:32:29 Telcontar amavis 3939 - - (03939-05) local delivery: <> -> banned-quarantine, mbx=/var/spool/amavis/virusmails/banned-J0be6HvIx64w Took two minutes and a half, I saw clamd busy and trashing. But I do not see a clamd entry in the log, maybe because it is not a virus. <2.6> 2019-09-02 16:32:30 Telcontar postfix 3503 - - connect from localhost[127.0.0.1] <2.6> 2019-09-02 16:32:30 Telcontar postfix 3503 - - 0B4303213B5: client=localhost[127.0.0.1] <2.6> 2019-09-02 16:32:30 Telcontar postfix 3441 - - 0B4303213B5: message-id=<VAJ0be6HvIx64w@telcontar.valinor> <2.6> 2019-09-02 16:32:30 Telcontar postfix 3503 - - disconnect from localhost[127.0.0.1] ehlo=1 mail=1 rcpt=1 data=1 quit=1 commands=5 <2.6> 2019-09-02 16:32:30 Telcontar postfix 4022 - - 0B4303213B5: from=<virusalert@telcontar.valinor>, size=2917, nrcpt=1 (queue active) <2.6> 2019-09-02 16:32:30 Telcontar amavis 3939 - - (03939-05) Gru4ztQtvhFO(J0be6HvIx64w) SEND from <virusalert@telcontar.valinor> -> <virusalert@telcontar.valinor>, ENVID=AM.Gru4ztQtvhFO.20190902T143230Z@telcontar.valinor 250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 0B4303213B5 <2.6> 2019-09-02 16:32:30 Telcontar amavis 3939 - - (03939-05) DEFANGING MAIL: WARNING: banning rules detected suspect part(s),\ndo not open unless you know what you are doing <2.6> 2019-09-02 16:32:30 Telcontar postfix 3503 - - connect from localhost[127.0.0.1] And then a pdf: 2.6> 2019-09-02 16:34:13 Telcontar postfix 3577 - - connect from Isengard.valinor[192.168.1.16] <2.6> 2019-09-02 16:34:13 Telcontar postfix 3577 - - AD196320B4A: client=Isengard.valinor[192.168.1.16] <2.6> 2019-09-02 16:34:13 Telcontar postfix 3578 - - AD196320B4A: message-id=<alpine.LSU.2.21.1909021633580.11149@Isengard.valinor> <2.6> 2019-09-02 16:34:13 Telcontar postfix 4022 - - AD196320B4A: from=<cer@Isengard.valinor>, size=3115, nrcpt=1 (queue active) <2.6> 2019-09-02 16:34:13 Telcontar postfix 3577 - - disconnect from Isengard.valinor[192.168.1.16] ehlo=1 mail=1 rcpt=1 data=1 quit=1 commands=5 <2.6> 2019-09-02 16:34:13 Telcontar amavis 3937 - - (03937-06) LMTP [127.0.0.1]:10024 /var/spool/amavis/tmp/amavis-20190902T130130-03937-Cu9e3pu9: <cer@Isengard.valinor> -> <cer@Telcontar.valinor> SIZE=3115 Received: from Telcontar.valinor ([127.0.0.1]) by localhost (telcontar.valinor [127.0.0.1]) (amavisd-new, port 10024) with LMTP for <cer@telcontar.valinor>; Mon, 2 Sep 2019 16:34:13 +0200 (CEST) <2.6> 2019-09-02 16:34:13 Telcontar amavis 3937 - - (03937-06) Checking: u_8kSrBam1lD MYNETS [192.168.1.16] <cer@Isengard.valinor> -> <cer@Telcontar.valinor> <2.6> 2019-09-02 16:34:13 Telcontar postfix 3582 - - connect from localhost[127.0.0.1] Not even a second. See the mem progression: 3929 vscan 20 0 997064 738932 4624 0 S 0,000 9,054 0:00.10 clamd 30239 vscan 20 0 923168 2092 2092 728904 S 0,000 0,026 0:00.00 clamd 3929 vscan 20 0 997064 738932 4624 0 S 0,000 9,054 0:00.10 clamd 30239 vscan 20 0 923168 2092 2092 728904 S 0,000 0,026 0:00.00 clamd 30239 vscan 20 0 996900 30004 4556 704460 S 0,000 0,368 0:00.22 clamd 30239 vscan 20 0 996900 29204 4620 704460 S 0,000 0,358 0:00.22 clamd 30239 vscan 20 0 996900 32652 4716 701284 S 0,000 0,400 0:00.29 clamd 30239 vscan 20 0 996900 123228 4808 615560 S 0,000 1,510 0:01.49 clamd 30239 vscan 20 0 996900 30004 4556 704460 S 0,000 0,368 0:00.22 clamd 30239 vscan 20 0 996900 29204 4620 704460 S 0,000 0,358 0:00.22 clamd 30239 vscan 20 0 996900 32652 4716 701284 S 0,000 0,400 0:00.29 clamd 30239 vscan 20 0 996900 123228 4808 615560 S 0,000 1,510 0:01.49 clamd - virus detected. 30239 vscan 20 0 998992 360616 6756 424364 S 0,000 4,419 1:31.16 clamd - healthy exe 30239 vscan 20 0 998992 361200 6780 423740 S 0,000 4,426 1:31.18 clamd - pdf So there is a long delay only when there is an executable that is not detected as virus, because then it has to load the entire data section. Notice however that amavis rejects it nonetheless, I have it setup that way.
I tried the same on my own clamd daemon (custom written, but same idea). Startup took just about 9 minutes, the first few scans took up to 35sec, but then it seems to drop to 1-2 seconds. That's easily 10 times more than normal, which isn't good. Sometimes processing time shoots up to 5 or 10. Still fairly minimal impact - I guess the numbers I'm seeing might be schewed as the system has plenty of memory.
Yes, I can accept this impact. Now ram usage is just beneath 400M. I'll try later something: find out the cgroup entry for memory limit and change it "brute", ie, after start. See if I can manage to drop the mem use to minimal on demand, then back to "normal" limit. This would allow a much faster response, and recover 800MB when I want it. If this works, I may be able to script it into the mail fetch script. -- Cheers / Saludos, Carlos E. R. (from 15.0 x86_64 at Telcontar)