presto generates http-request .log containing records that fail queries on localfile.logs.http_request_log

[dumarkov]

The short story

presto> select * from localfile.logs.http_request_log;

... Invalid format: "2017-12-21T00:12:27Z" is malformed at "Z"

Presto is looking for timestamp in yyyy-MM-ddTHH:mm:ss.fffZ format (please note the .fff).
In case the fractional part is missing, presto yields an error.
After editing the log and changing the timestamp to 2017-12-21T00:12:27.000Z (please note the .000) the query worked fine.

Version

presto-server-0.191
presto-cli-0.191-executable.jar

localfile.properties

connector.name=localfile
presto-logs.http-request-log.location=/var/presto/data/var/log
presto-logs.http-request-log.pattern=http-request.log

connect & run query

./presto --server localhost:8080 --catalog localfile --schema logs
presto:logs> select * from http_request_log;

Query 20171221_104944_00046_yfeuc, FAILED, 1 node
Splits: 17 total, 0 done (0.00%)
0:00 [0 rows, 0B] [0 rows/s, 0B/s]

Query 20171221_104944_00046_yfeuc failed: Invalid format: "2017-12-21T00:12:27Z" is malformed at "Z"

presto:logs>

http-request.log

dumarkov@dumarkov-presto:~/presto$ grep '2017-12-21T00:12:27Z' /var/presto/data/var/log/http-request.log
2017-12-21T00:12:27Z 127.0.0.1 GET /v1/service/collector/general null 1 200 0 36 1 830605f1fcac4d879453552
beeafaf4700000030d6

[nezihyigitbasi]

There is a TODO in the code about this issue, please see LocalFileRecordCursor.java#L69-L73.

PR is welcome!

[dumarkov]

Thanks :-)

I am not sure the TODO covers this issue.
The format of the log writer does match the format of the localfile catalog reader, however it seems the DateTimeFormatterBuilder suppresses 0 fractions of second, turning ss.000Z to ssZ and by that generates timestamp literal that does not match the required format.

[qqibrow]

I encountered the same error. I think this will fix it. #10252

[qqibrow]

@nezihyigitbasi As @dudu-markovitz mentioned, the problem is the defaultDateTimeFormatter used there doesn't support default timestamp format in request.log, which could be both ss.000Z and ssZ format.

[nezihyigitbasi]

@qqibrow The issue I think manifests itself when the JVM default timezone is UTC. (see the formatter used to write the HTTP logs). I put up a PR to fix the issue by using the same formatter: #10713

[nezihyigitbasi]

I merged a fix for this, can you guys please give it a try?