Truncated logs

[megastef]

Hi,

sometimes the first few bytes of a log message are missing

O[30926] Registering on the discovery service every 20s...  

which should be

INFO[30926] Registering on the discovery service every 20s...  

Do you have any idea, how this could happen? When I use 'docker logs', I can see that 'INFO' is colored (ANSI Escape Sequence)

[cammellos]

Hi, could you give us more info about the exact command you are running and the image? thank you

[megastef]

First I've got the problem using the loghose API with Docker 1.9. Then I used docker-loghose command line to verify the problem, to see if it is not related to my parser. So I can confirm the loghose output is already wrong.

If you like to get shipyard logs as example, simply install shipyard. Then you might get the same message every 20 seconds (install command from https://shipyard-project.com/docs/deploy/automated/):

curl -sSL https://shipyard-project.com/deploy | bash -s

But I have seen similar things on other containers. e.g. jwilder/nginx-proxy - so my guess it is related to ANSI escape sequences/colored logs. Please note that the terminal output of "docker logs" in the example below is colored (see ANSI escape sequences like '\u001b[0m').

root@Ubuntu-2G:~/# docker-loghose 
{"v":0,"id":"e0e6fadcc1c1","image":"6b40fe7724bd29107f6182ca2befec011cdf524b23ebc4c9a33591d6b7aea4ee","name":"shipyard-swarm-agent","line":"O\u001b[0m[64589] Registering on the discovery service every 20s...  \u001b[34maddr\u001b[0m=45.55.75.34:2375 \u001b[34mdiscovery\u001b[0m=etcd://discovery:4001"}
{"v":0,"id":"e0e6fadcc1c1","image":"6b40fe7724bd29107f6182ca2befec011cdf524b23ebc4c9a33591d6b7aea4ee","name":"shipyard-swarm-agent","line":"O\u001b[0m[64609] Registering on the discovery service every 20s...  \u001b[34maddr\u001b[0m=45.55.75.34:2375 \u001b[34mdiscovery\u001b[0m=etcd://discovery:4001"}
{"v":0,"id":"e0e6fadcc1c1","image":"6b40fe7724bd29107f6182ca2befec011cdf524b23ebc4c9a33591d6b7aea4ee","name":"shipyard-swarm-agent","line":"O\u001b[0m[64629] Registering on the discovery service every 20s...  \u001b[34maddr\u001b[0m=45.55.75.34:2375 \u001b[34mdiscovery\u001b[0m=etcd://discovery:4001"}
^C
root@Ubuntu-2G:~/# docker logs -f e0e6fadcc1c1
INFO[0000] Registering on the discovery service every 20s...  addr=45.55.75.34:2375 discovery=etcd://discovery:4001
INFO[0020] Registering on the discovery service every 20s...  addr=45.55.75.34:2375 discovery=etcd://discovery:4001
INFO[0040] Registering on the discovery service every 20s...  addr=45.55.75.34:2375 discovery=etcd://discovery:4001
INFO[0060] Registering on the discovery service every 20s...  addr=45.55.75.34:2375 discovery=etcd://discovery:4001

[megastef]

The Docker API is OK. Printed buffer content in line 19 of https://github.com/mcollina/docker-loghose/blob/master/lib/parser.js

node ./loghose.js 
from docker api: INFO[73994] Registering on the discovery service every 20s...  addr=45.55.75.34:2375 discovery=etcd://discovery:4001
{"v":0,"id":"e0e6fadcc1c1","image":"6b40fe7724bd29107f6182ca2befec011cdf524b23ebc4c9a33591d6b7aea4ee","name":"shipyard-swarm-agent","line":"O\u001b[0m[73994] Registering on the discovery service every 20s...  \u001b[34maddr\u001b[0m=45.55.75.34:2375 \u001b[34mdiscovery\u001b[0m=etcd://discovery:4001"}

[cammellos]

That's good to know, could be just a matter of the characters not displaying on the console, I will have a look at it over the weekend, thanks a lot for the info!

On Wed, Dec 2, 2015 at 11:56 AM, Stefan Thies notifications@github.com wrote:

The Docker API is OK. Printed buffer content in line 19 of https://github.com/mcollina/docker-loghose/blob/master/lib/parser.js

node ./loghose.js from docker api: INFO[73994] Registering on the discovery service every 20s... addr=45.55.75.34:2375 discovery=etcd://discovery:4001 {"v":0,"id":"e0e6fadcc1c1","image":"6b40fe7724bd29107f6182ca2befec011cdf524b23ebc4c9a33591d6b7aea4ee","name":"shipyard-swarm-agent","line":"O\u001b[0m[73994] Registering on the discovery service every 20s... \u001b[34maddr\u001b[0m=45.55.75.34:2375 \u001b[34mdiscovery\u001b[0m=etcd://discovery:4001"}

— Reply to this email directly or view it on GitHub https://github.com/mcollina/docker-loghose/issues/4#issuecomment-161271060 .

[megastef]

I had to fix this, but I'm not sure if it is a general solution (it might emit empty lines). Here is what I did to get it working for me (just started with more tests): https://github.com/megastef/docker-loghose/blob/master/lib/parser.js

• Basically consuming the whole buffer, as I don't know, which header you try to parse
• So I removed most of your parsing stuff.

I will make a pull request, just to make it easier for you to see the differnces (don't need to be merged).

[megastef]

Just digging a bit more. For other logs/containers I've got a header. It looks some containers have a header and others not. It might depend on TTY status (attached or detached). https://github.com/docker/docker/issues/14201 And I found the header specifiction for the "attached" protocol.

header := [8]byte{STREAM_TYPE, 0, 0, 0, SIZE1, SIZE2, SIZE3, SIZE4}

So I understand now, what the parser is doing :) enlightment.

To my current understandig, docker-loghose has to find out if the buffers include a header or not.

[mcollina]

A couple of questions:

• which version of Docker are you on? It might be a change in the API from docker, or a bug there.
• would you minding providing two examples (one working, one not) that shows the problem so we can reproduce it?

It seems that we need a way to know if the header is present or not, or to control it.

[megastef]

• Docker 1.9 - I don't think it is a docker bug (well having header or not, but as far I read here https://github.com/docker/docker/issues/14201 it depends on TTY).
• I modified my local loghose to dump some raw buffers (see examples)
• Examples.

• Shipyard agent, running detached (not working missing 'INF' from start). The real data including ANSI escape sequences, having no header(!) looks like:

  \u001b[34mINFO\u001b[0m[92163] Registering on the discovery service every 20s...  \u001b[34maddr\u001b[0m=45.55.75.34:2375 \u001b[34mdiscovery\u001b[0m=etcd://discovery:4001

  In this case loghose cuts 8 chars (header) and I get only the "O" from colored "INFO".

  1. Working: docker run --rm redis (attached to terminal), has a header

\u0001\u0000\u0000\u0000\u0000\u0000\u0001\u0010Received SIGINT scheduling shutdown...\n

[megastef]

I played more, and added a header detection, which seems to work well. Of course this could be done more efficent like reading int32 and compare bit pattern. https://github.com/megastef/docker-loghose/blob/master/lib/parser.js Will run it on my docker hosts to see if I get any problem with other logs.

[mcollina]

I would have to admit that a more sensible approach might be to use https://docs.docker.com/engine/reference/api/docker_remote_api_v1.19/#inspect-a-container and check the tty property, if true then there is a header, if not there isn't. We can programmatically check for this. (we should have been doing this from the very beginning).

However the problem should happen only with containers with an attached tty, not for production containers:

When using the TTY setting is enabled in POST /containers/create , the stream is the raw data from the process PTY and client’s stdin. When the TTY is disabled, then the stream is multiplexed to separate stdout and stderr.

You said you are running it detached and you get no header, then it's a docker bug according to their own spec. Or maybe their doc is not clear.

[megastef]

+1 to inspect the container first. But can the TTY property change? E.g. if somebody uses "docker exec -it" ?

Here are the 'docker inspect' details of the shipyard agent:

"Tty": true,
"OpenStdin": true,
"StdinOnce": false,

"When using the TTY setting is enabled in POST /containers/create , the stream is the raw data from the process PTY and client’s stdin." -> So it is correct, that the shipyard-agent container has no header. But pls. don't ask me why 'Tty' is set to 'true'.

Complete Docker Inspect result:

docker inspect shipyard-swarm-agent
[
{
    "Id": "e0e6fadcc1c1b95a86eb71fc2bc7e931a4e9c09b170cfc4c12851bf4c1c86162",
    "Created": "2015-11-27T12:44:25.313118134Z",
    "Path": "/swarm",
    "Args": [
        "j",
        "--addr",
        "45.55.75.34:2375",
        "etcd://discovery:4001"
    ],
    "State": {
        "Running": true,
        "Paused": false,
        "Restarting": false,
        "OOMKilled": false,
        "Dead": false,
        "Pid": 2715,
        "ExitCode": 0,
        "Error": "",
        "StartedAt": "2015-12-03T12:52:49.114727119Z",
        "FinishedAt": "2015-12-03T12:52:36.332799372Z"
    },
    "Image": "6b40fe7724bd29107f6182ca2befec011cdf524b23ebc4c9a33591d6b7aea4ee",
    "NetworkSettings": {
        "Bridge": "",
        "EndpointID": "01eb9d733ed9ac4b8849fb1400185efc2649853def89569294333cf763aee8a3",
        "Gateway": "172.17.42.1",
        "GlobalIPv6Address": "",
        "GlobalIPv6PrefixLen": 0,
        "HairpinMode": false,
        "IPAddress": "172.17.0.4",
        "IPPrefixLen": 16,
        "IPv6Gateway": "",
        "LinkLocalIPv6Address": "",
        "LinkLocalIPv6PrefixLen": 0,
        "MacAddress": "02:42:ac:11:00:04",
        "NetworkID": "3bfb5b5bdd7d2d098ce661f5261894f91f14cafe59db3ae4f7be48a67a769e97",
        "PortMapping": null,
        "Ports": {
            "2375/tcp": null
        },
        "SandboxKey": "/var/run/docker/netns/e0e6fadcc1c1",
        "SecondaryIPAddresses": null,
        "SecondaryIPv6Addresses": null
    },
    "ResolvConfPath": "/var/lib/docker/containers/e0e6fadcc1c1b95a86eb71fc2bc7e931a4e9c09b170cfc4c12851bf4c1c86162/resolv.conf",
    "HostnamePath": "/var/lib/docker/containers/e0e6fadcc1c1b95a86eb71fc2bc7e931a4e9c09b170cfc4c12851bf4c1c86162/hostname",
    "HostsPath": "/var/lib/docker/containers/e0e6fadcc1c1b95a86eb71fc2bc7e931a4e9c09b170cfc4c12851bf4c1c86162/hosts",
    "LogPath": "/var/lib/docker/containers/e0e6fadcc1c1b95a86eb71fc2bc7e931a4e9c09b170cfc4c12851bf4c1c86162/e0e6fadcc1c1b95a86eb71fc2bc7e931a4e9c09b170cfc4c12851bf4c1c86162-json.log",
    "Name": "/shipyard-swarm-agent",
    "RestartCount": 0,
    "Driver": "aufs",
    "ExecDriver": "native-0.2",
    "MountLabel": "",
    "ProcessLabel": "",
    "AppArmorProfile": "",
    "ExecIDs": null,
    "HostConfig": {
        "Binds": null,
        "ContainerIDFile": "",
        "LxcConf": [],
        "Memory": 0,
        "MemorySwap": 0,
        "CpuShares": 0,
        "CpuPeriod": 0,
        "CpusetCpus": "",
        "CpusetMems": "",
        "CpuQuota": 0,
        "BlkioWeight": 0,
        "OomKillDisable": false,
        "MemorySwappiness": -1,
        "Privileged": false,
        "PortBindings": {},
        "Links": [
            "/shipyard-discovery:/shipyard-swarm-agent/discovery"
        ],
        "PublishAllPorts": false,
        "Dns": null,
        "DnsSearch": null,
        "ExtraHosts": null,
        "VolumesFrom": null,
        "Devices": [],
        "NetworkMode": "default",
        "IpcMode": "",
        "PidMode": "",
        "UTSMode": "",
        "CapAdd": null,
        "CapDrop": null,
        "GroupAdd": null,
        "RestartPolicy": {
            "Name": "always",
            "MaximumRetryCount": 0
        },
        "SecurityOpt": null,
        "ReadonlyRootfs": false,
        "Ulimits": null,
        "LogConfig": {
            "Type": "json-file",
            "Config": {}
        },
        "CgroupParent": "",
        "ConsoleSize": [
            0,
            0
        ]
    },
    "GraphDriver": {
        "Name": "aufs",
        "Data": null
    },
    "Mounts": [
        {
            "Name": "89b0cca8d0af865d9a2944695088814a29d2c046a7d3f927968d8ba390901479",
            "Source": "/var/lib/docker/volumes/89b0cca8d0af865d9a2944695088814a29d2c046a7d3f927968d8ba390901479/_data",
            "Destination": "/.swarm",
            "Driver": "local",
            "Mode": "",
            "RW": true
        }
    ],
    "Config": {
        "Hostname": "e0e6fadcc1c1",
        "Domainname": "",
        "User": "",
        "AttachStdin": false,
        "AttachStdout": false,
        "AttachStderr": false,
        "ExposedPorts": {
            "2375/tcp": {}
        },
        "Tty": true,
        "OpenStdin": true,
        "StdinOnce": false,
        "Env": [
            "SWARM_HOST=:2375"
        ],
        "Cmd": [
            "j",
            "--addr",
            "45.55.75.34:2375",
            "etcd://discovery:4001"
        ],
        "Image": "swarm:latest",
        "Volumes": {
            "/.swarm": {}
        },
        "WorkingDir": "",
        "Entrypoint": [
            "/swarm"
        ],
        "OnBuild": null,
        "Labels": {}
    }
}
]

[megastef]

Ok, we got clarification in https://github.com/docker/docker/issues/14201 Here is the challenges to follow somehow the TTY status of the container. Loghose should use the initial TTY status at least. BTW. My fork works well, but in a few rare cases (probably multiple headers in one buffer? -> introduce again the while loop ..) i still can find non parsed headers.

[mcollina]

I'm :+1: to just check the original TTY status of the container: I think that could never be changed (see https://github.com/docker/docker/issues/14201#issuecomment-163617025).

Anybody that wants to send a PR for that?

[cammellos]

I am happy to take a look at it, hopefully should have enough time this weekend / over holidays. cheers

On Mon, Dec 14, 2015 at 11:36 AM, Matteo Collina notifications@github.com wrote:

I'm [image: :+1:] to just check the original TTY status of the container: I think that could never be changed (see docker/docker#14201 (comment) https://github.com/docker/docker/issues/14201#issuecomment-163617025).

Anybody that wants to send a PR for that?

— Reply to this email directly or view it on GitHub https://github.com/mcollina/docker-loghose/issues/4#issuecomment-164416063 .

[megastef]

+1 check tty for new containers and parse then right. I moved my packages to my fork, as it works at least a bit better then the current loghose version (better a char too much then 8 lost). And I will move back as soon loghose is in good shape.

Happy Holidays, in any case!

[megastef]

Hi, happy new year! Any news for this issue?

[cammellos]

Hi Stefan, I have pushed some changes to a branch: https://github.com/cammellos/docker-loghose/tree/ttyParser , it's still a bit rough and needs a bit more testing & polishing, but should be working already, feel free to try it out :) I will ask Matteo if it's ok with the overall strategy, and if it so send a pull request after a bit of refactoring, let me know if it works for you. cheers

On Wed, Jan 6, 2016 at 6:55 PM, Stefan Thies notifications@github.com wrote:

Hi, happy new year! Any news for this issue?

— Reply to this email directly or view it on GitHub https://github.com/mcollina/docker-loghose/issues/4#issuecomment-169419259 .

[megastef]

Hi, just started a test with https://github.com/cammellos/docker-loghose/tree/ttyParser and the problematic logs (from shipyard containers) are complete! Thanks a lot.

[mcollina]

@cammellos @megastef how about a PR? :)

[cammellos]

Hi Matteo, sure, I have separated the parsers in two different classes, as they have quite different behaviors when tty is enabled, if that's ok with you, I will refactor a few things and send a pull request. cheers andrea

On Mon, Jan 11, 2016 at 11:37 AM, Matteo Collina notifications@github.com wrote:

@cammellos https://github.com/cammellos @megastef https://github.com/megastef how about a PR? :)

— Reply to this email directly or view it on GitHub https://github.com/mcollina/docker-loghose/issues/4#issuecomment-170515809 .

[mcollina]

This should be fixed as 0.8.0.

[megastef]

Thank You!

[megastef]

It seems this issue is not solved. @cammellos could you pls. check this comment: https://github.com/sematext/sematext-agent-docker/issues/26#issuecomment-293864471

[cammellos]

thanks I will have a look

[cammellos]

Ok, I managed to replicate it locally, long lines seem to trigger this behaviour:

"ILMNOPQR\u0001\u0000\u0000\u0000\u0000\u0000�\u00..."

I will have a look at it this weekend and try to push a fix, thanks for reporting the issue.

[cammellos]

Hey @megastef , I have pushed a fix here https://github.com/mcollina/docker-loghose/tree/fix-long-lines, I have tested it locally and it seems to be working, before sending a pr would you mind having a look at it? thanks!

[megastef]

Thx @cammellos - I'm going to check the fix.

[megastef]

@cammellos Looks good. We used 50 kbyte long log lines. We will wait for the client to test it in his environment.

[cammellos]

Sweet, let me know how it goes and I'll polish things up and send a PR, thanks!

[ReToCode]

Nice work, looks very good!

[megastef]

Released on npm v1.5.1 (sorry I used release-it tool, it bumps version, pushes the release tag to github and runs then npm publish). I had a little issue with npm publish, but solved it this morning.