Timestamp column in database log.

Posted by dbeavon on 03-May-2016 08:33

I'm noticing unusual issues with the database log.  Does the following bother anyone else?  

 

[2016/05/02@07:13:22.212-0600] P-25827      T-1     I ABL   327: (915)   Lock table overflow, increase -L on server
[2016/05/02@07:13:22.386-0600] P-24191      T-1     I ABL   273: (915)   Lock table overflow, increase -L on server
[2016/05/02@13:13:22.000+0000] P-21879      T-1     I ABL    44: (562)   HANGUP signal received.
[2016/05/02@13:13:22.000+0000] P-21879      T-1     I ABL    44: (562)   HANGUP signal received.
[2016/05/02@07:13:22.443-0600] P-21879      T-1     I ABL    44: (453)   Logout by  on /dev/pts/t7g.
[2016/05/02@07:13:22.618-0600] P-24191      T-1     I ABL   273: (915)   Lock table overflow, increase -L on server


 

I can't think why the OE RDBMS would think its a good idea to alternate between different timezones from one line of the log file to the next.  Perhaps the piece of software that writes the "(562) HANGUP signal received." is written from a separate and oblivious thread that is unable to respect the  log's timezone preference?  Note that the vast majority of the log file is written with the non-utc timezone ( "-600" ) .

This inconsistency can cause a lot of problems.  When you are searching for something in the logs (with vi, grep, or whatever) and come across a line written with the UTC timezone, instead of the standard one, it is unexpected and it causes the log to be misinterpreted, unless you are looking out for the timezone offset and comparing the full "DATETIME-WITH-TZ" to the neighbors before and after.

Moreover another thing that is different about those lines (HANGUP signal received) is that they seen to truncate the milliseconds so that these lines appear to show up out of the correct sequence.  It can cause problems if the logs were to be parsed and analyzed with a utility.

All Replies

Posted by Paul Koufalis on 03-May-2016 08:46

The OE RDBMS is not alternating TZs. The ABL user is in a different TZ. Each shared memory process writes its own messages to the log file.

Nice catch on the HANGUP msg. I never noticed that.

Posted by gus on 03-May-2016 09:06

The signal handler cannot use the same C runtime-library conversion functions as everything else because they are not async signal safe.

IMO all database log messages should be in UTC. Period. No excpetions.

Posted by George Potemkin on 03-May-2016 09:10

Article: Database stalls on Linux because self-service OpenEdge client deadlocks if it receives hangup signal at the wrong time

knowledgebase.progress.com/.../Database-stalls-on-Linux-because-self-service-OpenEdge-client-deadlocks-if-it-receives-hangup-signal-at-the-wrong-time

<quote>

Upgrade to OpenEdge 11.4 or later

A partial fix is included in OpenEdge 11.2.1 and 11.3.x

As a side effect of the fix, messages from signal handlers will always show as UTC time instead of the database's timezone.

</quote>

Posted by dbeavon on 03-May-2016 10:15

Nice catch George.  Don't know how you found that, but its probably the key.

Personally I don't think every database client should be using separate logic to write to the logs, or changing the format of timestamps using alternating timezones, or arbitrarily truncating milliseconds.  For one thing, the *clients* don't go back and read the logs.  The logs should have a target audience in mind ( server managers / dba's / whatever )  and write the log entries accordingly.  Gus mentioned writing database log messages in UTC.  Is there a mechanism for that?  Or do we have to change the timezone environment used by the server itself.

This thread is closed