Duplicate logs

[patrick-bark]

Hey, have been using logspout for about a week now and am running into some pretty serious duplicate log issues. The simple script I am running is having its logs duplicated over 1000 times. I have verified that its not log stash or the application causing it. I have installed to logstash plugin for it, and I'm not sure if thats somehow messing it up.

Here is my Dockerfile:

FROM gliderlabs/logspout:master
ENV SYSLOG_FORMAT rfc3164

and heres is my modules.go

package main

import (
    _ "github.com/gliderlabs/logspout/adapters/syslog"
    _ "github.com/gliderlabs/logspout/transports/tcp"
    _ "github.com/looplab/logspout-logstash"
    _ "github.com/gliderlabs/logspout/transports/udp"
)

I am using the latest image off of docker hub. Any idea what could be happening here.

[josegonzalez]

Do you have a repro I can setup of the problem so we can investigate?

[ebr]

Have been seeing the same for a while, on master.

It's very sporadic and next to impossible to reproduce. We occasionally get batches of 100,000+ identical log entries pushed to Loggly. I'm just using the syslog adapter. the loggly collector runs on the same host, listening on port 514. The logspout:master container is started with CMD syslog://172.17.0.1:514. I have not installed any extra plugins.

Stopping the logspout container and starting it again seems to help for a while (ranging from hours to days), but then it happens again and sometimes stops after a few minutes/hours, sometimes keeps pushing duplicate entries until I get an alert from Loggly about an overage.

I can provide any pertinent info about the environment, whatever you think may help.

[ebr]

I think I'm able to narrow it down to cases when my app crashes inside the container, and the container is restarted (NOT recreated, but restarted). It probably makes sense as the same behaviour would be expected from docker-compose logs -f: all the logs of the container since its creation would be dumped to stdout.

[josegonzalez]

Oh interesting. I'm not sure there is a good way around that if it's docker just spitting out the logs again. I'll do a bit of research to see if thats the case, as it sounds like a bug in docker if so, though I'm guessing there may be a way around it.

[ebr]

Thanks! I tried looking at the code myself, but it's way over my head so far :) Wondering if, when starting to tail the logs for a started container, might it be possible to not tail any preceding log entries (similar to docker logs --tail=0), and only follow the incoming entries?

[josegonzalez]

@ebr maybe we can add a case statement here for restart that has the second arg (backlog) set to false?

[ebr]

Oh nice, that looks like it should work! any idea if there's any particular reason to tail the backlog on restart as currently implemented?

[josegonzalez]

Not sure. Might be worth spelunking in the commit history for that section.

Can you make a PR for this with the fix (assuming you validate that it works)?

[ebr]

So the rabbit hole appears to go deeper.
I have a repro case set up here: https://github.com/ebr/logspout/tree/187-repro-case/test

Steps to reproduce:

1. docker-compose up -d
2. docker-compose logs -f crasher
3. (in 2nd shell) docker-compose logs -f syslog
4. (in 3rd shell) curl <docker_ip>:3000 a few times.
   • observe log entries come in to both crasher and syslog, as expected so far
5. docker-compose restart crasher
   • in 1st shell: observe crasher service logs, in received order
   • in 2nd shell: observe syslog dumping the entire backlog of the crasher container, with each entry from crasher duplicated and out-of order!
6. (in 3rd shell) curl <docker_ip>:3000 a few times again
   • in 1st shell: observe crasher service logging as expected
   • in 2nd shell: observe syslog duplicating every entry from now on.
7. subsequent restarts of the crasher service produce no further effect. the syslog entries continue to be repeated only twice (i.e. the number of duplications does not increase with service restarts).
8. Let's dig deeper: (4th shell): curl <docker_ip>:8000/logs - connect to logspout's http stream
9. (in 3rd shell) curl <docker_ip>:3000 a few times again
   • in 2nd shell: observe syslog logs, with each entry from crasher continuing to be duplicated.
   • in 4th shell: the http stream logs are coming in as expected, one at a time!
10. restart the crasher service again...
11. repeat the curl to the crasher service....
    • in 2nd shell: syslog still duplicated, as before.
    • in 4th shell: now the logs are duplicated in the http stream as well
12. in 4th shell, disconnect from http stream and reconnect again.
13. another curl to the crasher service...
    • syslog still duplicated
    • http stream now back to singular entries.

I tried the fix as discussed earlier in the thread: https://github.com/ebr/logspout/blob/46cbd3c751a3d961ecea05b8c17143619575d835/router/pump.go#L120-L123... but that had no effect.

any ideas? I'm quite far out of my waters here, but will continue to experiment....

[josegonzalez]

Might also need a fix here.

[TNuzzi]

Is there a fix for this issue?