[TRAFODION-912] LP Bug: 1412806 - log4cpp : incorrect timestamp in logs for SQL info

• Type: Bug
• Status: Open
• Priority: Major
• Resolution: Unresolved
• Component/s: sql-exe
• External issue URL: https://bugs.launchpad.net/bugs/1412806
• Assignee: Sandhya Sundaresan
• Reporter: Gao, Rui-Xian
• Created: 22/Jul/15 18:18
• Updated: 06/Mar/18 16:19

Description

There are messages which have LOG_TS later than current timestamp logged into the log file.

current time is '2015-01-20 05:43:05', but there are messges have '2015-01-20 13:16:16' in the log, only for SQL INFO.

[trafodion@centos-mapr1 logs]$ date
Tue Jan 20 05:43:05 PST 2015

SQL>select * from udf(event_log_reader('f')) where log_ts > timestamp'2015-01-20 06:00:00.000000' order by 1;

LOG_TS SEVERITY COMPONENT NODE_NUMBER CPU PIN PROCESS_NAME SQL_CODE QUERY_ID MESSAGE LOG_FILE_NODE LOG_FILE_NAME LOG_FILE_LINE PARSE_STATUS
-------------------------- ---------- ------------------------ ----------- ----------- ----------- ------------ ----------- -------------------------------------------------------------------------------------------------------------------------------- -------------------------------------------------------------------------------------------------------------------------------- ------------- -------------------------------------------------------------------------------------------------------------------------------- ------------- ------------
2015-01-20 06:57:16.974000 INFO SQL.ESP 0 5 26257 $Z050LF7 NULL NULL An ESP process is launched. 0 master_exec_1_3719.log 1
2015-01-20 06:57:16.974000 INFO SQL.ESP 0 5 26257 $Z050LF7 NULL NULL An ESP process is launched. 0 master_exec_1_3719.log 1
2015-01-20 06:57:17.011000 INFO SQL.ESP 0 3 1982 $Z0301LM NULL NULL An ESP process is launched. 0 master_exec_1_3719.log 1
2015-01-20 06:57:17.011000 INFO SQL.ESP 0 3 1982 $Z0301LM NULL NULL An ESP process is launched. 0 master_exec_1_3719.log 1
2015-01-20 06:57:17.011000 INFO SQL.ESP 0 3 1982 $Z0301LM NULL NULL An ESP process is launched. 0 master_exec_1_3719.log 1
2015-01-20 06:57:17.040000 INFO SQL.ESP 0 0 18389 $Z000F0E NULL NULL An ESP process is launched. 0 master_exec_1_3719.log 1
2015-01-20 08:35:39.716000 INFO SQL.ESP 0 5 24550 $Z050K1F NULL NULL An ESP process is launched. 0 master_exec_1_3708.log 1
2015-01-20 08:35:39.716000 INFO SQL.ESP 0 5 24550 $Z050K1F NULL NULL An ESP process is launched. 0 master_exec_1_3708.log 1
2015-01-20 08:35:39.749000 INFO SQL.ESP 0 3 15912 $Z030CZM NULL NULL An ESP process is launched. 0 master_exec_1_3708.log 1
2015-01-20 08:35:39.749000 INFO SQL.ESP 0 3 15912 $Z030CZM NULL NULL An ESP process is launched. 0 master_exec_1_3708.log 1
2015-01-20 08:35:39.749000 INFO SQL.ESP 0 3 15912 $Z030CZM NULL NULL An ESP process is launched. 0 master_exec_1_3708.log 1
2015-01-20 08:35:39.753000 INFO SQL.ESP 0 0 3133 $Z0002JI NULL NULL An ESP process is launched. 0 master_exec_1_3708.log 1
2015-01-20 08:45:38.921000 INFO SQL.ESP 0 5 27905 $Z050MSA NULL NULL An ESP process is launched. 0 master_exec_2_11912.log 1
2015-01-20 08:45:38.921000 INFO SQL.ESP 0 5 27905 $Z050MSA NULL NULL An ESP process is launched. 0 master_exec_2_11912.log 1
2015-01-20 08:45:38.960000 INFO SQL.ESP 0 3 17323 $Z030E4Y NULL NULL An ESP process is launched. 0 master_exec_2_11912.log 1
2015-01-20 08:45:38.960000 INFO SQL.ESP 0 3 17323 $Z030E4Y NULL NULL An ESP process is launched. 0 master_exec_2_11912.log 1
2015-01-20 08:45:38.960000 INFO SQL.ESP 0 3 17323 $Z030E4Y NULL NULL An ESP process is launched. 0 master_exec_2_11912.log 1
2015-01-20 08:45:38.974000 INFO SQL.ESP 0 0 9730 $Z0007Y0 NULL NULL An ESP process is launched. 0 master_exec_2_11912.log 1
2015-01-20 10:33:50.745000 INFO SQL.ESP 0 5 29267 $Z050NW7 NULL NULL An ESP process is launched. 0 master_exec_0_9234.log 1
2015-01-20 10:33:50.745000 INFO SQL.ESP 0 5 29267 $Z050NW7 NULL NULL An ESP process is launched. 0 master_exec_0_9234.log 1
2015-01-20 10:33:50.772000 INFO SQL.ESP 0 0 31853 $Z000R03 NULL NULL An ESP process is launched. 0 master_exec_0_9234.log 8
2015-01-20 10:33:50.780000 INFO SQL.ESP 0 3 943 $Z0300RY NULL NULL An ESP process is launched. 0 master_exec_0_9234.log 1
2015-01-20 10:33:50.780000 INFO SQL.ESP 0 3 943 $Z0300RY NULL NULL An ESP process is launched. 0 master_exec_0_9234.log 1
2015-01-20 10:33:50.780000 INFO SQL.ESP 0 3 943 $Z0300RY NULL NULL An ESP process is launched. 0 master_exec_0_9234.log 1
2015-01-20 10:43:17.662000 INFO SQL.ESP 0 0 4751 $Z0003VR NULL NULL An ESP process is launched. 0 master_exec_0_14618.log 2
2015-01-20 10:43:17.662000 INFO SQL.ESP 0 5 32239 $Z050RB4 NULL NULL An ESP process is launched. 0 master_exec_0_14618.log 1
2015-01-20 10:43:17.662000 INFO SQL.ESP 0 5 32239 $Z050RB4 NULL NULL An ESP process is launched. 0 master_exec_0_14618.log 1
2015-01-20 10:43:17.696000 INFO SQL.ESP 0 3 2048 $Z0301NI NULL NULL An ESP process is launched. 0 master_exec_0_14618.log 1
2015-01-20 10:43:17.696000 INFO SQL.ESP 0 3 2048 $Z0301NI NULL NULL An ESP process is launched. 0 master_exec_0_14618.log 1
2015-01-20 10:43:17.696000 INFO SQL.ESP 0 3 2048 $Z0301NI NULL NULL An ESP process is launched. 0 master_exec_0_14618.log 1
2015-01-20 13:00:59.267000 INFO SQL.ESP 0 5 11049 $Z05090P NULL NULL An ESP process is launched. 0 master_exec_0_9224.log 1
2015-01-20 13:00:59.267000 INFO SQL.ESP 0 5 11049 $Z05090P NULL NULL An ESP process is launched. 0 master_exec_0_9224.log 1
2015-01-20 13:00:59.290000 INFO SQL.ESP 0 0 10868 $Z0008VI NULL NULL An ESP process is launched. 0 master_exec_0_9224.log 5
2015-01-20 13:00:59.304000 INFO SQL.ESP 0 3 22987 $Z030IRS NULL NULL An ESP process is launched. 0 master_exec_0_9224.log 1
2015-01-20 13:00:59.304000 INFO SQL.ESP 0 3 22987 $Z030IRS NULL NULL An ESP process is launched. 0 master_exec_0_9224.log 1
2015-01-20 13:00:59.304000 INFO SQL.ESP 0 3 22987 $Z030IRS NULL NULL An ESP process is launched. 0 master_exec_0_9224.log 1
2015-01-20 13:16:16.927000 INFO SQL.COMP 0 0 18834 $Z000FD4 NULL NULL A compiler process is launched. 0 master_exec_0_9234.log 12
2015-01-20 13:16:20.643000 INFO SQL.COMP 0 0 18902 $Z000FF2 NULL NULL A compiler process is launched. 0 master_exec_0_9234.log 13
2015-01-20 13:17:25.544000 INFO SQL.COMP 0 0 20121 $Z000GEW NULL NULL A compiler process is launched. 0 master_exec_0_9234.log 428
2015-01-20 13:19:54.074000 INFO SQL.COMP 0 5 17063 $Z050DXI NULL NULL A compiler process is launched. 0 master_exec_5_27541.log 5
2015-01-20 13:19:54.074000 INFO SQL.COMP 0 5 17063 $Z050DXI NULL NULL A compiler process is launched. 0 master_exec_5_27541.log 5
2015-01-20 13:19:57.535000 INFO SQL.COMP 0 5 17120 $Z050DZ5 NULL NULL A compiler process is launched. 0 master_exec_5_27541.log 6
2015-01-20 13:19:57.535000 INFO SQL.COMP 0 5 17120 $Z050DZ5 NULL NULL A compiler process is launched. 0 master_exec_5_27541.log 6
2015-01-20 13:20:10.324000 INFO SQL.COMP 0 5 17430 $Z050E80 NULL NULL A compiler process is launched. 0 master_exec_5_27541.log 9
2015-01-20 13:20:10.324000 INFO SQL.COMP 0 5 17430 $Z050E80 NULL NULL A compiler process is launched. 0 master_exec_5_27541.log 9
2015-01-20 13:20:15.043000 INFO SQL.COMP 0 5 17496 $Z050E9W NULL NULL A compiler process is launched. 0 master_exec_5_27541.log 10
2015-01-20 13:20:15.043000 INFO SQL.COMP 0 5 17496 $Z050E9W NULL NULL A compiler process is launched. 0 master_exec_5_27541.log 10
2015-01-20 13:22:15.873000 INFO SQL.COMP 0 3 25500 $Z030KTK NULL NULL A compiler process is launched. 0 master_exec_3_17267.log 5
2015-01-20 13:22:15.873000 INFO SQL.COMP 0 3 25500 $Z030KTK NULL NULL A compiler process is launched. 0 master_exec_3_17267.log 5
2015-01-20 13:22:15.873000 INFO SQL.COMP 0 3 25500 $Z030KTK NULL NULL A compiler process is launched. 0 master_exec_3_17267.log 5
2015-01-20 13:22:19.411000 INFO SQL.COMP 0 3 25558 $Z030KV8 NULL NULL A compiler process is launched. 0 master_exec_3_17267.log 6
2015-01-20 13:22:19.411000 INFO SQL.COMP 0 3 25558 $Z030KV8 NULL NULL A compiler process is launched. 0 master_exec_3_17267.log 6
2015-01-20 13:22:19.411000 INFO SQL.COMP 0 3 25558 $Z030KV8 NULL NULL A compiler process is launched. 0 master_exec_3_17267.log 6
2015-01-20 13:22:32.545000 INFO SQL.COMP 0 3 25821 $Z030L2R NULL NULL A compiler process is launched. 0 master_exec_3_17267.log 9
2015-01-20 13:22:32.545000 INFO SQL.COMP 0 3 25821 $Z030L2R NULL NULL A compiler process is launched. 0 master_exec_3_17267.log 9
2015-01-20 13:22:32.545000 INFO SQL.COMP 0 3 25821 $Z030L2R NULL NULL A compiler process is launched. 0 master_exec_3_17267.log 9
2015-01-20 13:22:37.363000 INFO SQL.COMP 0 3 25887 $Z030L4M NULL NULL A compiler process is launched. 0 master_exec_3_17267.log 10
2015-01-20 13:22:37.363000 INFO SQL.COMP 0 3 25887 $Z030L4M NULL NULL A compiler process is launched. 0 master_exec_3_17267.log 10
2015-01-20 13:22:37.363000 INFO SQL.COMP 0 3 25887 $Z030L4M NULL NULL A compiler process is launched. 0 master_exec_3_17267.log 10

— 59 row(s) selected.