"dlog: unexpected stream byte" when header bytes are absent

[Wilfred]

$ docker run -t --entrypoint bash --name example nginx:1.13.1 -c 'ls'
bin   dev  home  lib32  libx32  mnt  proc  run   srv  tmp  var
boot  etc  lib   lib64  media   opt  root  sbin  sys  usr

$ curl -sN --unix-socket /var/run/docker.sock "http://./containers/example/logs?stdout=1&stderr=1" | hexdump -C
00000000  62 69 6e 20 20 20 64 65  76 20 20 68 6f 6d 65 20  |bin   dev  home |
00000010  20 6c 69 62 33 32 09 6c  69 62 78 33 32 09 6d 6e  | lib32.libx32.mn|
00000020  74 20 20 70 72 6f 63 20  20 72 75 6e 09 20 73 72  |t  proc  run. sr|
00000030  76 20 20 74 6d 70 20 20  76 61 72 0d 0a 62 6f 6f  |v  tmp  var..boo|
00000040  74 20 20 65 74 63 20 20  6c 69 62 09 20 6c 69 62  |t  etc  lib. lib|
00000050  36 34 09 6d 65 64 69 61  09 6f 70 74 20 20 72 6f  |64.media.opt  ro|
00000060  6f 74 20 20 73 62 69 6e  20 20 73 79 73 20 20 75  |ot  sbin  sys  u|
00000070  73 72 0d 0a                                       |sr..|
00000074

Here I've created a container with -t and run a command. The Docker socket does not have the expected prefix, leading to dlog reporting the error "dlog: unexpected stream byte".

The docker logs command does the right thing:

$ docker logs example
bin   dev  home  lib32  libx32  mnt  proc  run   srv  tmp  var
boot  etc  lib   lib64  media   opt  root  sbin  sys  usr

so it seems dlog doesn't handle this case?

[ahmetb]

@Wilfred if my memory serves correctly, dlog only handles docker logs "stream".

It looks like you’re getting is just plain text. This might be a recent change in the docker-engine API (maybe they stopped sending streams).

Thankfully I blogged about this when I released this project: https://ahmet.im/blog/docker-logs-api-binary-format-explained/ it looks like the same request (without follow=1) actually returned the proper binary format for me.

Try making the request with &follow=1 (and maybe add -N to curl) and you’ll get the stream output?

dlog won’t handle plain text. It totally expects the "stream" format that used to be there before.

[Wilfred]

Same behaviour with follow=1:

$ curl -sN --unix-socket /var/run/docker.sock "http://./containers/example/logs?stdout=1&stderr=1&follow=1" | hexdump -C
00000000  62 69 6e 20 20 20 64 65  76 20 20 68 6f 6d 65 20  |bin   dev  home |
00000010  20 6c 69 62 33 32 09 6c  69 62 78 33 32 09 6d 6e  | lib32.libx32.mn|
00000020  74 20 20 70 72 6f 63 20  20 72 75 6e 09 20 73 72  |t  proc  run. sr|
00000030  76 20 20 74 6d 70 20 20  76 61 72 0d 0a 62 6f 6f  |v  tmp  var..boo|
00000040  74 20 20 65 74 63 20 20  6c 69 62 09 20 6c 69 62  |t  etc  lib. lib|
00000050  36 34 09 6d 65 64 69 61  09 6f 70 74 20 20 72 6f  |64.media.opt  ro|
00000060  6f 74 20 20 73 62 69 6e  20 20 73 79 73 20 20 75  |ot  sbin  sys  u|
00000070  73 72 0d 0a                                       |sr..|
00000074

There must be a way of reliably getting the stream, but it's not obvious to me.

[Wilfred]

The relevant docs do now document the format, and mention TTY specifically as being different: https://docs.docker.com/engine/api/v1.33/#operation/ContainerAttach

Relevant moby code: https://github.com/moby/moby/blob/master/client/container_attach.go#L15-L33

Similar issue in docker-py: https://github.com/docker/docker-py/issues/630

[Wilfred]

Looks like the correct solution is to inspect the container before deciding whether to use dlog.Newreader or just the underlying stream directly. Perhaps example_test.go could demonstrate this?

$ curl -sN --unix-socket /var/run/docker.sock "http://./containers/example/json" | jq '.Config.Tty'
true

[ahmetb]

Yes, I remember asking for it to be documented specifically because the only documentation at the time was on my blog. :)

I am happy to merge any documentation changes saying "this library doesn't work if containers are started with TTY (-t)". I am not sure if this applies to a broad set of containers, though. People don’t run their production containers that are logging stuff using TTY. TTY is for interactive human use.