Mailing List Archive

It is just returning the subsecond *part* of the timestamp.

So while 9:13:14.123 is "higher" than 8:13:14.567, the subsecond part of
the later (567) is higher than the subsecond part of the earlier (123).

It is important that you are extracting a partial timestamp, which also
implies that this is no longer monotonically increasing. Actually, it no
longer has any sense of "timing" at all. This is NOT the timestamp
converted to nanoseconds (or whatever).

I hope this clarifies, if not, keep posting ;)

Rainer

> -----Original Message-----
> From: rsyslog-bounces@lists.adiscon.com [mailto:rsyslog-
> bounces@lists.adiscon.com] On Behalf Of Luigi Perroti
> Sent: Wednesday, October 01, 2008 10:58 AM
> To: rsyslog@lists.adiscon.com
> Subject: [rsyslog] Subseconds in timereported and timegenerated
>
> Hi,
>
> I'd like to ask if it's normal that %timegenerated:::date-subseconds%
> returns a value lower than %timereported:::date-subseconds%.
>
> Intuitively I'd say it is since this makes sense by taking in
> consideration the property names.
> Still, since the documentation says that timegenerated is the
> timestamp when the message was received I would have expected a value
> higher than the one returned by timereported.
>
> I'm afraid this is a dumb question but this behaviour got me confused,
> if anyone could shed some light on this I'd be grateful. Thanks.
>
> Regards,
> Luigi
> _______________________________________________
> rsyslog mailing list
> http://lists.adiscon.net/mailman/listinfo/rsyslog
> http://www.rsyslog.com
_______________________________________________
rsyslog mailing list
http://lists.adiscon.net/mailman/listinfo/rsyslog
http://www.rsyslog.com

Thanks for the thorough explanation but I'm afraid that I still don't
understand why I'm seeing this:

http://imagebin.ca/view/2EknmP0.html

This is how the columns are populated:
sent <- %timereported:::date-mysql%
sent_subseconds <- %timereported:::date-subseconds%
received_by_rsyslog <- %timegenerated:::date-mysql%
received_subseconds <- %timegenerated:::date-subseconds%

Most probably I didn't get the difference between timereported and
timegenerated.
Meaning that I should just switch the sent* and received* columns and
that nothing is wrong with Rsyslog.

I'd be great if you could could confirm this scenario, thanks for your time!

Regards,
Luigi
_______________________________________________
rsyslog mailing list
http://lists.adiscon.net/mailman/listinfo/rsyslog
http://www.rsyslog.com

Just a quick note while working on a bigger thing: Is the sent timestamp
form an instance that received data via the network (data that contained
a high-precision timestamp). Also, which version are you using?

Rainer



> -----Original Message-----
> From: rsyslog-bounces@lists.adiscon.com [mailto:rsyslog-
> bounces@lists.adiscon.com] On Behalf Of Luigi Perroti
> Sent: Wednesday, October 01, 2008 12:01 PM
> To: rsyslog-users
> Subject: Re: [rsyslog] Subseconds in timereported and timegenerated
>
> Thanks for the thorough explanation but I'm afraid that I still don't
> understand why I'm seeing this:
>
> http://imagebin.ca/view/2EknmP0.html
>
> This is how the columns are populated:
> sent <- %timereported:::date-mysql%
> sent_subseconds <- %timereported:::date-subseconds%
> received_by_rsyslog <- %timegenerated:::date-mysql%
> received_subseconds <- %timegenerated:::date-subseconds%
>
> Most probably I didn't get the difference between timereported and
> timegenerated.
> Meaning that I should just switch the sent* and received* columns and
> that nothing is wrong with Rsyslog.
>
> I'd be great if you could could confirm this scenario, thanks for your
> time!
>
> Regards,
> Luigi
> _______________________________________________
> rsyslog mailing list
> http://lists.adiscon.net/mailman/listinfo/rsyslog
> http://www.rsyslog.com
_______________________________________________
rsyslog mailing list
http://lists.adiscon.net/mailman/listinfo/rsyslog
http://www.rsyslog.com

