timegenerated vs timereported

General discussions here

Moderator: rgerhards

Google Ads


timegenerated vs timereported

Postby user23235 » Tue Apr 25, 2017 1:05 am

I have one host sending syslog messages to another host using the @@ syntax. I notice that the timestamp on the receiving side is incorrect. The setup is like this:

Host A, timezone is UTC. Time in seconds since epoch is correct. rsyslog sends messages to Host B via '*.* @@hostb'
Host B, timezone is PDT. Time in seconds since epoch is correct.

I use the following template on Host B to log messages:
Code: Select all
template(name="useformat" type="list"){
  property(name="timegenerated" dateFormat="unixtimestamp")
  constant(value=" ")
  property(name="timestamp" dateFormat="unixtimestamp")
  constant(value=" ")


I have verified that both Host A and B see the same number of seconds since the epoch by using 'date "+%s"'

And on Host B I see this in the logfile for events generated on Host A
Code: Select all
1493077223 1493102423

The seconds for 'timestamp' is 7 hours ahead 'timegenerated', exactly the timezone difference between UTC and PDT, but as long as all the machines are synchronized to the same time they should report the same number of seconds since the epoch. Why is the timestamp seconds 7 hours ahead of its timegenerated couterpart?

The documentation for the time* properties is:

timegenerated
timestamp when the message was RECEIVED. Always in high resolution
timereported
timestamp from the message. Resolution depends on what was provided in the message (in most cases, only seconds)

These properties could be clarified a bit. What is meant by 'RECEIVED' exactly for timegenerated? Is it the time that the first rsyslog server receives the message, or the time the last rsyslog server receives the message? Do all rsyslog servers add in their own timestamp to a message before sending it off?
For timereported, is that time applied to the message by the application that created the message? Meaning, if I do 'logger test' that 'logger' is the one creating the message and therefore it will apply the current time to it?

I think I only want to care about 'timereported' because I don't care about any delays in how long it takes the message from being originally created to when it ends up at its final destination (possibly through multiple rsyslog servers), but right now that time is incorrect.

Both Host A and B are running rsyslog 8.16.0 on ubuntu 16.04.
user23235
New
 
Posts: 2
Joined: Tue Apr 25, 2017 12:49 am

Urgent Question?

  • Pulling out your Hair?
  • Wasting Time and Money?
  • Deadline Approaching?

Re: timegenerated vs timereported

Postby dlang » Tue Apr 25, 2017 1:20 am

received is when this instance of rsyslog received the message
reported is the timestamp in the text of the message as decoded by rsyslog

if you are relaying a message, the second server has no way of knowing when the first server received the message (unless that first server modifies the message to add the data somewhere), it can only know what's in the message or what it knows internally.

As for your question of why timereported and timereceived are different, we would need t see the rawmsg format to see what actually arrives at the box to tell.
dlang
Frequent Poster
 
Posts: 1001
Joined: Mon Sep 15, 2008 7:44 am

Re: timegenerated vs timereported

Postby user23235 » Tue Apr 25, 2017 1:39 am

I tried using printing the output of the 'rawmsg' property but it did not contain very much information.
Code: Select all
<38>Apr 25 00:29:36 testhost1 sshd[12603]: Disconnecting: Too many authentication failures [preauth]

Here is the output of 'jsonmesg' though
Code: Select all
{ "msg": " Disconnecting: Too many authentication failures [preauth]", "rawmsg": "<38>Apr 25 00:29:36 testhost1 sshd[12603]: Disconnecting: Too many authentication failures [preauth]", "timereported": "2017-04-25T00:29:36-07:00", "hostname": "testhost1", "syslogtag": "sshd[12603]:", "inputname": "imtcp", "fromhost": "localhost", "fromhost-ip": "127.0.0.1", "pri": "38", "syslogfacility": "4", "syslogseverity": "6", "timegenerated": "2017-04-24T17:29:36.489631-07:00", "programname": "sshd", "protocol-version": "0", "structured-data": "-", "app-name": "sshd", "procid": "12603", "msgid": "-", "uuid": null, "$!": null }


I noticed that if I modify the timezone on Host A that I could change the timereported time that shows up in Host B.
With a timezone of UTC, Host B will show a +7 hour difference between timereported - timegenerated.
With a timezone of GMT+1, Host B will show a +8 hour difference between timereported - timegenerated.
With a timezone of GMT-7, Host B will show a +14 hour difference between timereported - timegenerated.
With a timezone of GMT+7, Host B will show no difference difference between timereported - timegenerated.

AFAIK, PDT is GMT-7.

Each time I change the timezone, via 'dpkg-reconfigure tzdata' I have to restart rsyslog on Host A otherwise I do not see the timestamps change on Host B.

[edit] BTW the fromthost-ip is 127.0.0.1 because I send the traffic from Host A to Host B over ssh by forwarding localhost:1471 on Host A to port 514 on Host B.
user23235
New
 
Posts: 2
Joined: Tue Apr 25, 2017 12:49 am

Google Ads



Return to General

Who is online

Users browsing this forum: No registered users and 2 guests

cron