container.logs() returns unprintable chars in buffer

[leolivier]

Hello
I'm trying the following code with an existing container (typescript):

this.stream = await this.container.logs({ follow: true, stdout: true }) as Stream;
this.stream.on('data', (info: any) => console.log(info));

But I get things like:

<Buffer 02 00 00 00 00 00 00 60 74 69 6d 65 3d 22 32 30 32 31 2d 30 34 2d 31 37 54 30 39 3a 31 35 3a 31 38 5a 22 20 6c 65 76 65 6c 3d 77 61 72 6e 69 6e 67 20 ... >
<Buffer 02 00 00 00 00 00 00 5c 74 69 6d 65 3d 22 32 30 32 31 2d 30 34 2d 31 37 54 30 39 3a 31 35 3a 31 38 5a 22 20 6c 65 76 65 6c 3d 69 6e 66 6f 20 6d 73 67 ... >
<Buffer 02 00 00 00 00 00 00 93 74 69 6d 65 3d 22 32 30 32 31 2d 30 34 2d 31 38 54 31 34 3a 32 30 3a 32 39 5a 22 20 6c 65 76 65 6c 3d 65 72 72 6f 72 20 6d 73 ... >
<Buffer 02 00 00 00 00 00 00 53 74 69 6d 65 3d 22 32 30 32 31 2d 30 34 2d 31 38 54 31 34 3a 33 37 3a 34 38 5a 22 20 6c 65 76 65 6c 3d 65 72 72 6f 72 20 6d 73 ... >
<Buffer 02 00 00 00 00 00 00 93 74 69 6d 65 3d 22 32 30 32 31 2d 30 34 2d 31 38 54 31 34 3a 33 37 3a 34 38 5a 22 20 6c 65 76 65 6c 3d 65 72 72 6f 72 20 6d 73 ... >
<Buffer 02 00 00 00 00 00 01 11 74 69 6d 65 3d 22 32 30 32 31 2d 30 34 2d 31 38 54 31 34 3a 34 34 3a 33 39 5a 22 20 6c 65 76 65 6c 3d 65 72 72 6f 72 20 6d 73 ... >
<Buffer 02 00 00 00 00 00 00 4f 74 69 6d 65 3d 22 32 30 32 31 2d 30 35 2d 31 31 54 30 38 3a 34 37 3a 32 37 5a 22 20 6c 65 76 65 6c 3d 69 6e 66 6f 20 6d 73 67 ... >
<Buffer 02 00 00 00 00 00 00 52 74 69 6d 65 3d 22 32 30 32 31 2d 30 35 2d 31 31 54 30 38 3a 34 37 3a 32 37 5a 22 20 6c 65 76 65 6c 3d 77 61 72 6e 69 6e 67 20 ... >
<Buffer 02 00 00 00 00 00 01 61 74 69 6d 65 3d 22 32 30 32 31 2d 30 35 2d 31 31 54 30 38 3a 34 37 3a 32 37 5a 22 20 6c 65 76 65 6c 3d 69 6e 66 6f 20 6d 73 67 ... >
<Buffer 02 00 00 00 00 00 00 82 74 69 6d 65 3d 22 32 30 32 31 2d 30 35 2d 31 31 54 30 38 3a 34 37 3a 32 37 5a 22 20 6c 65 76 65 6c 3d 77 61 72 6e 69 6e 67 20 ... >
<Buffer 02 00 00 00 00 00 00 64 74 69 6d 65 3d 22 32 30 32 31 2d 30 35 2d 31 31 54 30 38 3a 34 37 3a 32 37 5a 22 20 6c 65 76 65 6c 3d 69 6e 66 6f 20 6d 73 67 ... >
<Buffer 02 00 00 00 00 00 00 60 74 69 6d 65 3d 22 32 30 32 31 2d 30 35 2d 31 31 54 30 38 3a 34 37 3a 32 37 5a 22 20 6c 65 76 65 6c 3d 77 61 72 6e 69 6e 67 20 ... >

Translated to an UTF-8 string, this gives:

    "\u0002\u0000\u0000\u0000\u0000\u0000\u0000�time=\"2021-05-11T08:47:27Z\" level=warning msg=\"skipping containerd worker, as \\\"/run/containerd/containerd.sock\\\" does not exist\"\n",
    "\u0002\u0000\u0000\u0000\u0000\u0000\u0000dtime=\"2021-05-11T08:47:27Z\" level=info msg=\"found 1 workers, default=\\\"vd8qke8qoo98y1vo3yokyssrw\\\"\"\n",
    "\u0002\u0000\u0000\u0000\u0000\u0000\u0000`time=\"2021-05-11T08:47:27Z\" level=warning msg=\"currently, only the default worker can be used.\"\n",
    "\u0002\u0000\u0000\u0000\u0000\u0000\u0000\\time=\"2021-05-11T08:47:27Z\" level=info msg=\"running server on /run/buildkit/buildkitd.sock\"\n",
    "\u0002\u0000\u0000\u0000\u0000\u0000\u0000Otime=\"2021-05-13T15:04:37Z\" level=info msg=\"auto snapshotter: using overlayfs\"\n",
    "\u0002\u0000\u0000\u0000\u0000\u0000\u0000Rtime=\"2021-05-13T15:04:37Z\" level=warning msg=\"using host network as the default\"\n",
    "\u0002\u0000\u0000\u0000\u0000\u0000\u0001atime=\"2021-05-13T15:04:37Z\" level=info msg=\"found worker \\\"vd8qke8qoo98y1vo3yokyssrw\\\", labels=map[org.mobyproject.buildkit.worker.executor:oci org.mobyproject.buildkit.worker.hostname:662c0cfd0a89 org.mobyproject.buildkit.worker.snapshotter:overlayfs], platforms=[linux/amd64 linux/arm64 linux/ppc64le linux/s390x linux/386 linux/arm/v7 linux/arm/v6]\"\n",
    "\u0002\u0000\u0000\u0000\u0000\u0000\u0000�time=\"2021-05-13T15:04:37Z\" level=warning msg=\"skipping containerd worker, as \\\"/run/containerd/containerd.sock\\\" does not exist\"\n",
    "\u0002\u0000\u0000\u0000\u0000\u0000\u0000dtime=\"2021-05-13T15:04:37Z\" level=info msg=\"found 1 workers, default=\\\"vd8qke8qoo98y1vo3yokyssrw\\\"\"\n",
    "\u0002\u0000\u0000\u0000\u0000\u0000\u0000`time=\"2021-05-13T15:04:37Z\" level=warning msg=\"currently, only the default worker can be used.\"\n",
    "\u0002\u0000\u0000\u0000\u0000\u0000\u0000\\time=\"2021-05-13T15:04:37Z\" level=info msg=\"running server on /run/buildkit/buildkitd.sock\"\n"

