Wrong log_time in sql view when log_time is out of order

[esbenboye]

lnav version
v0.11.1 on MacOS Big Sur (11.4) installed from HomeBrew

Describe the bug
If I have a log with entries that are out-of-order and switch to the SQL view, then log_time in sql view is wrong. It seems that lnav is simply using the latest timestamp that was in order.

I would expect the sql view to keep the original log_time.

To Reproduce
Run lnavn againt the attachment demo.log

This will show that the first 7 lines are in order, but from then on, they are out of order (I have collected some access logs from a some containers and put them into one file to get this result).

When switching to sql view (by pressing v) and doing a SELECT * FROM access_log, it will produce a list, but all the lines that are out of order, have inherited the latest log_time that was in order.

[jefft]

I just hit this too. To replicate:

cat > access.log <<EOF
localhost:443 1.2.3.4 1j0vhgd jsmith [10/Aug/2023:02:00:00 -0700] "GET /foo HTTP/2.0" 200 17163 "-" "Mozilla/5.0" 116075
localhost:443 1.2.3.4 cger1e khenry [10/Aug/2023:01:00:00 -0700] "GET /bar HTTP/2.0" 200 16517 "-" "Mozilla/5.0" 156302
EOF
lnav access.log -n -c ';select log_time from access_log;'

Expected output:

       log_time         
2023-08-10 02:00:00.000 
2023-08-10 01:00:00.000 

Actual output (lnav 0.11.2-97-g7c8d323):

       log_time         
2023-08-10 02:00:00.000 
2023-08-10 02:00:00.000 

[tstack]

lnav expects/likes to have the messages in a file be in time-order so that it doesn't have to do heavy re-sorting work frequently. So, when that isn't the case, it treats the message as out-of-time-order and uses the timestamp from the previous log message. In the log view, you can see the original timestamp and further details by pressing p. In the SQL interface, you can access the original timestamp with the log_actual_time column[1].

If you really want things to be in time-order, you can patch the log file format and set the ordered-by-time flag to false. Patching the format can be done by putting the following fragment in a .json file in your lnav dot directory (e.g. ~/.lnav/formats/installed or ~/.config/lnav/formats/installed)

{
    "access_log": {
        "ordered-by-time": false
    }
}

[1] - Reading the actual time can be costly since the log message needs to be read from disk.

[jefft]

In the SQL interface, you can access the original timestamp with the [log_actual_time (https://docs.lnav.org/en/latest/sqlext.html#log-tables) column[1].

Nice, thanks.

For me this arose when I ran lnav on <(cat access.log access.log.1 | grep ...). It was trivial to fix the order once I knew about the log_time behaviour, which is nicely documented in TFM I didn't R.