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:
```
...
2021-04-26T14:28:14.269+00:00 [sync_ldap_trigger.sh] [DEBUG] Get list of users from AD/LDAP successfully (with 1 records)
...
```
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
```
#Exec if $raw_event =~ %PEOSYNCREGEX% $EventTime = parsedate($1); $script = $2 ; $Severity = $3 ; $Message = $4 ;
#Exec if $raw_event =~ %PEOSYNCREGEX% $EventTime = strptime($1, '%Y-%m-%d%t%H:%M:%S.%N%Z'); $script = $2 ; $Severity = $3 ; $Message = $4 ;
Exec if $raw_event =~ %PEOSYNCREGEX% $EventTime = $1; $script = $2 ; $Severity = $3 ; $Message = $4 ;
```
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:_
```
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}
```
_nxlog.conf:_
```
########################################
# Global directives #
########################################
User nxlog
Group nxlog
LogFile /var/log/nxlog/nxlog.log
LogLevel INFO
# PeoSYNC
define PEOSYNCREGEX /^(?\d{4}\-\d{2}\-\d{2}T\d{2}\:\d{2}\:\d{2}.\d{3}\+\d{4})[\ ,\t]*\[(?[\S,\.,\_]+)\][\ ,\t]*\[(?[\S,\-,\ ]+)\][\ ,\t]*(?[\S,\s]*)/
define ROOT /var/spool/nxlog
CacheDir %ROOT%/data
SpoolDir %ROOT%/data
########################################
# Modules #
########################################
Module xm_multiline
HeaderLine %PEOSYNCREGEX%
Module xm_gelf
########################################
# Inputs #
########################################
Module im_file
File "/home/adsync/bin/engine/log/sync_general.log"
InputType multilinepeosync
SavePos TRUE
#Exec if $raw_event =~ %PEOSYNCREGEX% $EventTime = parsedate($1); $script = $2 ; $Severity = $3 ; $Message = $4 ;
#Exec if $raw_event =~ %PEOSYNCREGEX% $EventTime = strptime($1, '%Y-%m-%d%t%H:%M:%S.%N%Z'); $script = $2 ; $Severity = $3 ; $Message = $4 ;
Exec if $raw_event =~ %PEOSYNCREGEX% $EventTime = $1; $script = $2 ; $Severity = $3 ; $Message = $4 ;
if $Severity !~ /NEVERUSEDSTRING/
{
if $Severity =~ /ALERT/ $SyslogSeverityValue = 1;
if $Severity =~ /CRIT/ $SyslogSeverityValue = 2;
if $Severity =~ /ERR/ $SyslogSeverityValue = 3;
if $Severity =~ /WARN/ $SyslogSeverityValue = 4;
if $Severity =~ /NOTICE/ $SyslogSeverityValue = 5;
if $Severity =~ /INFO/ $SyslogSeverityValue = 6;
if $Severity =~ /---/ $SyslogSeverityValue = 6;
if $Severity =~ /SQL/ $SyslogSeverityValue = 7;
if $Severity =~ /DEBUG/ $SyslogSeverityValue = 7;
} else {
# Parsing and dropping all messages which are NEVERUSEDSTRING (or INFO|DEBUG if you want change) severity
drop();
}
$FileName = file_name();
$Hostname = 'someserver-dev.loc';
$order = 'ORDER';
$environment = 'DEV';
# if not defined($EventTime) $EventTime = now();
########################################
# Outputs #
########################################
Module om_tcp
Host 127.0.0.1
Port 20228
OutputType GELF_TCP
Module om_file
File "/tmp/sync_general.log"
########################################
# Define Processor Modules #
########################################
Module pm_buffer
MaxSize 524288
Type disk
WarnLimit 393216
########################################
# Routes #
########################################
#Path peosynclog => bufferpeosync => graylogtcppeosyncrewrite
Path peosynclog => graylogtcppeosyncrewrite
Path peosynclog => file
```
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.
When I use gelf extension the millisecond precision is dropped. Basically although I have in log file something like this:
```
...
2021-04-26T14:28:14.269+00:00 [sync_ldap_trigger.sh] [DEBUG] Get list of users from AD/LDAP successfully (with 1 records)
...
```
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
```
#Exec if $raw_event =~ %PEOSYNCREGEX% $EventTime = parsedate($1); $script = $2 ; $Severity = $3 ; $Message = $4 ;
#Exec if $raw_event =~ %PEOSYNCREGEX% $EventTime = strptime($1, '%Y-%m-%d%t%H:%M:%S.%N%Z'); $script = $2 ; $Severity = $3 ; $Message = $4 ;
Exec if $raw_event =~ %PEOSYNCREGEX% $EventTime = $1; $script = $2 ; $Severity = $3 ; $Message = $4 ;
```
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:_
```
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}
```
_nxlog.conf:_
```
########################################
# Global directives #
########################################
User nxlog
Group nxlog
LogFile /var/log/nxlog/nxlog.log
LogLevel INFO
# PeoSYNC
define PEOSYNCREGEX /^(?\d{4}\-\d{2}\-\d{2}T\d{2}\:\d{2}\:\d{2}.\d{3}\+\d{4})[\ ,\t]*\[(?[\S,\.,\_]+)\][\ ,\t]*\[(?[\S,\-,\ ]+)\][\ ,\t]*(?[\S,\s]*)/
define ROOT /var/spool/nxlog
CacheDir %ROOT%/data
SpoolDir %ROOT%/data
########################################
# Modules #
########################################
Module xm_multiline
HeaderLine %PEOSYNCREGEX%
Module xm_gelf
########################################
# Inputs #
########################################
Module im_file
File "/home/adsync/bin/engine/log/sync_general.log"
InputType multilinepeosync
SavePos TRUE
#Exec if $raw_event =~ %PEOSYNCREGEX% $EventTime = parsedate($1); $script = $2 ; $Severity = $3 ; $Message = $4 ;
#Exec if $raw_event =~ %PEOSYNCREGEX% $EventTime = strptime($1, '%Y-%m-%d%t%H:%M:%S.%N%Z'); $script = $2 ; $Severity = $3 ; $Message = $4 ;
Exec if $raw_event =~ %PEOSYNCREGEX% $EventTime = $1; $script = $2 ; $Severity = $3 ; $Message = $4 ;
if $Severity !~ /NEVERUSEDSTRING/
{
if $Severity =~ /ALERT/ $SyslogSeverityValue = 1;
if $Severity =~ /CRIT/ $SyslogSeverityValue = 2;
if $Severity =~ /ERR/ $SyslogSeverityValue = 3;
if $Severity =~ /WARN/ $SyslogSeverityValue = 4;
if $Severity =~ /NOTICE/ $SyslogSeverityValue = 5;
if $Severity =~ /INFO/ $SyslogSeverityValue = 6;
if $Severity =~ /---/ $SyslogSeverityValue = 6;
if $Severity =~ /SQL/ $SyslogSeverityValue = 7;
if $Severity =~ /DEBUG/ $SyslogSeverityValue = 7;
} else {
# Parsing and dropping all messages which are NEVERUSEDSTRING (or INFO|DEBUG if you want change) severity
drop();
}
$FileName = file_name();
$Hostname = 'someserver-dev.loc';
$order = 'ORDER';
$environment = 'DEV';
# if not defined($EventTime) $EventTime = now();
########################################
# Outputs #
########################################
Module om_tcp
Host 127.0.0.1
Port 20228
OutputType GELF_TCP
Module om_file
File "/tmp/sync_general.log"
########################################
# Define Processor Modules #
########################################
Module pm_buffer
MaxSize 524288
Type disk
WarnLimit 393216
########################################
# Routes #
########################################
#Path peosynclog => bufferpeosync => graylogtcppeosyncrewrite
Path peosynclog => graylogtcppeosyncrewrite
Path peosynclog => file
```
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.
#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:
```
...
2021-04-26T14:28:14.269+00:00 [sync_ldap_trigger.sh] [DEBUG] Get list of users from AD/LDAP successfully (with 1 records)
...
```
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
```
#Exec if $raw_event =~ %PEOSYNCREGEX% $EventTime = parsedate($1); $script = $2 ; $Severity = $3 ; $Message = $4 ;
#Exec if $raw_event =~ %PEOSYNCREGEX% $EventTime = strptime($1, '%Y-%m-%d%t%H:%M:%S.%N%Z'); $script = $2 ; $Severity = $3 ; $Message = $4 ;
Exec if $raw_event =~ %PEOSYNCREGEX% $EventTime = $1; $script = $2 ; $Severity = $3 ; $Message = $4 ;
```
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:_
```
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}
```
_nxlog.conf:_
```
########################################
# Global directives #
########################################
User nxlog
Group nxlog
LogFile /var/log/nxlog/nxlog.log
LogLevel INFO
# PeoSYNC
define PEOSYNCREGEX /^(?\d{4}\-\d{2}\-\d{2}T\d{2}\:\d{2}\:\d{2}.\d{3}\+\d{4})[\ ,\t]*\[(?[\S,\.,\_]+)\][\ ,\t]*\[(?[\S,\-,\ ]+)\][\ ,\t]*(?[\S,\s]*)/
define ROOT /var/spool/nxlog
CacheDir %ROOT%/data
SpoolDir %ROOT%/data
########################################
# Modules #
########################################
Module xm_multiline
HeaderLine %PEOSYNCREGEX%
Module xm_gelf
########################################
# Inputs #
########################################
Module im_file
File "/home/adsync/bin/engine/log/sync_general.log"
InputType multilinepeosync
SavePos TRUE
#Exec if $raw_event =~ %PEOSYNCREGEX% $EventTime = parsedate($1); $script = $2 ; $Severity = $3 ; $Message = $4 ;
#Exec if $raw_event =~ %PEOSYNCREGEX% $EventTime = strptime($1, '%Y-%m-%d%t%H:%M:%S.%N%Z'); $script = $2 ; $Severity = $3 ; $Message = $4 ;
Exec if $raw_event =~ %PEOSYNCREGEX% $EventTime = $1; $script = $2 ; $Severity = $3 ; $Message = $4 ;
if $Severity !~ /NEVERUSEDSTRING/
{
if $Severity =~ /ALERT/ $SyslogSeverityValue = 1;
if $Severity =~ /CRIT/ $SyslogSeverityValue = 2;
if $Severity =~ /ERR/ $SyslogSeverityValue = 3;
if $Severity =~ /WARN/ $SyslogSeverityValue = 4;
if $Severity =~ /NOTICE/ $SyslogSeverityValue = 5;
if $Severity =~ /INFO/ $SyslogSeverityValue = 6;
if $Severity =~ /---/ $SyslogSeverityValue = 6;
if $Severity =~ /SQL/ $SyslogSeverityValue = 7;
if $Severity =~ /DEBUG/ $SyslogSeverityValue = 7;
} else {
# Parsing and dropping all messages which are NEVERUSEDSTRING (or INFO|DEBUG if you want change) severity
drop();
}
$FileName = file_name();
$Hostname = 'someserver-dev.loc';
$order = 'ORDER';
$environment = 'DEV';
# if not defined($EventTime) $EventTime = now();
########################################
# Outputs #
########################################
Module om_tcp
Host 127.0.0.1
Port 20228
OutputType GELF_TCP
Module om_file
File "/tmp/sync_general.log"
########################################
# Define Processor Modules #
########################################
Module pm_buffer
MaxSize 524288
Type disk
WarnLimit 393216
########################################
# Routes #
########################################
#Path peosynclog => bufferpeosync => graylogtcppeosyncrewrite
Path peosynclog => graylogtcppeosyncrewrite
Path peosynclog => file
```
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