extra characters prepended to logs

[gmelika]

After upgrading to 3.2.3 logspout started adding weird characters to the beginning of every line. For example

�time="2017-10-04T01:20:14Z" level=info msg="Done checkpointing in-memory metrics and chunks in 1.404599334s." source="persistence.go:665"
xtime="2017-10-04T01:25:14Z" level=info msg="Checkpointing in-memory metrics and chunks..." source="persistence.go:633"
�time="2017-10-04T01:25:16Z" level=info msg="Done checkpointing in-memory metrics and chunks in 1.506158531s." source="persistence.go:665"
xtime="2017-10-04T01:30:16Z" level=info msg="Checkpointing in-memory metrics and chunks..." source="persistence.go:633"
�time="2017-10-04T01:30:17Z" level=info msg="Done checkpointing in-memory metrics and chunks in 1.52509546s." source="persistence.go:665"
xtime="2017-10-04T01:35:17Z" level=info msg="Checkpointing in-memory metrics and chunks..." source="persistence.go:633"
�time="2017-10-04T01:35:19Z" level=info msg="Done checkpointing in-memory metrics and chunks in 1.49991571s." source="persistence.go:665"
xtime="2017-10-04T01:40:19Z" level=info msg="Checkpointing in-memory metrics and chunks..." source="persistence.go:633"
�time="2017-10-04T01:40:20Z" level=info msg="Done checkpointing in-memory metrics and chunks in 1.417177673s." source="persistence.go:665"
xtime="2017-10-04T01:45:20Z" level=info msg="Checkpointing in-memory metrics and chunks..." source="persistence.go:633"
�time="2017-10-04T01:45:22Z" level=info msg="Done checkpointing in-memory metrics and chunks in 1.480621256s." source="persistence.go:665"
xtime="2017-10-04T01:50:22Z" level=info msg="Checkpointing in-memory metrics and chunks..." source="persistence.go:633"
�time="2017-10-04T01:50:23Z" level=info msg="Done checkpointing in-memory metrics and chunks in 1.516549895s." source="persistence.go:665"
xtime="2017-10-04T01:55:23Z" level=info msg="Checkpointing in-memory metrics and chunks..." source="persistence.go:633"
�time="2017-10-04T01:55:25Z" level=info msg="Done checkpointing in-memory metrics and chunks in 1.527579546s." source="persistence.go:665"
xtime="2017-10-04T02:00:25Z" level=info msg="Checkpointing in-memory metrics and chunks..." source="persistence.go:633"
�time="2017-10-04T02:00:26Z" level=info msg="Done checkpointing in-memory metrics and chunks in 1.341651987s." source="persistence.go:665"
xtime="2017-10-04T02:05:26Z" level=info msg="Checkpointing in-memory metrics and chunks..." source="persistence.go:633"
�time="2017-10-04T02:05:28Z" level=info msg="Done checkpointing in-memory metrics and chunks in 1.350708813s." source="persistence.go:665"
xtime="2017-10-04T02:10:28Z" level=info msg="Checkpointing in-memory metrics and chunks..." source="persistence.go:633"
�time="2017-10-04T02:10:29Z" level=info msg="Done checkpointing in-memory metrics and chunks in 1.404537061s." source="persistence.go:665"
xtime="2017-10-04T02:15:29Z" level=info msg="Checkpointing in-memory metrics and chunks..." source="persistence.go:633"
�time="2017-10-04T02:15:30Z" level=info msg="Done checkpointing in-memory metrics and chunks in 1.383589267s." source="persistence.go:665"

Any idea how to get rid of this?

[gmelika]

fyi, downgrading to 3.2.2 fixed the issue

[jgreat]

Looks like this is an undocumented "feature" of streaming the docker logs api. Docker is putting a 8 byte header on the front of each docker line. The header gets turned into unicode characters when you convert it to a string.

This guy has a good overview: https://medium.com/@dhanushgopinath/reading-docker-container-logs-with-golang-docker-engine-api-702233fac044

[je-al]

Hmm, any chance we can add a flag into the above merged code to disable the "drop the first 8 bytes" behaviour?, I was recently struck by it since we're (foolishly, but in not-in-prod) using an derivative image https://hub.docker.com/r/bekt/logspout-logstash which tracks master instead of specific releases (with no hash being specified), but it surfaced the fact that this (AFAICT haven't actually dug deep into the issue) is not happening in older versions of the docker API, and it manifested itself in our configuration as the first 8 characters from the message field (we're using looplab's logstash-logspout adapter, hence the custom image) being dropped, which took a while to debug, 'cause it's pretty weird.

[michaelshobbs]

@jgreat ping ☝️

[jgreat]

First :-1: on https://hub.docker.com/r/bekt/logspout-logstash not tagging releases.

There are 2 checks in there already.

1.) Has the container set TTY=false If the container has TTY set to true the log stream does not include the header, so we don't drop it.

2.) Docker Server API >= 1.13 (Docker version 1.5.x ish) This took a little bit of guessing on when this header was introduced into the stream. Docker has never documented this "feature". I tested back to API 1.22 (Docker 1.10.3) and there are GitHub issue references back to API 1.13.

@je-al can you let me know what docker server api version (docker version should show) you are running?

[je-al]

@jgreat Running swarm-mode, if it makes any difference...

Server:
 Version:      17.06.1-ee-2
 API version:  1.30 (minimum version 1.12)
 Go version:   go1.8.3
 Git commit:   8e43158
 Built:        Wed Aug 23 21:19:53 2017
 OS/Arch:      linux/amd64
 Experimental: false

