search

darold / squidclamav

SquidClamAv is a dedicated ClamAV antivirus redirector for Squid. It can run antivirus checks based on filename regex, content-type regex, and more. It is easy to install and works even with heavy Squid access.
http://squidclamav.darold.net/
Other
55 stars 32 forks source link

Eicar archive not detected as virus. #11

Closed Mang0uste closed 11 years ago

Mang0uste commented 11 years ago

Hi,

I have installed a squid proxy (3.2.6) using clamav (0.97.6) for virus detection. I obviously installed squidclamav (6.10) and c-icap (0.2.5) and they were just all running like a charm.

During my tests I have noticed that the eicar archive weren't detected as a virus, my browser have just downloaded the file normally.

I'm pretty sure my clamav daemon is working OK, as a manual scan detect archive as a virus : /tmp/eicar.zip: Eicar-Test-Signature FOUND

I've set verbose to 10 on c-icap to figure out the problem daemon is doing lot of stuff but never raised any alert. Here is logs :

Wed Jan 23 16:34:16 2013, main proc, Server stats: Children: 2 Free servers: 18 Used servers:2 Requests served:492 Wed Jan 23 16:34:17 2013, 7450/1437308672, Server 7450 going to serve new request from client (keep-alive) Wed Jan 23 16:34:17 2013, 7450/1437308672, Get entity from trash.... Wed Jan 23 16:34:17 2013, 7450/1437308672, Get entity from trash.... Wed Jan 23 16:34:17 2013, 7450/1437308672, Going to check request for access control restrictions Wed Jan 23 16:34:17 2013, 7450/1437308672, Access control: ALLOW Wed Jan 23 16:34:17 2013, 7450/1437308672, DEBUG squidclamav_init_request_data: initializing request data handler. Wed Jan 23 16:34:17 2013, 7450/1437308672, pool hits:238 allocations: 4 Wed Jan 23 16:34:17 2013, 7450/1437308672, Allocating from objects pool object 6 Wed Jan 23 16:34:17 2013, 7450/1437308672, Requested service: squidclamav Wed Jan 23 16:34:17 2013, 7450/1437308672, Read preview data if there are and process request Wed Jan 23 16:34:17 2013, 7450/1437308672, DEBUG squidclamav_check_preview_handler: processing preview header. Wed Jan 23 16:34:17 2013, 7450/1437308672, DEBUG squidclamav_check_preview_handler: X-Client-IP: 172.16.182.82 Wed Jan 23 16:34:17 2013, 7450/1437308672, DEBUG extract_http_info: method GET Wed Jan 23 16:34:17 2013, 7450/1437308672, DEBUG extract_http_info: url http://securite-informatique.info/virus/eicar/download/eicar_niveau1.zip Wed Jan 23 16:34:17 2013, 7450/1437308672, DEBUG squidclamav_check_preview_handler: URL requested: http://securite-informatique.info/virus/eicar/download/eicar_niveau1.zip Wed Jan 23 16:34:17 2013, 7450/1437308672, DEBUG squidclamav_check_preview_handler: Content-Length: 0 Wed Jan 23 16:34:17 2013, 7450/1437308672, DEBUG squidclamav_check_preview_handler: No body data, allow 204 Wed Jan 23 16:34:17 2013, 7450/1437308672, Preview handler return allow 204 response Wed Jan 23 16:34:17 2013, 7450/1437308672, DEBUG squidclamav_release_request_data: Releasing request data. Wed Jan 23 16:34:17 2013, 7450/1437308672, Storing to objects pool object 6 Wed Jan 23 16:34:17 2013, 7450/1437308672, Log request to access log file /proxy-ng/logs/c-icap/c-icap_access.log Wed Jan 23 16:34:17 2013, 7450/1437308672, Width: 0, Parameter: Wed Jan 23 16:34:17 2013, 7450/1437308672, Width: 0, Parameter: Wed Jan 23 16:34:17 2013, 7450/1437308672, Width: 0, Parameter: Wed Jan 23 16:34:17 2013, 7450/1437308672, Width: 0, Parameter: Wed Jan 23 16:34:17 2013, 7450/1437308672, Width: 0, Parameter: Wed Jan 23 16:34:17 2013, 7450/1437308672, Width: 0, Parameter: Wed Jan 23 16:34:17 2013, 7450/1437308672, Keep-alive:1 Wed Jan 23 16:34:17 2013, main proc, Server stats: Children: 2 Free servers: 18 Used servers:2 Requests served:493

Can you shed any light on this ? I don't really know where to search now :)

Regards,

darold commented 11 years ago

Hi,

Those two lines indicate that the eicar file is already in your squid cache:

Wed Jan 23 16:34:17 2013, 7450/1437308672, DEBUG squidclamav_check_preview_handler: Content-Length: 0
Wed Jan 23 16:34:17 2013, 7450/1437308672, DEBUG squidclamav_check_preview_handler: No body data, allow 204

this is why no preview data were sent to squidclamav.

You have to clear your cache or make a test with an other eicar file. Here is a useful site to test your antivir solution:

 http://www.rosu.fr/tav.html

Regards,

Mang0uste commented 11 years ago

Hi Gilles,