Here's a better screenshot:
http://imagebin.ca/view/8p8hSnT.html

Everything is happening on the same machine.
I have these modules loaded: imfile, imuxsock, imklog, ommysql.
The php-fpm entries are read from a log file by imfile.

Right now I'm trying out 3.21.5 but I think I had already seen this
behaviour on 3.21.3 but I'm not too sure about the version number.

Luigi

On 10/1/08, Rainer Gerhards <rgerhards@hq.adiscon.com> wrote:
> Just a quick note while working on a bigger thing: Is the sent timestamp
> form an instance that received data via the network (data that contained
> a high-precision timestamp). Also, which version are you using?
>
> Rainer
>
>
>
>> -----Original Message-----
>> From: rsyslog-bounces@lists.adiscon.com [mailto:rsyslog-
>> bounces@lists.adiscon.com] On Behalf Of Luigi Perroti
>> Sent: Wednesday, October 01, 2008 12:01 PM
>> To: rsyslog-users
>> Subject: Re: [rsyslog] Subseconds in timereported and timegenerated
>>
>> Thanks for the thorough explanation but I'm afraid that I still don't
>> understand why I'm seeing this:
>>
>> http://imagebin.ca/view/2EknmP0.html
>>
>> This is how the columns are populated:
>> sent <- %timereported:::date-mysql%
>> sent_subseconds <- %timereported:::date-subseconds%
>> received_by_rsyslog <- %timegenerated:::date-mysql%
>> received_subseconds <- %timegenerated:::date-subseconds%
>>
>> Most probably I didn't get the difference between timereported and
>> timegenerated.
>> Meaning that I should just switch the sent* and received* columns and
>> that nothing is wrong with Rsyslog.
>>
>> I'd be great if you could could confirm this scenario, thanks for your
>> time!
>>
>> Regards,
>> Luigi
>> _______________________________________________
>> rsyslog mailing list
>> http://lists.adiscon.net/mailman/listinfo/rsyslog
>> http://www.rsyslog.com
> _______________________________________________
> rsyslog mailing list
> http://lists.adiscon.net/mailman/listinfo/rsyslog
> http://www.rsyslog.com
>
_______________________________________________
rsyslog mailing list
http://lists.adiscon.net/mailman/listinfo/rsyslog
http://www.rsyslog.com

Please post your config, that makes it easier for me ;). I think I know
where this stems back from - we had two time calls inside rsyslog done,
which has been removed in the experimental "perf" git branch.

Rainer

