goaccess icon indicating copy to clipboard operation
goaccess copied to clipboard

Parsing traefik JSON logs timestamps

Open cberescu opened this issue 3 years ago • 5 comments

It seems that the timestamps in traefik JSON logs are in nanoseconds format. Is there a way to convert/parse them in correct format?

I was not able to find a way to do it, just to ignore the fields.

Could there be added a specifier for nanoseconds ?

cberescu avatar Jan 24 '22 08:01 cberescu

I can look into it. Can you please post a few lines directly from your access log? Thanks.

allinurl avatar Jan 26 '22 02:01 allinurl

yes, here you go :

 {"ClientAddr":"1.1.1.1:32314","ClientHost":"1.1.1.1","ClientPort":"32314","ClientUsername":"-","DownstreamContentSize":10,"DownstreamStatus":410,"Duration":433331475,"OriginContentSize":10,"OriginDuration":432963955,"OriginStatus":410,"Overhead":367520,"RequestAddr":"example.com","RequestContentSize":0,"RequestCount":260689,"RequestHost":"example.com","RequestMethod":"GET","RequestPath":"/something","RequestPort":"-","RequestProtocol":"HTTP/1.1","RequestScheme":"http","RetryAttempts":0,"RouterName":"images@consulcatalog","ServiceAddr":"1.1.1.1:20594","ServiceName":"images@consulcatalog","ServiceURL":{"Scheme":"http","Opaque":"","User":null,"Host":"1.1.1.1:20594","Path":"","RawPath":"","ForceQuery":false,"RawQuery":"","Fragment":"","RawFragment":""},"StartLocal":"2021-11-30T23:00:00.201712623Z","StartUTC":"2021-11-30T23:00:00.201712623Z","downstream_Content-Type":"text/plain; charset=utf-8","entryPointName":"http","level":"info","msg":"","origin_Content-Type":"text/plain; charset=utf-8","time":"2021-11-30T23:00:00Z"}
 {"ClientAddr":"1.1.1.1:36371","ClientHost":"1.1.1.1","ClientPort":"36371","ClientUsername":"-","DownstreamContentSize":21,"DownstreamStatus":500,"Duration":1423845,"OriginContentSize":21,"OriginDuration":1228804,"OriginStatus":500,"Overhead":195041,"RequestAddr":"example.com","RequestContentSize":0,"RequestCount":19985,"RequestHost":"example.com","RequestMethod":"GET","RequestPath":"/s","RequestPort":"-","RequestProtocol":"HTTP/1.1","RequestScheme":"http","RetryAttempts":0,"RouterName":"images@consulcatalog","ServiceAddr":"1.1.1.1:22070","ServiceName":"images@consulcatalog","ServiceURL":{"Scheme":"http","Opaque":"","User":null,"Host":"1.1.1.1:22070","Path":"","RawPath":"","ForceQuery":false,"RawQuery":"","Fragment":"","RawFragment":""},"StartLocal":"2021-11-30T23:00:01.252644663Z","StartUTC":"2021-11-30T23:00:01.252644663Z","entryPointName":"http","level":"info","msg":"","time":"2021-11-30T23:00:01Z"}
 {"ClientAddr":"1.1.1.1:32314","ClientHost":"1.1.1.1","ClientPort":"32314","ClientUsername":"-","DownstreamContentSize":10,"DownstreamStatus":410,"Duration":114149505,"OriginContentSize":10,"OriginDuration":113829734,"OriginStatus":410,"Overhead":319771,"RequestAddr":"example.com","RequestContentSize":0,"RequestCount":260698,"RequestHost":"example.com","RequestMethod":"GET","RequestPath":"/s","RequestPort":"-","RequestProtocol":"HTTP/1.1","RequestScheme":"http","RetryAttempts":0,"RouterName":"images@consulcatalog","ServiceAddr":"1.1.1.1:20594","ServiceName":"images@consulcatalog","ServiceURL":{"Scheme":"http","Opaque":"","User":null,"Host":"1.1.1.1:20594","Path":"","RawPath":"","ForceQuery":false,"RawQuery":"","Fragment":"","RawFragment":""},"StartLocal":"2021-11-30T23:00:01.635948344Z","StartUTC":"2021-11-30T23:00:01.635948344Z","downstream_Content-Type":"text/plain; charset=utf-8","entryPointName":"http","level":"info","msg":"","origin_Content-Type":"text/plain; charset=utf-8","time":"2021-11-30T23:00:01Z"}
 {"ClientAddr":"1.1.1.1:52940","ClientHost":"1.1.1.1","ClientPort":"52940","ClientUsername":"-","DownstreamContentSize":21,"DownstreamStatus":500,"Duration":1648346,"OriginContentSize":21,"OriginDuration":1512722,"OriginStatus":500,"Overhead":135624,"RequestAddr":"example.com","RequestContentSize":0,"RequestCount":19986,"RequestHost":"example.com","RequestMethod":"GET","RequestPath":"/s","RequestPort":"-","RequestProtocol":"HTTP/1.1","RequestScheme":"http","RetryAttempts":0,"RouterName":"images@consulcatalog","ServiceAddr":"1.1.1.1:22070","ServiceName":"images@consulcatalog","ServiceURL":{"Scheme":"http","Opaque":"","User":null,"Host":"1.1.1.1:22070","Path":"","RawPath":"","ForceQuery":false,"RawQuery":"","Fragment":"","RawFragment":""},"StartLocal":"2021-11-30T23:00:02.471578576Z","StartUTC":"2021-11-30T23:00:02.471578576Z","entryPointName":"http","level":"info","msg":"","time":"2021-11-30T23:00:02Z"}
 {"ClientAddr":"1.1.1.1:47682","ClientHost":"1.1.1.1","ClientPort":"47682","ClientUsername":"-","DownstreamContentSize":4,"DownstreamStatus":400,"Duration":1374661,"OriginContentSize":4,"OriginDuration":1215289,"OriginStatus":400,"Overhead":159372,"RequestAddr":"example.com","RequestContentSize":0,"RequestCount":2525749,"RequestHost":"example.com","RequestMethod":"GET","RequestPath":"/s","RequestPort":"-","RequestProtocol":"HTTP/1.1","RequestScheme":"http","RetryAttempts":0,"RouterName":"images@consulcatalog","StartLocal":"2021-11-30T23:00:03.595637485Z","StartUTC":"2021-11-30T23:00:03.595637485Z","downstream_Content-Type":"text/plain; charset=utf-8","entryPointName":"http","level":"info","msg":"","origin_Content-Type":"text/plain; charset=utf-8","time":"2021-11-30T23:00:03Z"}