Many thanks for the answer. I have cleaned my cache and made another test. It is still not working but this time I can see that some data are copied to clamav socket. … Thu Jan 24 09:14:32 2013, 27677/471369472, DEBUG squidclamav_check_preview_handler: processing preview header. Thu Jan 24 09:14:32 2013, 27677/471369472, DEBUG squidclamav_check_preview_handler: preview data size is 271 Thu Jan 24 09:14:32 2013, 27677/471369472, DEBUG squidclamav_check_preview_handler: X-Client-IP: 172.16.182.82 Thu Jan 24 09:14:32 2013, 27677/471369472, DEBUG extract_http_info: method GET Thu Jan 24 09:14:32 2013, 27677/471369472, DEBUG extract_http_info: url http://c.rosu.free.fr/eicar.zip Thu Jan 24 09:14:32 2013, 27677/471369472, DEBUG squidclamav_check_preview_handler: URL requested: http://c.rosu.free.fr/eicar.zip Thu Jan 24 09:14:32 2013, 27677/471369472, DEBUG squidclamav_check_preview_handler: Content-Length: 271 Thu Jan 24 09:14:32 2013, 27677/471369472, DEBUG squidclamav_check_preview_handler: Content-Type: application/zip …. Thu Jan 24 09:14:32 2013, 27677/471369472, DEBUG squidclamav_end_of_data_handler: Sending zINSTREAM command to clamd. Thu Jan 24 09:14:32 2013, 27677/471369472, DEBUG squidclamav_end_of_data_handler: Ok connected to clamd. Thu Jan 24 09:14:32 2013, 27677/471369472, DEBUG: squidclamav_end_of_data_handler: Scanning data now Thu Jan 24 09:14:32 2013, 27677/471369472, DEBUG squidclamav_end_of_data_handler: Write 275 bytes on 271 to socket Thu Jan 24 09:14:32 2013, 27677/471369472, DEBUG squidclamav_end_of_data_handler: Closing Clamd connection. Thu Jan 24 09:14:32 2013, 27677/471369472, DEBUG squidclamav_end_of_data_handler: Responding with allow 204 Thu Jan 24 09:14:32 2013, 27677/471369472, DEBUG squidclamav_release_request_data: Releasing request data. …

From my understanding squidclamav have successfully provided the archive to clamav, which did not find anything ? I will investigate on the clamav part, hope logs are relevant for you.

Regards,