> -----Original Message-----
> From: rsyslog-bounces@lists.adiscon.com [mailto:rsyslog-
> bounces@lists.adiscon.com] On Behalf Of Luigi Perroti
> Sent: Wednesday, October 01, 2008 12:22 PM
> To: rsyslog-users
> Subject: Re: [rsyslog] Subseconds in timereported and timegenerated
>
> Here's a better screenshot:
> http://imagebin.ca/view/8p8hSnT.html
>
> Everything is happening on the same machine.
> I have these modules loaded: imfile, imuxsock, imklog, ommysql.
> The php-fpm entries are read from a log file by imfile.
>
> Right now I'm trying out 3.21.5 but I think I had already seen this
> behaviour on 3.21.3 but I'm not too sure about the version number.
>
> Luigi
>
> On 10/1/08, Rainer Gerhards <rgerhards@hq.adiscon.com> wrote:
> > Just a quick note while working on a bigger thing: Is the sent
> timestamp
> > form an instance that received data via the network (data that
> contained
> > a high-precision timestamp). Also, which version are you using?
> >
> > Rainer
> >
> >
> >
> >> -----Original Message-----
> >> From: rsyslog-bounces@lists.adiscon.com [mailto:rsyslog-
> >> bounces@lists.adiscon.com] On Behalf Of Luigi Perroti
> >> Sent: Wednesday, October 01, 2008 12:01 PM
> >> To: rsyslog-users
> >> Subject: Re: [rsyslog] Subseconds in timereported and timegenerated
> >>
> >> Thanks for the thorough explanation but I'm afraid that I still
> don't
> >> understand why I'm seeing this:
> >>
> >> http://imagebin.ca/view/2EknmP0.html
> >>
> >> This is how the columns are populated:
> >> sent <- %timereported:::date-mysql%
> >> sent_subseconds <- %timereported:::date-subseconds%
> >> received_by_rsyslog <- %timegenerated:::date-mysql%
> >> received_subseconds <- %timegenerated:::date-subseconds%
> >>
> >> Most probably I didn't get the difference between timereported and
> >> timegenerated.
> >> Meaning that I should just switch the sent* and received* columns
> and
> >> that nothing is wrong with Rsyslog.
> >>
> >> I'd be great if you could could confirm this scenario, thanks for
> your
> >> time!
> >>
> >> Regards,
> >> Luigi
> >> _______________________________________________
> >> rsyslog mailing list
> >> http://lists.adiscon.net/mailman/listinfo/rsyslog
> >> http://www.rsyslog.com
> > _______________________________________________
> > rsyslog mailing list
> > http://lists.adiscon.net/mailman/listinfo/rsyslog
> > http://www.rsyslog.com
> >
> _______________________________________________
> rsyslog mailing list
> http://lists.adiscon.net/mailman/listinfo/rsyslog
> http://www.rsyslog.com
_______________________________________________
rsyslog mailing list
http://lists.adiscon.net/mailman/listinfo/rsyslog
http://www.rsyslog.com

Here it is:

$ModLoad imfile
$ModLoad imuxsock
$ModLoad imklog
$ModLoad ommysql
$ActionOmmysqlServerPort 1234

$MaxMessageSize 8k

$EscapeControlCharactersOnReceive off

$FileOwner root
$FileGroup root
$FileCreateMode 0600

$InputFileName /path/to/log/php-fpm.log
$InputFileTag php-fpm
$InputFileStateFile php-fpm.state
$InputFileSeverity notice
$InputFileFacility local5
$InputRunFileMonitor

$MainMsgQueueType LinkedList
$MainMsgQueueSize 20000
$MainMsgQueueFileName main-spool
$MainMsgQueueMaxDiskSpace 200M
$MainMsgQueueWorkerThreadMinimumMessages 2500
$MainMsgQueueWorkerThreads 1
$MainMsgQueueWorkerTimeoutThreadShutdown 10000
$MainMsgQueueSaveOnShutdown on

$template my-rsyslog-schema,"insert into messages(hostname, sent,
sent_subseconds, received_by_rsyslog, received_subseconds, process,
facility, severity, message) values ('%hostname%',
'%timereported:::date-mysql%', %timereported:::date-subseconds%,
'%timegenerated:::date-mysql%', %timegenerated:::date-subseconds%,
'%programname%', '%syslogfacility-text%', '%syslogseverity-text%',
'%msg%')",sql

*.* :ommysql:127.0.0.1,rsyslog,rsyslog_user,password;my-rsyslog-schema
_______________________________________________
rsyslog mailing list
http://lists.adiscon.net/mailman/listinfo/rsyslog
http://www.rsyslog.com

Thanks, this is useful and helps understanding what is going on. I think
what you see is an artifact of the two time() calls I mentioned. To
verify, I'd appreciate if you could try out the latest from the perf
branch, which can be found here:

http://git.adiscon.com/?p=rsyslog.git;a=snapshot;h=1531c541b294b6c029e5de9a01d4d8499f7e4718;sf=tgz

Note that you need to setup the build environment (quite easy, but you
need to know). Details at:

http://www.rsyslog.com/doc-build_from_repo.html

