Millisecond issue on XM_GELF for parsing timestamp

Tags: GELF

#1 juvie

I am using nxLog CE as log shipper, but I found issue for GELP module with millisecond precision in time stamp. The millisecond precision is not added to timestamp (EventTime as well)
When I use gelf extension the millisecond precision is dropped. Basically although I have in log file something like this:
<br/>... <br/>2021-04-26T14:28:14.269+00:00 [sync_ldap_trigger.sh] [DEBUG] Get list of users from AD/LDAP successfully (with 1 records) <br/>... <br/>
and for parsing I am using REGEX for multi line detection. Doesn't matter if I am using parsing date function parsedate or strptime or nothing just pure $1
<br/>#Exec if $raw_event =~ %PEOSYNCREGEX% $EventTime = parsedate($1); $script = $2 ; $Severity = $3 ; $Message = $4 ; <br/>#Exec if $raw_event =~ %PEOSYNCREGEX% $EventTime = strptime($1, '%Y-%m-%d%t%H:%M:%S.%N%Z'); $script = $2 ; $Severity = $3 ; $Message = $4 ; <br/>Exec if $raw_event =~ %PEOSYNCREGEX% $EventTime = $1; $script = $2 ; $Severity = $3 ; $Message = $4 ; <br/>
I excluded "buffer" from path to be sure and all parsing are done in im_file section. For sure I am testing it with file output from the same source. But on the tcpdump I still have timestamp without the millisecond precision - which I confirmation form me that this information is lost on shipper site.

tcpdump detailed packet output:
<br/>CNSCNc@{"version":"1.1","_EventReceivedTime":"2021-04-26 14:32:15","_SourceModuleName":"peosynclog","_SourceModuleType":"im_file","_script":"sync_ldap_trigger.sh","_Severity":"DEBUG","_SyslogSeverityValue":7,"_FileName":"/home/adsync/bin/adsync2amish/log/sync_general.log","_order":"VNB","_environment":"TEST","host":"amishd-test.vnbrno.cz","short_message":"Get list of users from AD/LDAP successfully (with 1 records)","full_message":"Get list of users from AD/LDAP successfully (with 1 records)","timestamp":1619447535,"level":7} <br/>

nxlog.conf:
<br/>######################################## <br/># Global directives # <br/>######################################## <br/>User nxlog <br/>Group nxlog <br/>LogFile /var/log/nxlog/nxlog.log <br/>LogLevel INFO <br/># PeoSYNC <br/>define PEOSYNCREGEX /^(?<EventTime>\d{4}\-\d{2}\-\d{2}T\d{2}\:\d{2}\:\d{2}.\d{3}\+\d{4})[\ ,\t]*\[(?<Script>[\S,\.,\_]+)\][\ ,\t]*\[(?<Severity>[\S,\-,\ ]+)\][\ ,\t]*(?<Message>[\S,\s]*)/ <br/>define ROOT /var/spool/nxlog <br/>CacheDir %ROOT%/data <br/>SpoolDir %ROOT%/data <br/>######################################## <br/># Modules # <br/>######################################## <br/><Extension multilinepeosync> <br/> Module xm_multiline <br/> HeaderLine %PEOSYNCREGEX% <br/></Extension> <br/><Extension gelf> <br/> Module xm_gelf <br/></Extension> <br/>######################################## <br/># Inputs # <br/>######################################## <br/><Input peosynclog> <br/> Module im_file <br/> File "/home/adsync/bin/engine/log/sync_general.log" <br/> InputType multilinepeosync <br/> SavePos TRUE <br/> #Exec if $raw_event =~ %PEOSYNCREGEX% $EventTime = parsedate($1); $script = $2 ; $Severity = $3 ; $Message = $4 ; <br/> #Exec if $raw_event =~ %PEOSYNCREGEX% $EventTime = strptime($1, '%Y-%m-%d%t%H:%M:%S.%N%Z'); $script = $2 ; $Severity = $3 ; $Message = $4 ; <br/> Exec if $raw_event =~ %PEOSYNCREGEX% $EventTime = $1; $script = $2 ; $Severity = $3 ; $Message = $4 ; <br/> <Exec> <br/> if $Severity !~ /NEVERUSEDSTRING/ <br/> { <br/> if $Severity =~ /ALERT/ $SyslogSeverityValue = 1; <br/> if $Severity =~ /CRIT/ $SyslogSeverityValue = 2; <br/> if $Severity =~ /ERR/ $SyslogSeverityValue = 3; <br/> if $Severity =~ /WARN/ $SyslogSeverityValue = 4; <br/> if $Severity =~ /NOTICE/ $SyslogSeverityValue = 5; <br/> if $Severity =~ /INFO/ $SyslogSeverityValue = 6; <br/> if $Severity =~ /---/ $SyslogSeverityValue = 6; <br/> if $Severity =~ /SQL/ $SyslogSeverityValue = 7; <br/> if $Severity =~ /DEBUG/ $SyslogSeverityValue = 7; <br/> } else { <br/> # Parsing and dropping all messages which are NEVERUSEDSTRING (or INFO|DEBUG if you want change) severity <br/> drop(); <br/> } <br/> $FileName = file_name(); <br/> $Hostname = 'someserver-dev.loc'; <br/> $order = 'ORDER'; <br/> $environment = 'DEV'; <br/> # if not defined($EventTime) $EventTime = now(); <br/> </Exec> <br/></Input> <br/>######################################## <br/># Outputs # <br/>######################################## <br/><Output graylogtcppeosyncrewrite> <br/> Module om_tcp <br/> Host 127.0.0.1 <br/> Port 20228 <br/> OutputType GELF_TCP <br/></Output> <br/><Output file> <br/> Module om_file <br/> File "/tmp/sync_general.log" <br/></Output> <br/>######################################## <br/># Define Processor Modules # <br/>######################################## <br/><Processor bufferpeosync> <br/> Module pm_buffer <br/> MaxSize 524288 <br/> Type disk <br/> WarnLimit 393216 <br/></Processor> <br/>######################################## <br/># Routes # <br/>######################################## <br/><Route 1> <br/> #Path peosynclog => bufferpeosync => graylogtcppeosyncrewrite <br/> Path peosynclog => graylogtcppeosyncrewrite <br/></Route> <br/><Route 2> <br/> Path peosynclog => file <br/></Route> <br/>

