Output should be line-buffered

[arcimboldo]

When running kail on a k8s cluster with many pods logging at the same time it seems like log lines are trimmed or displayed interleaved, for instances:

1: foobar/core-data-6767d5f5df-bdgqj[core-data]: dler.go:81] (get) a4BE settings
2: D1124 12:27:38.566878 00001 core.data.core-data d87e1dc6 003_3649_002_000 indexhandler.go:46] (get.page) a4BE
3: D1124 12:27:38.560970 00001 core.data.core-data d87e1dc6 003_3640_001_000 handler.go:81] (get) a4BB settings
4: 00 handler.go:81] (get) a4BA settings
5: D1124 12:27:38.564373 00001 core.data.core-data d87e1dc6 003_3646_002_000 indexhandler.go:46] (get.page) a4BD
6: D1124 12:27:38.566814 00001 core.data.core-data d87e1dc6 003_3649_001_000 han

Note that lines 2,3 and 5 are complete while 1,4,6 are not. Running kubectl logs of course gives the full lines.

[boz]

Thanks for the report, @arcimboldo.

Did you prune the namespace/name[container]: prefix from lines 2 through 6 or is that how it came out? If the latter, this might be a kubernetes issue.

How many pods were matching? Can you provide the output of reproducing with --log-level debug enabled?

Thanks!

[arcimboldo]

No, this is exactly what I mean when I say that the loglines are trimmed. I've posted what I get on the console as it is.

I've tried by selecting only 2 pods using -l option, the issue is still there:

$ kail --log-level debug -l service=core-data 2>&1 | tee /tmp/foobar; cat /tmp/foobar
time="2017-11-27T13:37:30+01:00" level=debug msg="create subscription: current count 0" cmp=publisher
time="2017-11-27T13:37:30+01:00" level=debug msg="create subscription: current count 0" cmp=publisher
time="2017-11-27T13:37:30+01:00" level=debug msg="create subscription: current count 0" cmp=publisher
time="2017-11-27T13:37:30+01:00" level=debug msg="list version: 3131451" cmp=controller
time="2017-11-27T13:37:30+01:00" level=debug msg="list complete: version: 3131451, items: 110, events: 110" cmp=controller
time="2017-11-27T13:37:30+01:00" level=debug msg=ready cmp=controller
time="2017-11-27T13:37:30+01:00" level=debug msg="ressetting to version 3131451" cmp=watcher
time="2017-11-27T13:37:30+01:00" level=debug msg="parent ready: making ready" cmp=publisher
time="2017-11-27T13:37:30+01:00" level=debug msg="parent ready: making ready" cmp=publisher
time="2017-11-27T13:37:30+01:00" level=debug msg="parent ready: making ready" cmp=publisher
time="2017-11-27T13:37:30+01:00" level=debug msg="create subscription: current count 0" cmp=publisher
time="2017-11-27T13:37:30+01:00" level=debug msg=ENTER cmp=kail.controller func=run
time="2017-11-27T13:37:30+01:00" level=debug msg=ENTER cmp=kail.controller func="createInitialMonitors(pods=1)"
time="2017-11-27T13:37:30+01:00" level=debug msg="pod foobar/core-data-6767d5f5df-bdgqj: 1 containers ready" cmp=kail.controller
time="2017-11-27T13:37:30+01:00" level=debug msg=ENTER cmp=kail.controller func="createMonitor(foobar/core-data-6767d5f5df-bdgqj@core-data)"
time="2017-11-27T13:37:30+01:00" level=debug msg=LEAVE cmp=kail.controller func="createMonitor(foobar/core-data-6767d5f5df-bdgqj@core-data)"
time="2017-11-27T13:37:30+01:00" level=debug msg=LEAVE cmp=kail.controller func="createInitialMonitors(pods=1)"
time="2017-11-27T13:37:30+01:00" level=debug msg="loop draining:false monitors:1" cmp=kail.controller
time="2017-11-27T13:37:30+01:00" level=debug msg=ENTER cmp="monitor [foobar/core-data-6767d5f5df-bdgqj@core-data]" func=run
time="2017-11-27T13:37:30+01:00" level=debug msg=ENTER cmp="monitor [foobar/core-data-6767d5f5df-bdgqj@core-data]" func=mainloop
time="2017-11-27T13:37:30+01:00" level=debug msg="displaying logs since 1 seconds" cmp="monitor [foobar/core-data-6767d5f5df-bdgqj@core-data]"
time="2017-11-27T13:37:30+01:00" level=debug msg="readloop count: 0" cmp="monitor [foobar/core-data-6767d5f5df-bdgqj@core-data]"
time="2017-11-27T13:37:30+01:00" level=debug msg=ENTER cmp="monitor [foobar/core-data-6767d5f5df-bdgqj@core-data]" func=readloop
foobar/core-data-6767d5f5df-bdgqj[core-data]: er.go:81] (get) a369 settings
D1127 12:37:27.010964 00001 core.data.core-data 3a92688c 001_2626_002_000 indexhandler.go:46] (get.page) a369
D1127 12:37:27.012978 00001 core.data.core-data 16337d90 001_5686_001_000 handler.go:81] (get) a764 settings
D1127 12:37:27.013009 00001 core.data.core-data 16337d90 001_5686_002_000 indexhandler.go:46] (get.page) a764
D1127 12:37:27.026829 00001 core.data.core-data 2ec8682d 003_5086_001_000 handler.go:81] (get) a69C settings
D1127 12:37:27.026854 00001 core.data.core-data 2ec8682d 003_5086_002_000 indexhandler.go:46] (get.page) a69C
D1127 12:37:27.027490 00001 core.data.core-data 6ff6b24b 003_2794_001_000 handler.go:81] (get) a3A1 settings
D1127 12:37:27.027544 00001 core.data.core-data 6ff6b24b 003_2794_002_000 indexhandler.go:46] (get.page) a3A1
D1127 12:37:27.028469 00001 core.data.core-data d830d310 003_4396_001_000 handler.go:81] (get) a5B7 settings
D1127 12:37:27.028540 00001 core.data.core-data d830d310 003_4396_002_000 indexhandler.go:46] (get.page) a5B7
00 handl
foobar/core-data-6767d5f5df-bdgqj[core-data]: er.go:81] (get) a369 settings
D1127 12:37:27.010964 00001 core.data.core-data 3a92688c 001_2626_002_000 indexhandler.go:46] (get.page) a369

[boz]

I see. Line 4 in the first example threw me off.

Yes, it can be line buffered 👍. I've been considering getting to this for a while but it hasn't been a priority.

Thanks again for the report.