These two timestamps, for internally generated sources, should be the
same in that version.

Note, however, that, for externally generated messages, timereceived is
whatever is recorded inside the message. There are various reasons for
this not being correct, clock skew being a highly probably cause (which
is also often found).

HTH
Rainer

On Wed, 2008-10-01 at 12:37 +0200, Luigi Perroti wrote:
> Here it is:
>
> $ModLoad imfile
> $ModLoad imuxsock
> $ModLoad imklog
> $ModLoad ommysql
> $ActionOmmysqlServerPort 1234
>
> $MaxMessageSize 8k
>
> $EscapeControlCharactersOnReceive off
>
> $FileOwner root
> $FileGroup root
> $FileCreateMode 0600
>
> $InputFileName /path/to/log/php-fpm.log
> $InputFileTag php-fpm
> $InputFileStateFile php-fpm.state
> $InputFileSeverity notice
> $InputFileFacility local5
> $InputRunFileMonitor
>
> $MainMsgQueueType LinkedList
> $MainMsgQueueSize 20000
> $MainMsgQueueFileName main-spool
> $MainMsgQueueMaxDiskSpace 200M
> $MainMsgQueueWorkerThreadMinimumMessages 2500
> $MainMsgQueueWorkerThreads 1
> $MainMsgQueueWorkerTimeoutThreadShutdown 10000
> $MainMsgQueueSaveOnShutdown on
>
> $template my-rsyslog-schema,"insert into messages(hostname, sent,
> sent_subseconds, received_by_rsyslog, received_subseconds, process,
> facility, severity, message) values ('%hostname%',
> '%timereported:::date-mysql%', %timereported:::date-subseconds%,
> '%timegenerated:::date-mysql%', %timegenerated:::date-subseconds%,
> '%programname%', '%syslogfacility-text%', '%syslogseverity-text%',
> '%msg%')",sql
>
> *.* :ommysql:127.0.0.1,rsyslog,rsyslog_user,password;my-rsyslog-schema
> _______________________________________________
> rsyslog mailing list
> http://lists.adiscon.net/mailman/listinfo/rsyslog
> http://www.rsyslog.com

_______________________________________________
rsyslog mailing list
http://lists.adiscon.net/mailman/listinfo/rsyslog
http://www.rsyslog.com

I installed the snapshot but apparently the issue persists.

If there's something else that I can do, now or when you have more
time, let me know.

Regards,
Luigi
_______________________________________________
rsyslog mailing list
http://lists.adiscon.net/mailman/listinfo/rsyslog
http://www.rsyslog.com

On Wed, 2008-10-01 at 14:09 +0200, Luigi Perroti wrote:
> I installed the snapshot but apparently the issue persists.
>
> If there's something else that I can do, now or when you have more
> time, let me know.

That's interesting. Could you please get me a debug log (you can mail it
privately). Here is info about how to do that:

http://www.rsyslog.com/doc-troubleshoot.html

Rainer

_______________________________________________
rsyslog mailing list
http://lists.adiscon.net/mailman/listinfo/rsyslog
http://www.rsyslog.com

Thanks to the debug data provided, I could find out that the timestamps
stem back to imfile and the way (sequence) in which it generates the
timestamps. I will take the opportunity and fix it in a way that also
improves performance. I just thought I let you know, more info follows
when I have written the fix.

Rainer

> -----Original Message-----
> From: rsyslog-bounces@lists.adiscon.com [mailto:rsyslog-
> bounces@lists.adiscon.com] On Behalf Of Luigi Perroti
> Sent: Wednesday, October 01, 2008 2:10 PM
> To: rsyslog-users
> Subject: Re: [rsyslog] Subseconds in timereported and timegenerated
>
> I installed the snapshot but apparently the issue persists.
>
> If there's something else that I can do, now or when you have more
> time, let me know.
>
> Regards,
> Luigi
> _______________________________________________
> rsyslog mailing list
> http://lists.adiscon.net/mailman/listinfo/rsyslog
> http://www.rsyslog.com
_______________________________________________
rsyslog mailing list
http://lists.adiscon.net/mailman/listinfo/rsyslog
http://www.rsyslog.com

