hikhvar/journaldtail

PoC for shipping systemd logs to grafana loki

journaldtail's Issues

Grafana loki reports 'Entry out of order'

loki_1     | level=warn ts=2019-01-06T19:07:05.044194968Z caller=gokit.go:46 method=/logproto.Pusher/Push duration=85.439µs request="&PushRequest{Streams:[&Stream{Labels:{PRIORITY=\"6\", SYSLOG_FACILITY=\"0\", SYSLOG_IDENTIFIER=\"kernel\", _BOOT_ID=\"255a3d02873b482ab3c3ba031c981005\", _HOSTNAME=\"christoph-thinkpad-sport\", _MACHINE_ID=\"61e16bd053114b70866d616466391e9d\", _SOURCE_MONOTONIC_TIMESTAMP=\"6604925\", _TRANSPORT=\"kernel\"},Entries:[{1970-01-01 00:00:06.60649 +0000 UTC thinkpad_acpi: ThinkPad BIOS N22ET48W (1.25 ), EC unknown}],}],}" err="Entry out of order" msg="gRPC\n"
loki_1     | level=warn ts=2019-01-06T19:07:05.044542981Z caller=gokit.go:43 msg="POST /api/prom/push (500) 1.223078ms Response: \"rpc error: code = Unknown desc = Entry out of order\\n\" ws: false; Accept-Encoding: gzip; Content-Length: 316; Content-Type: application/x-protobuf; User-Agent: Go-http-client/1.1; "
loki_1     | level=warn ts=2019-01-06T19:07:05.046783059Z caller=gokit.go:46 duration=58.26µs method=/logproto.Pusher/Push request="&PushRequest{Streams:[&Stream{Labels:{PRIORITY=\"6\", SYSLOG_FACILITY=\"0\", SYSLOG_IDENTIFIER=\"kernel\", _BOOT_ID=\"255a3d02873b482ab3c3ba031c981005\", _HOSTNAME=\"christoph-thinkpad-sport\", _MACHINE_ID=\"61e16bd053114b70866d616466391e9d\", _SOURCE_MONOTONIC_TIMESTAMP=\"6604925\", _TRANSPORT=\"kernel\"},Entries:[{1970-01-01 00:00:06.606528 +0000 UTC thinkpad_acpi: Lenovo ThinkPad T480s, model 20L7CTO1WW}],}],}" err="Entry out of order" msg="gRPC\n"
loki_1     | level=warn ts=2019-01-06T19:07:05.047042844Z caller=gokit.go:43 msg="POST /api/prom/push (500) 783.914µs Response: \"rpc error: code = Unknown desc = Entry out of order\\n\" ws: false; Accept-Encoding: gzip; Content-Length: 313; Content-Type: application/x-protobuf; User-Agent: Go-http-client/1.1; "

chasing the Entry out of order issue

I've changed things so journaldtail keeps going after its finished importing the existing logs, and the entry out of order issue then too.

Adding some debug output shows that when its triggered, things look like:

ts="2019/01/14 03:56:09" caller="2019-01-14 03:56" msg=":09.05096 +0000 UTC: Message: goa_ews_client_autodiscover() failed: 401 — Unauthorized"
ts="2019/01/14 03:56:45" caller="2019-01-14 03:56" msg=":44.834912 +0000 UTC: Message: time=\"2019-01-14T13:56:44.834778069+10:00\" level=info msg=\"NetworkDB stats TOWER-SL(cc16e37550af) - netID:4g332cks9ckfe2mygp6jrvyur leaving:false netPeers:3 entries:43 Queue qLen:0 netMsg/s:0\""
ts="2019/01/14 03:56:45" caller="2019-01-14 03:56" msg=":44.834912 +0000 UTC: Message: time=\"2019-01-14T13:56:44.834902037+10:00\" level=info msg=\"NetworkDB stats TOWER-SL(cc16e37550af) - netID:xo812jhpyg672z2ilsk628thv leaving:false netPeers:3 entries:15 Queue qLen:0 netMsg/s:0\""
ts="2019/01/14 03:56:45" caller="2019-01-14 03:56" msg=":44.837692 +0000 UTC: Message: time=\"2019-01-14T13:56:44.834957630+10:00\" level=info msg=\"NetworkDB stats TOWER-SL(cc16e37550af) - netID:ukxnbid1t0b259ge087iyrk0a leaving:false netPeers:3 entries:37 Queue qLen:0 netMsg/s:0\""
level=error msg="error sending batch" error="Error doing write: 500 - 500 Internal Server Error"
ts="2019/01/14 03:56:45" caller="2019-01-14 03:56" msg=":44.837692 +0000 UTC: Message: time=\"2019-01-14T13:56:44.834996532+10:00\" level=info msg=\"NetworkDB stats TOWER-SL(cc16e37550af) - netID:ytnem5hmm522nxhdpqpuj6v5h leaving:false netPeers:2 entries:6 Queue qLen:0 netMsg/s:0\""
ts="2019/01/14 03:56:45" caller="2019-01-14 03:56" msg=":44.837692 +0000 UTC: Message: time=\"2019-01-14T13:56:44.835045281+10:00\" level=info msg=\"NetworkDB stats TOWER-SL(cc16e37550af) - netID:l98boizgwfp10qt4fadrd9c0n leaving:false netPeers:3 entries:11 Queue qLen:0 netMsg/s:0\""
level=error msg="error sending batch" error="Error doing write: 500 - 500 Internal Server Error"
ts="2019/01/14 03:56:45" caller="2019-01-14 03:56" msg=":44.837692 +0000 UTC: Message: time=\"2019-01-14T13:56:44.835094169+10:00\" level=info msg=\"NetworkDB stats TOWER-SL(cc16e37550af) - netID:zbfjzqdnr1ffv2texa3xrcnc2 leaving:false netPeers:3 entries:12 Queue qLen:0 netMsg/s:0\""
level=error msg="error sending batch" error="Error doing write: 500 - 500 Internal Server Error"
ts="2019/01/14 03:56:45" caller="2019-01-14 03:56" msg=":44.837692 +0000 UTC: Message: time=\"2019-01-14T13:56:44.835140823+10:00\" level=info msg=\"NetworkDB stats TOWER-SL(cc16e37550af) - netID:3nygp8rih1yq7vxu3xv3sm2v6 leaving:false netPeers:3 entries:35 Queue qLen:0 netMsg/s:0\""
level=error msg="error sending batch" error="Error doing write: 500 - 500 Internal Server Error"
level=error msg="error sending batch" error="Error doing write: 500 - 500 Internal Server Error"

note that the output is weird because go-kit doesn't work the way I think it does - but it took over lunch for things to load, so I'll redo it later.