Thanks for looking into it.

cberescu avatar Jan 26 '22 07:01 cberescu

@cberescu would you please share your log-format settings in goaccess which matches the traefik accesslog format? I have been trying for days to get the requested hostnames :-/

somnium78 avatar Feb 08 '22 14:02 somnium78

Hi @somnium78 here you go :

log-format {"ClientAddr":"%h:%^","DownstreamContentSize":"%b","Duration":"%T","OriginStatus":"%s","RequestAddr":"%v","RequestMethod":"%m","RequestPath":"%U","RequestProtocol":"%H","StartUTC":"%dT%t.%^"}

cberescu avatar Feb 08 '22 14:02 cberescu

Yep, Traefik logs duration in nanoseconds, which is not an available option at the moment:

%D The time taken to serve the request, in microseconds.
%T The time taken to serve the request, in seconds with milliseconds resolution.
%L The time taken to serve the request, in milliseconds as a decimal number.

see https://goaccess.io/man#SPECIFIERS

lastzero avatar Feb 10 '22 16:02 lastzero

Yep, Traefik logs duration in nanoseconds, which is not an available option at the moment:

%D The time taken to serve the request, in microseconds.
%T The time taken to serve the request, in seconds with milliseconds resolution.
%L The time taken to serve the request, in milliseconds as a decimal number.

see https://goaccess.io/man#SPECIFIERS

Any idea when it shall be supported, so we can use Traefik JSON Logs with nanoseconds? Theres also more header info such as X-Forwarded-For so we can use real user IP, as the standard COMBINED log doesn't include this!

t0mtaylor avatar Jan 17 '23 20:01 t0mtaylor

Added on v1.7.1 using the %n specifier.

allinurl avatar Mar 01 '23 01:03 allinurl

@cberescu What was the rest of your log configuration. I'm trying to setup traefik JSON parsing in goaccess and having some issues with it

sfulham avatar Dec 02 '23 06:12 sfulham

I couldn't figure out how to parse the fractional ISO 8601 timestamps emitted by Traefik (example) including the time zone offset.

This is what such a log line looks like, pretty-printed and with some irrelevant fields omitted, logged by Traefik when configured to a timezone with a +04:00 offset:

{
	"StartLocal": "2023-12-13T20:33:08.43197025+04:00",
	"StartUTC": "2023-12-13T16:33:08.43197025Z",
	"ClientAddr": "192.168.65.1:35893",
	"Duration": 327542,
	"RequestHost": "localhost",
	"RequestMethod": "HEAD",
	"RequestPath": "/",
	"RequestPort": "8080",
	"RequestProtocol": "HTTP/1.1",
	"RequestScheme": "http",
	"downstream_Content-Type": "text/plain; charset=utf-8",
	"entryPointName": "web",
	"level": "info",
	"msg": "",
	"request_Accept": "*/*"
}

I tried both %Y-%m-%dT%H:%M:%S.%f%z and %Y-%m-%dT%H:%M:%S.%n%z as datetime-format, but it fails as follows:

Token '2023-12-13T20:33:08.43197025+04:00' doesn't match specifier '%x'
Token '2023-12-13T20:34:01.125568+04:00' doesn't match specifier '%x'

Is it possible to do it?

Alternatively, I could also parse StartUTC, but it has the same fractional seconds part.


  • log-format: {"DownstreamContentSize":"%b","DownstreamStatus":"%s","Duration":"%n","RequestMethod":"%m","RequestPath":"%U","RequestProtocol":"%H","ServiceName":"%v@docker","StartLocal":"%x","request_User-Agent":"%u","request_X-Real-Ip":"%h"}
  • GoAccess version: 1.8.1

derhuerst avatar Dec 13 '23 17:12 derhuerst

@derhuerst, I believe strptime() doesn't handle fractional time. An alternative approach would be to preprocess the log, a task easily achievable with either jq or sed:

sed -r 's/([0-9]{2}:[0-9]{2}:[0-9]{2})\.[0-9]+/\1 /' access.log | goaccess - --log-format='{"startLocal": "%x"}' --datetime-format='%Y-%m-%dT%H:%M:%S %z'

allinurl avatar Dec 13 '23 23:12 allinurl