I (think) I have now fixed it, but not verified all cases. I would
appreciate if you could give the new snapshot a try:

http://git.adiscon.com/?p=rsyslog.git;a=snapshot;h=39000a62024510cd62607
200e6100e3cd7c05005;sf=tgz

Rainer

> -----Original Message-----
> From: rsyslog-bounces@lists.adiscon.com [mailto:rsyslog-
> bounces@lists.adiscon.com] On Behalf Of Rainer Gerhards
> Sent: Thursday, October 02, 2008 3:15 PM
> To: rsyslog-users
> Subject: Re: [rsyslog] Subseconds in timereported and timegenerated
>
> Thanks to the debug data provided, I could find out that the
timestamps
> stem back to imfile and the way (sequence) in which it generates the
> timestamps. I will take the opportunity and fix it in a way that also
> improves performance. I just thought I let you know, more info follows
> when I have written the fix.
>
> Rainer
>
> > -----Original Message-----
> > From: rsyslog-bounces@lists.adiscon.com [mailto:rsyslog-
> > bounces@lists.adiscon.com] On Behalf Of Luigi Perroti
> > Sent: Wednesday, October 01, 2008 2:10 PM
> > To: rsyslog-users
> > Subject: Re: [rsyslog] Subseconds in timereported and timegenerated
> >
> > I installed the snapshot but apparently the issue persists.
> >
> > If there's something else that I can do, now or when you have more
> > time, let me know.
> >
> > Regards,
> > Luigi
> > _______________________________________________
> > rsyslog mailing list
> > http://lists.adiscon.net/mailman/listinfo/rsyslog
> > http://www.rsyslog.com
> _______________________________________________
> rsyslog mailing list
> http://lists.adiscon.net/mailman/listinfo/rsyslog
> http://www.rsyslog.com
_______________________________________________
rsyslog mailing list
http://lists.adiscon.net/mailman/listinfo/rsyslog
http://www.rsyslog.com

Everything's fine here. Now I get the same subsecond part for all the events.
This is how it should be since they are being generated on the same host.

If it's of relevance I'm using these modules:
imfile, imuxsock, imklog, ommysql.
I'm also listening on a couple of additional unix sockets.
Everything seems to be working fine.

Thanks for the quick turnaround.

Regards,
Luigi
_______________________________________________
rsyslog mailing list
http://lists.adiscon.net/mailman/listinfo/rsyslog
http://www.rsyslog.com

Excellent, thanks for the confirmation. The modules are no longer
relevant, they all get the time from a consistent call now (not doing
this was part of the problem, if not the whole ;)).

Rainer

> -----Original Message-----
> From: rsyslog-bounces@lists.adiscon.com [mailto:rsyslog-
> bounces@lists.adiscon.com] On Behalf Of Luigi Perroti
> Sent: Friday, October 03, 2008 5:01 PM
> To: rsyslog-users
> Subject: Re: [rsyslog] Subseconds in timereported and timegenerated
>
> Everything's fine here. Now I get the same subsecond part for all the
> events.
> This is how it should be since they are being generated on the same
> host.
>
> If it's of relevance I'm using these modules:
> imfile, imuxsock, imklog, ommysql.
> I'm also listening on a couple of additional unix sockets.
> Everything seems to be working fine.
>
> Thanks for the quick turnaround.
>
> Regards,
> Luigi
> _______________________________________________
> rsyslog mailing list
> http://lists.adiscon.net/mailman/listinfo/rsyslog
> http://www.rsyslog.com
_______________________________________________
rsyslog mailing list
http://lists.adiscon.net/mailman/listinfo/rsyslog
http://www.rsyslog.com