[clamav-users] log representation -SOLVED
Frans de Boer
frans at fransdb.nl
Thu Oct 24 11:03:35 UTC 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