Please anyone for help or solution for this issue.

Michal

BTW: Of course that I tried more format for timestamp as 2021-04-26T14:28:04.240+02:00 or 2021-04-26T14:28:04.240+0200 etc. The format in log is in my hands too.

#2 rafDeactivated Nxlog ✓
#1 juvie
I am using nxLog CE as log shipper, but I found issue for GELP module with millisecond precision in time stamp. The millisecond precision is not added to timestamp (EventTime as well) When I use gelf extension the millisecond precision is dropped. Basically although I have in log file something like this: <br/>... <br/>2021-04-26T14:28:14.269+00:00 [sync_ldap_trigger.sh] [DEBUG] Get list of users from AD/LDAP successfully (with 1 records) <br/>... <br/> and for parsing I am using REGEX for multi line detection. Doesn't matter if I am using parsing date function parsedate or strptime or nothing just pure $1 <br/>#Exec if $raw_event =~ %PEOSYNCREGEX% $EventTime = parsedate($1); $script = $2 ; $Severity = $3 ; $Message = $4 ; <br/>#Exec if $raw_event =~ %PEOSYNCREGEX% $EventTime = strptime($1, '%Y-%m-%d%t%H:%M:%S.%N%Z'); $script = $2 ; $Severity = $3 ; $Message = $4 ; <br/>Exec if $raw_event =~ %PEOSYNCREGEX% $EventTime = $1; $script = $2 ; $Severity = $3 ; $Message = $4 ; <br/> I excluded "buffer" from path to be sure and all parsing are done in im_file section. For sure I am testing it with file output from the same source. But on the tcpdump I still have timestamp without the millisecond precision - which I confirmation form me that this information is lost on shipper site. tcpdump detailed packet output: <br/>CNSCNc@{"version":"1.1","_EventReceivedTime":"2021-04-26 14:32:15","_SourceModuleName":"peosynclog","_SourceModuleType":"im_file","_script":"sync_ldap_trigger.sh","_Severity":"DEBUG","_SyslogSeverityValue":7,"_FileName":"/home/adsync/bin/adsync2amish/log/sync_general.log","_order":"VNB","_environment":"TEST","host":"amishd-test.vnbrno.cz","short_message":"Get list of users from AD/LDAP successfully (with 1 records)","full_message":"Get list of users from AD/LDAP successfully (with 1 records)","timestamp":1619447535,"level":7} <br/> nxlog.conf: <br/>######################################## <br/># Global directives # <br/>######################################## <br/>User nxlog <br/>Group nxlog <br/>LogFile /var/log/nxlog/nxlog.log <br/>LogLevel INFO <br/># PeoSYNC <br/>define PEOSYNCREGEX /^(?<EventTime>\d{4}\-\d{2}\-\d{2}T\d{2}\:\d{2}\:\d{2}.\d{3}\+\d{4})[\ ,\t]*\[(?<Script>[\S,\.,\_]+)\][\ ,\t]*\[(?<Severity>[\S,\-,\ ]+)\][\ ,\t]*(?<Message>[\S,\s]*)/ <br/>define ROOT /var/spool/nxlog <br/>CacheDir %ROOT%/data <br/>SpoolDir %ROOT%/data <br/>######################################## <br/># Modules # <br/>######################################## <br/><Extension multilinepeosync> <br/> Module xm_multiline <br/> HeaderLine %PEOSYNCREGEX% <br/></Extension> <br/><Extension gelf> <br/> Module xm_gelf <br/></Extension> <br/>######################################## <br/># Inputs # <br/>######################################## <br/><Input peosynclog> <br/> Module im_file <br/> File "/home/adsync/bin/engine/log/sync_general.log" <br/> InputType multilinepeosync <br/> SavePos TRUE <br/> #Exec if $raw_event =~ %PEOSYNCREGEX% $EventTime = parsedate($1); $script = $2 ; $Severity = $3 ; $Message = $4 ; <br/> #Exec if $raw_event =~ %PEOSYNCREGEX% $EventTime = strptime($1, '%Y-%m-%d%t%H:%M:%S.%N%Z'); $script = $2 ; $Severity = $3 ; $Message = $4 ; <br/> Exec if $raw_event =~ %PEOSYNCREGEX% $EventTime = $1; $script = $2 ; $Severity = $3 ; $Message = $4 ; <br/> <Exec> <br/> if $Severity !~ /NEVERUSEDSTRING/ <br/> { <br/> if $Severity =~ /ALERT/ $SyslogSeverityValue = 1; <br/> if $Severity =~ /CRIT/ $SyslogSeverityValue = 2; <br/> if $Severity =~ /ERR/ $SyslogSeverityValue = 3; <br/> if $Severity =~ /WARN/ $SyslogSeverityValue = 4; <br/> if $Severity =~ /NOTICE/ $SyslogSeverityValue = 5; <br/> if $Severity =~ /INFO/ $SyslogSeverityValue = 6; <br/> if $Severity =~ /---/ $SyslogSeverityValue = 6; <br/> if $Severity =~ /SQL/ $SyslogSeverityValue = 7; <br/> if $Severity =~ /DEBUG/ $SyslogSeverityValue = 7; <br/> } else { <br/> # Parsing and dropping all messages which are NEVERUSEDSTRING (or INFO|DEBUG if you want change) severity <br/> drop(); <br/> } <br/> $FileName = file_name(); <br/> $Hostname = 'someserver-dev.loc'; <br/> $order = 'ORDER'; <br/> $environment = 'DEV'; <br/> # if not defined($EventTime) $EventTime = now(); <br/> </Exec> <br/></Input> <br/>######################################## <br/># Outputs # <br/>######################################## <br/><Output graylogtcppeosyncrewrite> <br/> Module om_tcp <br/> Host 127.0.0.1 <br/> Port 20228 <br/> OutputType GELF_TCP <br/></Output> <br/><Output file> <br/> Module om_file <br/> File "/tmp/sync_general.log" <br/></Output> <br/>######################################## <br/># Define Processor Modules # <br/>######################################## <br/><Processor bufferpeosync> <br/> Module pm_buffer <br/> MaxSize 524288 <br/> Type disk <br/> WarnLimit 393216 <br/></Processor> <br/>######################################## <br/># Routes # <br/>######################################## <br/><Route 1> <br/> #Path peosynclog => bufferpeosync => graylogtcppeosyncrewrite <br/> Path peosynclog => graylogtcppeosyncrewrite <br/></Route> <br/><Route 2> <br/> Path peosynclog => file <br/></Route> <br/> Please anyone for help or solution for this issue. Michal BTW: Of course that I tried more format for timestamp as 2021-04-26T14:28:04.240+02:00 or 2021-04-26T14:28:04.240+0200 etc. The format in log is in my hands too.

Hi Michal,

Thanks for sharing your observations.

I'll try to reproduce your problem, and share the outcomes with you.

Best regards,
Rafal