De : Darold [mailto:notifications@github.com] Envoyé : mercredi 23 janvier 2013 18:28 À : darold/squidclamav Cc : Aubert Thibaud Objet : Re: [squidclamav] Eicar archive not detected as virus. (#11)

Hi,

Those two lines indicate that the eicar file is already in your squid cache:

Wed Jan 23 16:34:17 2013, 7450/1437308672, DEBUG squidclamav_check_preview_handler: Content-Length: 0

Wed Jan 23 16:34:17 2013, 7450/1437308672, DEBUG squidclamav_check_preview_handler: No body data, allow 204

this is why no preview data were sent to squidclamav.

You have to clear your cache or make a test with an other eicar file. Here is a useful site to test your antivir solution:

http://www.rosu.fr/tav.html

Regards,

— Reply to this email directly or view it on GitHubhttps://github.com/darold/squidclamav/issues/11#issuecomment-12611205.

darold commented 11 years ago

Please make a test with a bigger eicar test file, for example: http://c.rosu.free.fr/eicar_niveau11.zip

Mang0uste commented 11 years ago

Hi,

Same result but I’ve noticed this time the following error : Can't write zINSTREAM ending chars to clamd socket.

Here is full logs :

Fri Jan 25 08:58:29 2013, 27677/408430336, DEBUG squidclamav_release_request_data: Releasing request data. Fri Jan 25 08:58:29 2013, 27677/408430336, Storing to objects pool object 6 Fri Jan 25 08:58:29 2013, 27677/408430336, Log request to access log file /proxy-ng/logs/c-icap/c-icap_access.log Fri Jan 25 08:58:29 2013, 27677/408430336, Width: 0, Parameter: Fri Jan 25 08:58:29 2013, 27677/408430336, Width: 0, Parameter: Fri Jan 25 08:58:29 2013, 27677/408430336, Width: 0, Parameter: Fri Jan 25 08:58:29 2013, 27677/408430336, Width: 0, Parameter: Fri Jan 25 08:58:29 2013, 27677/408430336, Width: 0, Parameter: Fri Jan 25 08:58:29 2013, 27677/408430336, Width: 0, Parameter: Fri Jan 25 08:58:29 2013, 27677/408430336, Keep-alive:1 Fri Jan 25 08:58:29 2013, 27677/408430336, Server 27677 going to serve new request from client (keep-alive) Fri Jan 25 08:58:29 2013, 27677/408430336, Get entity from trash.... Fri Jan 25 08:58:29 2013, 27677/408430336, Get entity from trash.... Fri Jan 25 08:58:29 2013, 27677/408430336, Get entity from trash.... Fri Jan 25 08:58:29 2013, 27677/408430336, Going to check request for access control restrictions Fri Jan 25 08:58:29 2013, 27677/408430336, Access control: ALLOW Fri Jan 25 08:58:29 2013, 27677/408430336, DEBUG squidclamav_init_request_data: initializing request data handler. Fri Jan 25 08:58:29 2013, 27677/408430336, pool hits:996 allocations: 3 Fri Jan 25 08:58:29 2013, 27677/408430336, Allocating from objects pool object 6 Fri Jan 25 08:58:29 2013, 27677/408430336, Requested service: squidclamav Fri Jan 25 08:58:29 2013, 27677/408430336, Read preview data if there are and process request Fri Jan 25 08:58:29 2013, 27677/408430336, DEBUG squidclamav_check_preview_handler: processing preview header. Fri Jan 25 08:58:29 2013, 27677/408430336, DEBUG squidclamav_check_preview_handler: preview data size is 1024 Fri Jan 25 08:58:29 2013, 27677/408430336, DEBUG squidclamav_check_preview_handler: X-Client-IP: 172.16.182.82 Fri Jan 25 08:58:29 2013, 27677/408430336, DEBUG extract_http_info: method GET Fri Jan 25 08:58:29 2013, 27677/408430336, DEBUG extract_http_info: url http://c.rosu.free.fr/eicar_niveau11.zip Fri Jan 25 08:58:29 2013, 27677/408430336, DEBUG squidclamav_check_preview_handler: URL requested: http://c.rosu.free.fr/eicar_niveau11.zip Fri Jan 25 08:58:29 2013, 27677/408430336, DEBUG squidclamav_check_preview_handler: Content-Length: 2666 Fri Jan 25 08:58:29 2013, 27677/408430336, DEBUG squidclamav_check_preview_handler: Content-Type: application/zip Fri Jan 25 08:58:29 2013, 27677/408430336, pool hits:257 allocations: 6 Fri Jan 25 08:58:29 2013, 27677/408430336, Geting buffer from pool 41:0 Fri Jan 25 08:58:29 2013, 27677/408430336, pool hits:258 allocations: 6 Fri Jan 25 08:58:29 2013, 27677/408430336, Geting buffer from pool 2:0 Fri Jan 25 08:58:29 2013, 27677/408430336, pool hits:259 allocations: 6 Fri Jan 25 08:58:29 2013, 27677/408430336, Geting buffer from pool 14:0 Fri Jan 25 08:58:29 2013, 27677/408430336, pool hits:113 allocations: 2 Fri Jan 25 08:58:29 2013, 27677/408430336, Allocating from objects pool object 4 Fri Jan 25 08:58:29 2013, 27677/408430336, Preview handler continue reading more body data Fri Jan 25 08:58:29 2013, 27677/408430336, Going to get/send body data..... Fri Jan 25 08:58:29 2013, 27677/408430336, Going to Read/- data Fri Jan 25 08:58:29 2013, 27677/408430336, OK done reading/writing going to process Fri Jan 25 08:58:29 2013, 27677/408430336, get send body: going to write/read: 1642/0 bytes Fri Jan 25 08:58:29 2013, 27677/408430336, Body data size=2666 Fri Jan 25 08:58:29 2013, 27677/408430336, get send body: written/read: 1642/0 bytes (eof: 1) Fri Jan 25 08:58:29 2013, 27677/408430336, DEBUG squidclamav_end_of_data_handler: ending request data handler. Fri Jan 25 08:58:29 2013, 27677/408430336, dconnect: entering. Fri Jan 25 08:58:29 2013, 27677/408430336, DEBUG squidclamav_end_of_data_handler: Sending zINSTREAM command to clamd. Fri Jan 25 08:58:29 2013, 27677/408430336, DEBUG squidclamav_end_of_data_handler: Ok connected to clamd. Fri Jan 25 08:58:29 2013, 27677/408430336, DEBUG: squidclamav_end_of_data_handler: Scanning data now Fri Jan 25 08:58:29 2013, 27677/408430336, DEBUG squidclamav_end_of_data_handler: Write 2670 bytes on 2666 to socket Fri Jan 25 08:58:29 2013, 27677/408430336, ERROR: Can't send to clamd: Broken pipe Fri Jan 25 08:58:29 2013, 27677/408430336, ERROR squidclamav_end_of_data_handler: Can't write zINSTREAM ending chars to clamd socket. Fri Jan 25 08:58:29 2013, 27677/408430336, DEBUG squidclamav_end_of_data_handler: Closing Clamd connection. Fri Jan 25 08:58:29 2013, 27677/408430336, DEBUG squidclamav_end_of_data_handler: Responding with allow 204 Fri Jan 25 08:58:29 2013, 27677/408430336, DEBUG squidclamav_release_request_data: Releasing request data. Fri Jan 25 08:58:29 2013, 27677/408430336, Storing to objects pool object 4 Fri Jan 25 08:58:29 2013, 27677/408430336, Store buffer to short pool 41:0 Fri Jan 25 08:58:29 2013, 27677/408430336, Store buffer to short pool 2:0 Fri Jan 25 08:58:29 2013, 27677/408430336, Store buffer to short pool 14:0 Fri Jan 25 08:58:29 2013, 27677/408430336, Storing to objects pool object 6 Fri Jan 25 08:58:29 2013, 27677/408430336, Log request to access log file /proxy-ng/logs/c-icap/c-icap_access.log Fri Jan 25 08:58:29 2013, 27677/408430336, Width: 0, Parameter: Fri Jan 25 08:58:29 2013, 27677/408430336, Width: 0, Parameter: Fri Jan 25 08:58:29 2013, 27677/408430336, Width: 0, Parameter: Fri Jan 25 08:58:29 2013, 27677/408430336, Width: 0, Parameter: Fri Jan 25 08:58:29 2013, 27677/408430336, Width: 0, Parameter: Fri Jan 25 08:58:29 2013, 27677/408430336, Width: 0, Parameter: Fri Jan 25 08:58:29 2013, 27677/408430336, Keep-alive:1

Regards,

De : Darold [mailto:notifications@github.com] Envoyé : jeudi 24 janvier 2013 18:21 À : darold/squidclamav Cc : Aubert Thibaud Objet : Re: [squidclamav] Eicar archive not detected as virus. (#11)

Please make a test with a bigger eicar test file, for example: http://c.rosu.free.fr/eicar_niveau11.zip

— Reply to this email directly or view it on GitHubhttps://github.com/darold/squidclamav/issues/11#issuecomment-12662104.

darold commented 11 years ago

Hi,

Sorry for the response delay. What is the value of MaxRecursion in your clamd.conf configuration file ?

Here the eicar test file downloaded have eleven recursion level in the archive so if MaxRecursion is lower clamd may close the communication socket. You should either increase the value of this directive or use a test file with less recursion level.

Let me know,

Regards,

Mang0uste commented 11 years ago

Hi and no problem,

I’ve explicitly add a value of 15 for this option. I have also removed squidguard redirection, squid caching and abort content directives in squidclamav.conf. This file now look like :

maxsize 5000000 redirect http://myproxytestserver1/cgi-bin/clwarn.cgi clamd_local /proxy-ng/var/run/clamd.ctl

trust_cache 0 maxredir 30 timeout 60

logredir 1 dnslookup 0 safebrowsing 0

Here is the result for eicar11 :

Mon Jan 28 09:13:04 2013, 17388/260740864, DEBUG squidclamav_release_request_data: Releasing request data. Mon Jan 28 09:13:04 2013, 17388/260740864, DEBUG squidclamav_init_request_data: initializing request data handler. Mon Jan 28 09:13:04 2013, 17388/260740864, DEBUG squidclamav_check_preview_handler: processing preview header. Mon Jan 28 09:13:04 2013, 17388/260740864, DEBUG squidclamav_check_preview_handler: preview data size is 1024 Mon Jan 28 09:13:04 2013, 17388/260740864, DEBUG squidclamav_check_preview_handler: X-Client-IP: 172.16.182.82 Mon Jan 28 09:13:04 2013, 17388/260740864, DEBUG extract_http_info: method GET Mon Jan 28 09:13:04 2013, 17388/260740864, DEBUG extract_http_info: url http://c.rosu.free.fr/eicar_niveau11.zip Mon Jan 28 09:13:04 2013, 17388/260740864, DEBUG squidclamav_check_preview_handler: URL requested: http://c.rosu.free.fr/eicar_niveau11.zip Mon Jan 28 09:13:04 2013, 17388/260740864, DEBUG squidclamav_check_preview_handler: Content-Length: 2666 Mon Jan 28 09:13:04 2013, 17388/260740864, DEBUG squidclamav_check_preview_handler: Content-Type: application/zip Mon Jan 28 09:13:04 2013, 17388/260740864, Preview handler continue reading more body data Mon Jan 28 09:13:04 2013, 17388/260740864, DEBUG squidclamav_end_of_data_handler: ending request data handler. Mon Jan 28 09:13:04 2013, 17388/260740864, dconnect: entering. Mon Jan 28 09:13:04 2013, 17388/260740864, DEBUG squidclamav_end_of_data_handler: Sending zINSTREAM command to clamd. Mon Jan 28 09:13:04 2013, 17388/260740864, DEBUG squidclamav_end_of_data_handler: Ok connected to clamd. Mon Jan 28 09:13:04 2013, 17388/260740864, DEBUG: squidclamav_end_of_data_handler: Scanning data now Mon Jan 28 09:13:04 2013, 17388/260740864, DEBUG squidclamav_end_of_data_handler: Write 2670 bytes on 2666 to socket Mon Jan 28 09:13:04 2013, 17388/260740864, DEBUG squidclamav_end_of_data_handler: Closing Clamd connection. Mon Jan 28 09:13:04 2013, 17388/260740864, DEBUG squidclamav_end_of_data_handler: Responding with allow 204 Mon Jan 28 09:13:04 2013, 17388/260740864, DEBUG squidclamav_release_request_data: Releasing request data.

Here an other log for eivar_niveau14.bin :

Mon Jan 28 09:16:05 2013, 17388/239761152, DEBUG squidclamav_init_request_data: initializing request data handler. Mon Jan 28 09:16:05 2013, 17388/239761152, DEBUG squidclamav_check_preview_handler: processing preview header. Mon Jan 28 09:16:05 2013, 17388/239761152, DEBUG squidclamav_check_preview_handler: X-Client-IP: 172.16.182.82 Mon Jan 28 09:16:05 2013, 17388/239761152, DEBUG extract_http_info: method GET Mon Jan 28 09:16:05 2013, 17388/239761152, DEBUG extract_http_info: url http://c.rosu.free.fr/eicar_niveau14.bin Mon Jan 28 09:16:05 2013, 17388/239761152, DEBUG squidclamav_check_preview_handler: URL requested: http://c.rosu.free.fr/eicar_niveau14.bin Mon Jan 28 09:16:05 2013, 17388/239761152, DEBUG squidclamav_check_preview_handler: Content-Length: 0 Mon Jan 28 09:16:05 2013, 17388/239761152, DEBUG squidclamav_check_preview_handler: No body data, allow 204 Mon Jan 28 09:16:05 2013, 17388/239761152, Preview handler return allow 204 response Mon Jan 28 09:16:05 2013, 17388/239761152, DEBUG squidclamav_release_request_data: Releasing request data. Mon Jan 28 09:16:05 2013, 17388/271230720, DEBUG squidclamav_init_request_data: initializing request data handler. Mon Jan 28 09:16:05 2013, 17388/271230720, DEBUG squidclamav_check_preview_handler: processing preview header. Mon Jan 28 09:16:05 2013, 17388/271230720, DEBUG squidclamav_check_preview_handler: preview data size is 1024 Mon Jan 28 09:16:05 2013, 17388/271230720, DEBUG squidclamav_check_preview_handler: X-Client-IP: 172.16.182.82 Mon Jan 28 09:16:05 2013, 17388/271230720, DEBUG extract_http_info: method GET Mon Jan 28 09:16:05 2013, 17388/271230720, DEBUG extract_http_info: url http://c.rosu.free.fr/eicar_niveau14.bin Mon Jan 28 09:16:05 2013, 17388/271230720, DEBUG squidclamav_check_preview_handler: URL requested: http://c.rosu.free.fr/eicar_niveau14.bin Mon Jan 28 09:16:05 2013, 17388/271230720, DEBUG squidclamav_check_preview_handler: Content-Length: 34573 Mon Jan 28 09:16:05 2013, 17388/271230720, DEBUG squidclamav_check_preview_handler: Content-Type: application/octet-stream Mon Jan 28 09:16:05 2013, 17388/271230720, Preview handler continue reading more body data Mon Jan 28 09:16:05 2013, 17388/271230720, DEBUG squidclamav_end_of_data_handler: ending request data handler. Mon Jan 28 09:16:05 2013, 17388/271230720, dconnect: entering. Mon Jan 28 09:16:05 2013, 17388/271230720, DEBUG squidclamav_end_of_data_handler: Sending zINSTREAM command to clamd. Mon Jan 28 09:16:05 2013, 17388/271230720, DEBUG squidclamav_end_of_data_handler: Ok connected to clamd. Mon Jan 28 09:16:05 2013, 17388/271230720, DEBUG: squidclamav_end_of_data_handler: Scanning data now Mon Jan 28 09:16:05 2013, 17388/271230720, DEBUG squidclamav_end_of_data_handler: Write 8196 bytes on 8192 to socket Mon Jan 28 09:16:05 2013, 17388/271230720, DEBUG squidclamav_end_of_data_handler: Write 8196 bytes on 8192 to socket Mon Jan 28 09:16:05 2013, 17388/271230720, DEBUG squidclamav_end_of_data_handler: Write 8196 bytes on 8192 to socket Mon Jan 28 09:16:05 2013, 17388/271230720, DEBUG squidclamav_end_of_data_handler: Write 8196 bytes on 8192 to socket Mon Jan 28 09:16:05 2013, 17388/271230720, DEBUG squidclamav_end_of_data_handler: Write 1809 bytes on 1805 to socket Mon Jan 28 09:16:05 2013, 17388/271230720, DEBUG squidclamav_end_of_data_handler: Closing Clamd connection. Mon Jan 28 09:16:05 2013, 17388/271230720, DEBUG squidclamav_end_of_data_handler: Responding with allow 204 Mon Jan 28 09:16:05 2013, 17388/271230720, DEBUG squidclamav_release_request_data: Releasing request data.

Is there any way to analyze what’s going on between socket ? Clamav is also not very talkative in debug mode…

Regards,

De : Darold [mailto:notifications@github.com] Envoyé : samedi 26 janvier 2013 11:39 À : darold/squidclamav Cc : Aubert Thibaud Objet : Re: [squidclamav] Eicar archive not detected as virus. (#11)

Hi,

Sorry for the response delay. What is the value of MaxRecursion in your clamd.conf configuration file ?

Here the eicar test file downloaded have eleven recursion level in the archive so if MaxRecursion is lower clamd may close the communication socket. You should either increase the value of this directive or use a test file with less recursion level.

Let me know,

Regards,

— Reply to this email directly or view it on GitHubhttps://github.com/darold/squidclamav/issues/11#issuecomment-12733717.

Mang0uste commented 11 years ago

My apologies for this second mail, but regarding source code (line 654) I should see in log a message such as “received from Clamd: stream: OK|NOK” or whatever during archive downloading no ?

Regards,

De : Aubert Thibaud Envoyé : lundi 28 janvier 2013 09:19 À : 'darold/squidclamav' Objet : RE: [squidclamav] Eicar archive not detected as virus. (#11)

Hi and no problem,

I’ve explicitly add a value of 15 for this option. I have also removed squidguard redirection, squid caching and abort content directives in squidclamav.conf. This file now look like :

maxsize 5000000 redirect http://myproxytestserver1/cgi-bin/clwarn.cgi clamd_local /proxy-ng/var/run/clamd.ctl

trust_cache 0 maxredir 30 timeout 60

logredir 1 dnslookup 0 safebrowsing 0

Here is the result for eicar11 :

Mon Jan 28 09:13:04 2013, 17388/260740864, DEBUG squidclamav_release_request_data: Releasing request data. Mon Jan 28 09:13:04 2013, 17388/260740864, DEBUG squidclamav_init_request_data: initializing request data handler. Mon Jan 28 09:13:04 2013, 17388/260740864, DEBUG squidclamav_check_preview_handler: processing preview header. Mon Jan 28 09:13:04 2013, 17388/260740864, DEBUG squidclamav_check_preview_handler: preview data size is 1024 Mon Jan 28 09:13:04 2013, 17388/260740864, DEBUG squidclamav_check_preview_handler: X-Client-IP: 172.16.182.82 Mon Jan 28 09:13:04 2013, 17388/260740864, DEBUG extract_http_info: method GET Mon Jan 28 09:13:04 2013, 17388/260740864, DEBUG extract_http_info: url http://c.rosu.free.fr/eicar_niveau11.zip Mon Jan 28 09:13:04 2013, 17388/260740864, DEBUG squidclamav_check_preview_handler: URL requested: http://c.rosu.free.fr/eicar_niveau11.zip Mon Jan 28 09:13:04 2013, 17388/260740864, DEBUG squidclamav_check_preview_handler: Content-Length: 2666 Mon Jan 28 09:13:04 2013, 17388/260740864, DEBUG squidclamav_check_preview_handler: Content-Type: application/zip Mon Jan 28 09:13:04 2013, 17388/260740864, Preview handler continue reading more body data Mon Jan 28 09:13:04 2013, 17388/260740864, DEBUG squidclamav_end_of_data_handler: ending request data handler. Mon Jan 28 09:13:04 2013, 17388/260740864, dconnect: entering. Mon Jan 28 09:13:04 2013, 17388/260740864, DEBUG squidclamav_end_of_data_handler: Sending zINSTREAM command to clamd. Mon Jan 28 09:13:04 2013, 17388/260740864, DEBUG squidclamav_end_of_data_handler: Ok connected to clamd. Mon Jan 28 09:13:04 2013, 17388/260740864, DEBUG: squidclamav_end_of_data_handler: Scanning data now Mon Jan 28 09:13:04 2013, 17388/260740864, DEBUG squidclamav_end_of_data_handler: Write 2670 bytes on 2666 to socket Mon Jan 28 09:13:04 2013, 17388/260740864, DEBUG squidclamav_end_of_data_handler: Closing Clamd connection. Mon Jan 28 09:13:04 2013, 17388/260740864, DEBUG squidclamav_end_of_data_handler: Responding with allow 204 Mon Jan 28 09:13:04 2013, 17388/260740864, DEBUG squidclamav_release_request_data: Releasing request data.

Here an other log for eivar_niveau14.bin :

Mon Jan 28 09:16:05 2013, 17388/239761152, DEBUG squidclamav_init_request_data: initializing request data handler. Mon Jan 28 09:16:05 2013, 17388/239761152, DEBUG squidclamav_check_preview_handler: processing preview header. Mon Jan 28 09:16:05 2013, 17388/239761152, DEBUG squidclamav_check_preview_handler: X-Client-IP: 172.16.182.82 Mon Jan 28 09:16:05 2013, 17388/239761152, DEBUG extract_http_info: method GET Mon Jan 28 09:16:05 2013, 17388/239761152, DEBUG extract_http_info: url http://c.rosu.free.fr/eicar_niveau14.bin Mon Jan 28 09:16:05 2013, 17388/239761152, DEBUG squidclamav_check_preview_handler: URL requested: http://c.rosu.free.fr/eicar_niveau14.bin Mon Jan 28 09:16:05 2013, 17388/239761152, DEBUG squidclamav_check_preview_handler: Content-Length: 0 Mon Jan 28 09:16:05 2013, 17388/239761152, DEBUG squidclamav_check_preview_handler: No body data, allow 204 Mon Jan 28 09:16:05 2013, 17388/239761152, Preview handler return allow 204 response Mon Jan 28 09:16:05 2013, 17388/239761152, DEBUG squidclamav_release_request_data: Releasing request data. Mon Jan 28 09:16:05 2013, 17388/271230720, DEBUG squidclamav_init_request_data: initializing request data handler. Mon Jan 28 09:16:05 2013, 17388/271230720, DEBUG squidclamav_check_preview_handler: processing preview header. Mon Jan 28 09:16:05 2013, 17388/271230720, DEBUG squidclamav_check_preview_handler: preview data size is 1024 Mon Jan 28 09:16:05 2013, 17388/271230720, DEBUG squidclamav_check_preview_handler: X-Client-IP: 172.16.182.82 Mon Jan 28 09:16:05 2013, 17388/271230720, DEBUG extract_http_info: method GET Mon Jan 28 09:16:05 2013, 17388/271230720, DEBUG extract_http_info: url http://c.rosu.free.fr/eicar_niveau14.bin Mon Jan 28 09:16:05 2013, 17388/271230720, DEBUG squidclamav_check_preview_handler: URL requested: http://c.rosu.free.fr/eicar_niveau14.bin Mon Jan 28 09:16:05 2013, 17388/271230720, DEBUG squidclamav_check_preview_handler: Content-Length: 34573 Mon Jan 28 09:16:05 2013, 17388/271230720, DEBUG squidclamav_check_preview_handler: Content-Type: application/octet-stream Mon Jan 28 09:16:05 2013, 17388/271230720, Preview handler continue reading more body data Mon Jan 28 09:16:05 2013, 17388/271230720, DEBUG squidclamav_end_of_data_handler: ending request data handler. Mon Jan 28 09:16:05 2013, 17388/271230720, dconnect: entering. Mon Jan 28 09:16:05 2013, 17388/271230720, DEBUG squidclamav_end_of_data_handler: Sending zINSTREAM command to clamd. Mon Jan 28 09:16:05 2013, 17388/271230720, DEBUG squidclamav_end_of_data_handler: Ok connected to clamd. Mon Jan 28 09:16:05 2013, 17388/271230720, DEBUG: squidclamav_end_of_data_handler: Scanning data now Mon Jan 28 09:16:05 2013, 17388/271230720, DEBUG squidclamav_end_of_data_handler: Write 8196 bytes on 8192 to socket Mon Jan 28 09:16:05 2013, 17388/271230720, DEBUG squidclamav_end_of_data_handler: Write 8196 bytes on 8192 to socket Mon Jan 28 09:16:05 2013, 17388/271230720, DEBUG squidclamav_end_of_data_handler: Write 8196 bytes on 8192 to socket Mon Jan 28 09:16:05 2013, 17388/271230720, DEBUG squidclamav_end_of_data_handler: Write 8196 bytes on 8192 to socket Mon Jan 28 09:16:05 2013, 17388/271230720, DEBUG squidclamav_end_of_data_handler: Write 1809 bytes on 1805 to socket Mon Jan 28 09:16:05 2013, 17388/271230720, DEBUG squidclamav_end_of_data_handler: Closing Clamd connection. Mon Jan 28 09:16:05 2013, 17388/271230720, DEBUG squidclamav_end_of_data_handler: Responding with allow 204 Mon Jan 28 09:16:05 2013, 17388/271230720, DEBUG squidclamav_release_request_data: Releasing request data.

Is there any way to analyze what’s going on between socket ? Clamav is also not very talkative in debug mode…

Regards,

De : Darold [mailto:notifications@github.com] Envoyé : samedi 26 janvier 2013 11:39 À : darold/squidclamav Cc : Aubert Thibaud Objet : Re: [squidclamav] Eicar archive not detected as virus. (#11)

Hi,

Sorry for the response delay. What is the value of MaxRecursion in your clamd.conf configuration file ?

Here the eicar test file downloaded have eleven recursion level in the archive so if MaxRecursion is lower clamd may close the communication socket. You should either increase the value of this directive or use a test file with less recursion level.

Let me know,

Regards,

— Reply to this email directly or view it on GitHubhttps://github.com/darold/squidclamav/issues/11#issuecomment-12733717.

Mang0uste commented 11 years ago

Hi Again…

It’s now working ok ! It was my user « clamav » who did not have rights to write into the custom tmp server directory.

Clamav never complain the temporary folder were not writeable during startup or debug … Anyway now I have a nice message from squidclamav : received from Clamd: stream: Virus found

Many thanks for your time anyway ☺

Regards,

De : Aubert Thibaud Envoyé : lundi 28 janvier 2013 11:08 À : 'darold/squidclamav' Objet : RE: [squidclamav] Eicar archive not detected as virus. (#11)

My apologies for this second mail, but regarding source code (line 654) I should see in log a message such as “received from Clamd: stream: OK|NOK” or whatever during archive downloading no ?

Regards,

De : Aubert Thibaud Envoyé : lundi 28 janvier 2013 09:19 À : 'darold/squidclamav' Objet : RE: [squidclamav] Eicar archive not detected as virus. (#11)

Hi and no problem,

I’ve explicitly add a value of 15 for this option. I have also removed squidguard redirection, squid caching and abort content directives in squidclamav.conf. This file now look like :

maxsize 5000000 redirect http://myproxytestserver1/cgi-bin/clwarn.cgi clamd_local /proxy-ng/var/run/clamd.ctl

trust_cache 0 maxredir 30 timeout 60

logredir 1 dnslookup 0 safebrowsing 0

Here is the result for eicar11 :

Mon Jan 28 09:13:04 2013, 17388/260740864, DEBUG squidclamav_release_request_data: Releasing request data. Mon Jan 28 09:13:04 2013, 17388/260740864, DEBUG squidclamav_init_request_data: initializing request data handler. Mon Jan 28 09:13:04 2013, 17388/260740864, DEBUG squidclamav_check_preview_handler: processing preview header. Mon Jan 28 09:13:04 2013, 17388/260740864, DEBUG squidclamav_check_preview_handler: preview data size is 1024 Mon Jan 28 09:13:04 2013, 17388/260740864, DEBUG squidclamav_check_preview_handler: X-Client-IP: 172.16.182.82 Mon Jan 28 09:13:04 2013, 17388/260740864, DEBUG extract_http_info: method GET Mon Jan 28 09:13:04 2013, 17388/260740864, DEBUG extract_http_info: url http://c.rosu.free.fr/eicar_niveau11.zip Mon Jan 28 09:13:04 2013, 17388/260740864, DEBUG squidclamav_check_preview_handler: URL requested: http://c.rosu.free.fr/eicar_niveau11.zip Mon Jan 28 09:13:04 2013, 17388/260740864, DEBUG squidclamav_check_preview_handler: Content-Length: 2666 Mon Jan 28 09:13:04 2013, 17388/260740864, DEBUG squidclamav_check_preview_handler: Content-Type: application/zip Mon Jan 28 09:13:04 2013, 17388/260740864, Preview handler continue reading more body data Mon Jan 28 09:13:04 2013, 17388/260740864, DEBUG squidclamav_end_of_data_handler: ending request data handler. Mon Jan 28 09:13:04 2013, 17388/260740864, dconnect: entering. Mon Jan 28 09:13:04 2013, 17388/260740864, DEBUG squidclamav_end_of_data_handler: Sending zINSTREAM command to clamd. Mon Jan 28 09:13:04 2013, 17388/260740864, DEBUG squidclamav_end_of_data_handler: Ok connected to clamd. Mon Jan 28 09:13:04 2013, 17388/260740864, DEBUG: squidclamav_end_of_data_handler: Scanning data now Mon Jan 28 09:13:04 2013, 17388/260740864, DEBUG squidclamav_end_of_data_handler: Write 2670 bytes on 2666 to socket Mon Jan 28 09:13:04 2013, 17388/260740864, DEBUG squidclamav_end_of_data_handler: Closing Clamd connection. Mon Jan 28 09:13:04 2013, 17388/260740864, DEBUG squidclamav_end_of_data_handler: Responding with allow 204 Mon Jan 28 09:13:04 2013, 17388/260740864, DEBUG squidclamav_release_request_data: Releasing request data.

Here an other log for eivar_niveau14.bin :

Mon Jan 28 09:16:05 2013, 17388/239761152, DEBUG squidclamav_init_request_data: initializing request data handler. Mon Jan 28 09:16:05 2013, 17388/239761152, DEBUG squidclamav_check_preview_handler: processing preview header. Mon Jan 28 09:16:05 2013, 17388/239761152, DEBUG squidclamav_check_preview_handler: X-Client-IP: 172.16.182.82 Mon Jan 28 09:16:05 2013, 17388/239761152, DEBUG extract_http_info: method GET Mon Jan 28 09:16:05 2013, 17388/239761152, DEBUG extract_http_info: url http://c.rosu.free.fr/eicar_niveau14.bin Mon Jan 28 09:16:05 2013, 17388/239761152, DEBUG squidclamav_check_preview_handler: URL requested: http://c.rosu.free.fr/eicar_niveau14.bin Mon Jan 28 09:16:05 2013, 17388/239761152, DEBUG squidclamav_check_preview_handler: Content-Length: 0 Mon Jan 28 09:16:05 2013, 17388/239761152, DEBUG squidclamav_check_preview_handler: No body data, allow 204 Mon Jan 28 09:16:05 2013, 17388/239761152, Preview handler return allow 204 response Mon Jan 28 09:16:05 2013, 17388/239761152, DEBUG squidclamav_release_request_data: Releasing request data. Mon Jan 28 09:16:05 2013, 17388/271230720, DEBUG squidclamav_init_request_data: initializing request data handler. Mon Jan 28 09:16:05 2013, 17388/271230720, DEBUG squidclamav_check_preview_handler: processing preview header. Mon Jan 28 09:16:05 2013, 17388/271230720, DEBUG squidclamav_check_preview_handler: preview data size is 1024 Mon Jan 28 09:16:05 2013, 17388/271230720, DEBUG squidclamav_check_preview_handler: X-Client-IP: 172.16.182.82 Mon Jan 28 09:16:05 2013, 17388/271230720, DEBUG extract_http_info: method GET Mon Jan 28 09:16:05 2013, 17388/271230720, DEBUG extract_http_info: url http://c.rosu.free.fr/eicar_niveau14.bin Mon Jan 28 09:16:05 2013, 17388/271230720, DEBUG squidclamav_check_preview_handler: URL requested: http://c.rosu.free.fr/eicar_niveau14.bin Mon Jan 28 09:16:05 2013, 17388/271230720, DEBUG squidclamav_check_preview_handler: Content-Length: 34573 Mon Jan 28 09:16:05 2013, 17388/271230720, DEBUG squidclamav_check_preview_handler: Content-Type: application/octet-stream Mon Jan 28 09:16:05 2013, 17388/271230720, Preview handler continue reading more body data Mon Jan 28 09:16:05 2013, 17388/271230720, DEBUG squidclamav_end_of_data_handler: ending request data handler. Mon Jan 28 09:16:05 2013, 17388/271230720, dconnect: entering. Mon Jan 28 09:16:05 2013, 17388/271230720, DEBUG squidclamav_end_of_data_handler: Sending zINSTREAM command to clamd. Mon Jan 28 09:16:05 2013, 17388/271230720, DEBUG squidclamav_end_of_data_handler: Ok connected to clamd. Mon Jan 28 09:16:05 2013, 17388/271230720, DEBUG: squidclamav_end_of_data_handler: Scanning data now Mon Jan 28 09:16:05 2013, 17388/271230720, DEBUG squidclamav_end_of_data_handler: Write 8196 bytes on 8192 to socket Mon Jan 28 09:16:05 2013, 17388/271230720, DEBUG squidclamav_end_of_data_handler: Write 8196 bytes on 8192 to socket Mon Jan 28 09:16:05 2013, 17388/271230720, DEBUG squidclamav_end_of_data_handler: Write 8196 bytes on 8192 to socket Mon Jan 28 09:16:05 2013, 17388/271230720, DEBUG squidclamav_end_of_data_handler: Write 8196 bytes on 8192 to socket Mon Jan 28 09:16:05 2013, 17388/271230720, DEBUG squidclamav_end_of_data_handler: Write 1809 bytes on 1805 to socket Mon Jan 28 09:16:05 2013, 17388/271230720, DEBUG squidclamav_end_of_data_handler: Closing Clamd connection. Mon Jan 28 09:16:05 2013, 17388/271230720, DEBUG squidclamav_end_of_data_handler: Responding with allow 204 Mon Jan 28 09:16:05 2013, 17388/271230720, DEBUG squidclamav_release_request_data: Releasing request data.

Is there any way to analyze what’s going on between socket ? Clamav is also not very talkative in debug mode…

Regards,

De : Darold [mailto:notifications@github.com] Envoyé : samedi 26 janvier 2013 11:39 À : darold/squidclamav Cc : Aubert Thibaud Objet : Re: [squidclamav] Eicar archive not detected as virus. (#11)

Hi,

Sorry for the response delay. What is the value of MaxRecursion in your clamd.conf configuration file ?

Here the eicar test file downloaded have eleven recursion level in the archive so if MaxRecursion is lower clamd may close the communication socket. You should either increase the value of this directive or use a test file with less recursion level.

Let me know,

Regards,

— Reply to this email directly or view it on GitHubhttps://github.com/darold/squidclamav/issues/11#issuecomment-12733717.

darold commented 11 years ago

Oh great, thank you for your feedback. I was looking for reproducing the issue without success until know :-)