[clamav-users] log representation -SOLVED

Frans de Boer frans at fransdb.nl
Thu Oct 24 07:03:35 EDT 2019


On 23-10-2019 20:35, Frans de Boer wrote:
> 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. 

I found that I could force the output to syslog-ng by adding the line 
StandardOutput=journal - as well as StandardError =journal - and use 
filtering in syslog-ng to drop unwanted messages.

Mind you, this works only with systemd 232+

Now all the output of the ClamAV suite is routed and where needed 
filtered to and by syslog-ng and still have separate log files.

--- Frans.



More information about the clamav-users mailing list