[jgreat]

@je-al I'm scratching my head on this. We are running almost the same version, api 1.30/17.06.0-ce.

Can you run logspout with DEBUG=true environment var? I'm curious what api version/TTY is detected. You should see something like this for each container on the system:

2017/11/07 01:44:04 API Version:  1.30
2017/11/07 01:44:04 TTY is:  false
2017/11/07 01:44:04 hasHeaders set to:  true
2017/11/07 01:44:04 pump.pumpLogs(): 15dcee1a6ad6 started, tail: all

[je-al]

@jgreat

2017/11/07 14:02:16 setting allowTTY to: false
# logspout v3.3-dev-custom by gliderlabs
# adapters: logstash raw udp tcp
# options : debug:t persist:/mnt/routes
# jobs    : http[]:80 pump routes
# routes  :
#   ADAPTER      ADDRESS         CONTAINERS              SOURCES OPTIONS
#   logstash+tcplogstash:5000    com.xxxx.log:t             map[]
2017/11/07 14:02:16 pump.Run(): using inactivity timeout:  1m0s
2017/11/07 14:02:16 API Version:  1.30
2017/11/07 14:02:16 TTY is:  false
2017/11/07 14:02:16 hasHeaders set to:  true
2017/11/07 14:02:16 pump.pumpLogs(): 37728917402f started, tail: 512

this is what I get with the stdout rubydebug output:

{
    "@timestamp" => 2017-11-07T13:49:08.429Z,
        "stream" => "stdout",
          "port" => 46322,
      "@version" => "1",
          "host" => "10.30.10.11",
       "message" => "07 13:49:08 Got configuration from http://dfsl:8080.",
        "docker" => {
           "image" => "vfarcic/docker-flow-proxy:17.09.14-15@sha256:9aff1d1b8da3aaf355b92249eb0f92c88fa68be77479e94e21bf84d32d16dc6c",
        "hostname" => "42c8e72ae5bd",
            "name" => "/proxy_dfp.2.xrdpme3etpu1vbijx8s5lmbjb",
              "id" => "42c8e72ae5bdf2254cb99add47e8ee4d1f8b43edb9473a362355f5cdd803db4d",
          "labels" => {
                                                "com_docker_stack_namespace" => "proxy",
                                                 "com_docker_ucp_collection" => "7b5b835d-196e-43a8-afff-dba7cdbf53e3",
                                                     "com_xxxx_logType" => "proxy_backend",
                                                     "com_docker_swarm_task" => "",
                                               "com_docker_ucp_access_label" => "/Shared/xxxx/proxy",
                                          "com_docker_ucp_collection_shared" => "true",
                                                "com_docker_swarm_task_name" => "proxy_dfp.2.xrdpme3etpu1vbijx8s5lmbjb",
                                            "com_docker_ucp_collection_root" => "true",
                                                         "com_xxxx_log" => "t",
                                             "com_docker_swarm_service_name" => "proxy_dfp",
                                                  "com_docker_swarm_task_id" => "xrdpme3etpu1vbijx8s5lmbjb",
                                                  "com_docker_swarm_node_id" => "0jnqmd2muqmvok78zjeluiw80",
                                               "com_docker_swarm_service_id" => "fxmo3un3fsxrdk7zuaesidfch",
            "com_docker_ucp_collection_5f656e65-c5ac-4916-a119-8034cddabc88" => "true",
            "com_docker_ucp_collection_7b5b835d-196e-43a8-afff-dba7cdbf53e3" => "true",
                                           "com_docker_ucp_collection_swarm" => "true"
        }
    },
          "tags" => [
        [0] "test",
        [1] "docker",
        [2] "_grokparsefailure"
    ]
}

as you can see the message is missing the first 8 chars: YYYY-MM-

[jgreat]

@je-al you don't happen to have a filter in your logstash pipeline that is dropping the "unicode garbage" from the beginning of the message? So we are now "fixing" the message twice.

[je-al]

@jgreat Nope, I actually removed everything from the filter stage to test whether it was our doing... (not in that particular example, mind you)

[jgreat]

I'm out of ideas. I can't think of a reason why your setup would be different.

I'll think on a better way to detect if the headers are on the stream. If I can't figure out a better way I'll put a PR in for an environment var switch.

[jgreat]

@je-al I think I figured it out. Its the ALLOW_TTY option the difference between our setups.

When ALLOW_TTY true is set, logspout is setting the RawTerminal option on the docker.client.Logs() function. This is being done on all containers, not just the ones with Tty=true. This being set on Tty=false containers is what is causing the headers to be included in the log stream and the problem that I was trying to fix.

For the moment if you set ALLOW_TTY=true it won't eat the beginning of the log entry. I will work on getting a fix in the next couple of days.

[je-al]

@jgreat I can't speak to whether the logic is right, but I tested setting ALLOW_TTY: "true" in my compose-file definition (deployed through stack deploy) and what I'm getting is a bunch of: "message" => "Error grabbing logs: EOF", Dunno if it's actually related thought, 'cause it seems to be logspout reading the "backlog" of messages for the containers... It, however, doesn't happen with tagged releases.

[jgreat]

@je-al can you try out this fix :arrow_up:

I have a container built with the logstash plugin here: jgreat/logspout:logstash.smarter-fix-log-header-bytes.1

[je-al]

@jgreat yup, it seems to work just fine