The log file contains lines like this:

{"log":"time=\"2021-02-13T17:50:43Z\" level=info msg=\"auto snapshotter: using overlayfs\"\n","stream":"stderr","time":"2021-02-13T17:50:43.122733748Z"}
{"log":"time=\"2021-02-13T17:50:43Z\" level=warning msg=\"using host network as the default\"\n","stream":"stderr","time":"2021-02-13T17:50:43.122785591Z"}
{"log":"time=\"2021-02-13T17:50:43Z\" level=info msg=\"found worker \\\"vd8qke8qoo98y1vo3yokyssrw\\\", labels=map[org.mobyproject.buildkit.worker.executor:oci org.mobyproject.buildkit.worker.hostname:662
c0cfd0a89 org.mobyproject.buildkit.worker.snapshotter:overlayfs], platforms=[linux/amd64 linux/arm64 linux/ppc64le linux/s390x linux/386 linux/arm/v7 linux/arm/v6]\"\n","stream":"stderr","time":"2021-02-
13T17:50:43.129430342Z"}
{"log":"time=\"2021-02-13T17:50:43Z\" level=warning msg=\"skipping containerd worker, as \\\"/run/containerd/containerd.sock\\\" does not exist\"\n","stream":"stderr","time":"2021-02-13T17:50:43.13793810
3Z"}
{"log":"time=\"2021-02-13T17:50:43Z\" level=info msg=\"found 1 workers, default=\\\"vd8qke8qoo98y1vo3yokyssrw\\\"\"\n","stream":"stderr","time":"2021-02-13T17:50:43.137953377Z"}
{"log":"time=\"2021-02-13T17:50:43Z\" level=warning msg=\"currently, only the default worker can be used.\"\n","stream":"stderr","time":"2021-02-13T17:50:43.137973538Z"}
{"log":"time=\"2021-02-13T17:50:43Z\" level=info msg=\"running server on /run/buildkit/buildkitd.sock\"\n","stream":"stderr","time":"2021-02-13T17:50:43.141073587Z"}
{"log":"time=\"2021-02-13T17:52:32Z\" level=error msg=\"releasing already released reference\"\n","stream":"stderr","time":"2021-02-13T17:52:32.162341911Z"}

So it seems that the beginning of each line returned by container.logs is preprended with weird unprintable chars + one printable char...

Is this a bug or am I missing something?

[leolivier]

I finally resolved to fix it by removing the 8 first chars this way:

this.stream = await this.container.logs({ follow: true, stdout: true }) as Stream;
this.stream.on('data', (info: any) => console.log(info.toString('utf-8').slice(8));

[vanodevium]

It's docker internal logging prefix (8 symbols).

Better to be described in README

[skyclo]

It's docker internal logging prefix (8 symbols).

Better to be described in README

For those wondering, the documentation can be found here: https://docs.docker.com/engine/api/v1.41/#tag/Container/operation/ContainerAttach (subsection: Stream format)

[leolivier]

thank you @skyclo
Although it's not very hard to implement when you get this information, it's quite hard to get the info :)
So maybe worth adding utility methods in the API to implement this and hide this complexity?

[skyclo]

thank you @skyclo Although it's not very hard to implement when you get this information, it's quite hard to get the info :) So maybe worth adding utility methods in the API to implement this and hide this complexity?

I think adding utility methods (maybe something like isStdout(<chunk>)/isStderr(<chunk>)) would be useful. However, I'm not 100% sure if they are within the scope of this library. The dockerode package (similar scope) does not include any of these helper functions to my knowledge. As you said, its relatively easy when this information is made available.

Eventually I can make a pull request to this repo with some additional docs in the README or examples to show such functionality. I'm using this feature heavily, so I'd be willing to submit a PR.

Of course, that being said, the multiplexed stream is immediately removed in favor of raw data for TTY terminals. So far, from what I've seen, it still works with Tty: true when creating a container, however, TTY functionality and/or stdin doesn't work. Maybe I'm not using it right... who knows... I'll figure it out eventually. 🤷‍♂️

Since this is your package @AgustinCB, any thoughts on adding these doc changes or helper functions?