[clamav-users] log representation

Wed Oct 23 18:35:35 UTC 2019

On 23-10-2019 16:08, G.W. Haywood via clamav-users wrote:
> Hi there,
>
> On Wed, 23 Oct 2019, Frans de Boer wrote:
>> On 22-10-2019 22:33, G.W. Haywood via clamav-users wrote:
>>> On Tue, 22 Oct 2019, Frans de Boer wrote:
>>>
>>>> Does anybody knows how to make the log output of the ClamAV daemons 
>>>> the same as normal log's. That is, with an ISO date, followed by 
>>>> host name, program/daemon name and concluding with the real message.
>>>
>>> That's normally done by syslog (or equivalent: rsyslog, syslog-ng, ...)
>>> so if you tell the daemon to log via syslog it should be taken care of
>>> for you.
>>>
>> Nope, 0.102.0 for instance does not pass the program name. I only get 
>> the '->' characters.
>
> Below is the debug log from your mail as it came in today.  The lines
> are very long I'm afraid, if your mail client does silly things with
> them then they all begin with the date and time.  The line from the
> clamd scan result is approximately in the middle.  This is 0.102rc.
>
> 8<-------------------------------------------------------------------------------------------------------------------------------------------- 
>
> Oct 23 14:05:05 mail6 xm[18320]   x9ND4sM7022360: xm_eoh_callback(): 
> [192.34.61.247], [AS14061], return [SMFIS_CONTINUE]
> Oct 23 14:05:06 mail6 xm[18320] x9ND4sM7022360:                    
> xm_stats(): [192.34.61.247] +++++++ END EOH CALLBACK +++++++
> Oct 23 14:05:06 mail6 xm[18320]   x9ND4sM7022360: 
> xm_body_callback(464)  : [192.34.61.247]  + chunk length: [1618]
> Oct 23 14:05:06 mail6 sm-mta[22360] x9ND4sM8022360: Milter add: 
> header: X-Originating-Country: US
> Oct 23 14:05:06 mail6 sm-mta[22360] x9ND4sM8022360: Milter add: 
> header: X-AS-Number: AS14061 ([DIGITALOCEAN, LLC] [US] [192.34.61.247])
> Oct 23 14:05:06 mail6 sm-mta[22360] x9ND4sM8022360: Milter insert (0): 
> header: Received-SPF: pass (mail6.jubileegroup.co.uk: 
> lists.clamav.net: 192.34.61.247 is authorized to use 
> 'clamav-users-bounces at lists.clamav.net' in 'mfrom' identity (mechanism 
> 'mx' matched) client-ip=192.34.61.247; helo=mailmanlists.network)
> Oct 23 14:05:06 mail6 sm-mta[22360] x9ND4sM8022360: Milter add: 
> header: X-SPF-hello: pass ([mailmanlists.network]=[v=spf1 mx a 
> ip4:192.34.61.247 ip6:2604:A880:400:D0::C0E:2001 ~all])\n\t( DNS 
> lookups=[2] void lookups=[0])
> Oct 23 14:05:06 mail6 sm-mta[22360] x9ND4sM8022360: Milter add: 
> header: X-SPF-mfrom: pass ([lists.clamav.net]=[v=spf1 mx a 
> ip4:192.34.61.247 ip6:2604:A880:400:D0::C0E:2001 ~all])\n\t( DNS 
> lookups=[2] void lookups=[0])
> Oct 23 14:05:06 mail6 xm[18320]   x9ND4sM7022360: 
> xm_greylist_interval(): [192.34.61.247] Rejection rate is [ 310/ 
> 726]=[ 42.70] percent for [AS14061]
> Oct 23 14:05:06 mail6 xm[18320]   x9ND4sM7022360: 
> xm_eom_callback(464)  : [192.34.61.247] not greylisting WHITELISTED IP
> Oct 23 14:05:06 mail6 sm-mta[22360] x9ND4sM8022360: Milter add: 
> header: X-Greylist-Delay: WHITELISTED IP [192.34.61.247], transport 
> not delayed by extensible-milter-6.842
> Oct 23 14:05:06 mail6 sm-mta[22360] x9ND4sM8022360: Milter add: 
> header: X-DKIM-auth: none ([2019-10-23 13:05:06Z 
> mail6.jubileegroup.co.uk] [result=No DKIM signature found in message])
> Oct 23 14:05:06 mail6 xm[18320]   x9ND4sM7022360: xm_scan(9600)  : 
> [192.34.61.247], Connnecting to ClamAV daemon on [192.168.44.47:3313]...
> Oct 23 14:05:06 mail6 xm[18320]   x9ND4sM7022360: xm_scan(9600)  : 
> [192.34.61.247], Connnected to ClamAV daemon (version [ClamAV 
> 0.102.0-rc/25597/Wed Oct  9 09:39:14 2019]
> Oct 23 14:05:06 mail6 xm[18320]   x9ND4sM7022360: xm_scan(9600)  : 
> [192.34.61.247], Attempting to send [4446] bytes to ClamAV daemon from 
> entire_message...
> Oct 23 14:05:06 mail6 xm[18320]   x9ND4sM7022360: xm_scan(9600)  : 
> [192.34.61.247], Sent [4446] bytes to clamd...
> Oct 23 14:05:07 tornado clamd[10873]: instream(192.168.44.25 at 59038): OK
> Oct 23 14:05:07 mail6 xm[18320]   x9ND4sM7022360: xm_scan(9600)  : 
> [192.34.61.247], clamd on IP [192.168.44.47] port [3313] replied 
> [stream: OK]
> Oct 23 14:05:07 mail6 xm[18320]   x9ND4sM7022360: xm_scan(9600)  : 
> [192.34.61.247], clamd on IP [192.168.44.47] port [3313] scanned 
> [4446] bytes in [0.195] seconds (22.819 kbytes/sec), nothing found in 
> entire_message
> Oct 23 14:05:07 mail6 sm-mta[22360] x9ND4sM8022360: Milter add: 
> header: X-Scanned-OK: extensible-milter version 6.842 using ClamAV 
> version [ClamAV 0.102.0-rc/25597/Wed Oct  9 09:39:14 2019], clamd on 
> IP [192.168.44.47] port [3313], [4446] bytes in [0.652s] at 2019-10-23 
> 13:05:07Z
> Oct 23 14:05:07 mail6 xm[18320]   x9ND4sM7022360: xm_scripts(): 
> [192.34.61.247] [eom] [ 56] MATCH (CONTINUE) eval(reciprule at line [ 
> 219]) time [0.056393s] [return "CONTINUE" 
> if(!(xm_blacklisted_envfrom($priv_data))...]
> Oct 23 14:05:07 mail6 xm[18320]   x9ND4sM7022360: xm_eom_callback(): 
> [192.34.61.247], [AS14061], return [SMFIS_CONTINUE]
> Oct 23 14:05:07 mail6 xm[18320] x9ND4sM7022360:                    
> xm_stats(): [192.34.61.247] +++++++ END EOM CALLBACK +++++++
> Oct 23 14:05:07 mail6 sm-mta[22360] x9ND4sM8022360: --- 250 2.0.0 
> x9ND4sM8022360 Message accepted for delivery
> Oct 23 14:05:07 mail6 sm-mta[22360] x9ND4sM9022360: <-- QUIT
> Oct 23 14:05:07 mail6 sm-mta[22360] x9ND4sM9022360: --- 221 2.0.0 
> mail6.jubileegroup.co.uk closing connection
> Oct 23 14:05:07 mail6 xm[18320]   x9ND4sM7022360: xm_close_callback(): 
> [192.34.61.247] now has [0] open connections to MTA
> Oct 23 14:05:07 mail6 xm[18320]   x9ND4sM7022360: xm_close_callback(): 
> [192.34.61.247], [AS14061], return [IGNORED_BY_SENDMAIL] [52]
> Oct 23 14:05:09 mail6 xm[18320]   x9ND4sM7022360: 
> xm_log_endex_message(): [192.34.61.247] +ENDEX US =AS14061 0m 14.51s 
> connect,260 mailmanlists.network P clamav@
> Oct 23 14:05:09 mail6 xm[18320] x9ND4sM7022360:                    
> xm_stats(): [192.34.61.247] +++++++ END CLOSE CALLBACK +++++++
> Oct 23 14:05:22 mail6 clamd[22369] on tornado: Pong
> Oct 23 14:06:22 mail6 clamd[22412] on tornado: Pong
> Oct 23 14:07:23 mail6 clamd[22430] on tornado: Pong
> Oct 23 14:08:22 mail6 clamd[22448] on tornado: Pong
> 8<-------------------------------------------------------------------------------------------------------------------------------------------- 
>
>
> I wonder if we should compare some configurations?
>
> Below I give the relevant part of the configuration file for the clamd
> daemon which logged the line in the above log extract which reads:
>
> "Oct 23 14:05:07 tornado clamd[10873]: instream(192.168.44.25 at 59038): OK"
>
> 8<----------------------------------------------------------------------
> # Use system logger (can work together with LogFile).
> # Default: no
> LogSyslog yes
> # Specify the type of syslog messages - please refer to 'man syslog'
> # for facility names.
> # Default: LOG_LOCAL6
> LogFacility LOG_MAIL
> 8<----------------------------------------------------------------------
>
> Does that help?
>
> I'm afraid the logging daemon configuration probably won't help you
> because the logging server here happens to be running rsyslog.  If it
> matters, the times are all BST (+0100).
>
The thing is, I do use 0.102.0 on my mail server with direct output to 
the clamd.log file. However, this is another matter on one of my 
workstations (see also the discussion at 17/10; clamonacc behaviour). It 
involves files/directories which are created but removed before 
clamonacc has passed the scan request to clamd.

I did leave the default for LogFacility and output to syslog, just like 
you did.
I switched from rsyslog to syslog-ng because of the uncomprehensible 
coding used in rsyslog.

Also a remark: I noticed you used 0.102.0-rc, I used the released 
version. Your listing shows the programs name, mine not. That's what 
makes it difficult to filter the correct messages.

Anyhow, I will setup things again in the next days and try again, just 
to see if I made a mistake somewhere.

To be continued...
Frans.