AttachContainer sometimes hangs

[gravis]

Hi,

I'm fighting with a nasty bug. Sometimes, but not always (a bit hard to reproduce), AttachContainer will hangs, eating 100% of CPU.
I have profiled my program and ended up with this (profiled during the hang):

(pprof) top
Total: 3002 samples
    1906  63.5%  63.5%     3002 100.0% github.com/fsouza/go-dockerclient/utils.StdCopy
    1096  36.5% 100.0%     1096  36.5% bufio.(*Reader).Read
       0   0.0% 100.0%     3002 100.0% github.com/fsouza/go-dockerclient.func·001
       0   0.0% 100.0%     3002 100.0% runtime.gosched0

I'm using the latest go-dockerclient (master / e21b2a4), and having the same problem with older versions (tried until 992e6ab)

My code is pretty standard:

  var buf bytes.Buffer
  opts := docker.AttachToContainerOptions{
      Container:    w.container.ID,
      OutputStream: &buf,
      Logs:         true,
      Stdout:       true,
      Stderr:       true,
  }
  err = w.client.AttachToContainer(opts)
  if err != nil {
      log.Printf("Error while fetching logs from container: %s\n", err)
  }

and works "most of the time" (99% of runs).

I'm not sure if it's related to docker, but here's my configuration:

Containers: 0
Images: 206
Storage Driver: aufs
 Root Dir: /var/lib/docker/aufs
 Dirs: 206
Execution Driver: native-0.2
Kernel Version: 3.2.0-4-amd64 

Any hint would be appreciated :)

[fsouza]

Which docker version are you using? I will try to reproduce. If you're using docker>=0.11, does it happen with the method Logs as well? It uses a different endpoint in the Docker API.

Is your container running anything special? Or are you able to reproduce it with any command?

[gravis]

I didn't know the Logs commands, thanks for pointing it. Will try and report in a few minutes.

My container doesn't run anything special, just a shell script to get bower dependencies, and it doesn't always hangs if I restart the process with the same params, just sometimes.

I'm running docker 1.1.0. By the way, the container is stopped (Exited (0) 2 minutes ago) when I try to fetch to output (logs).

[gravis]

Ok, so with Logs, it's a bit better.
I'm killing our api server, because most of the results are invalid json. There's a weird char before the response from the container:

buf.String() ��{"name":"angular-resource","versions":["1.3.0-build.2893+sha.5963b5c"," [...]

(from code:

var buf bytes.Buffer
opts := docker.LogsOptions{
    Container:    w.container.ID,
    OutputStream: &buf,
    Stdout:       true,
    Stderr:       true,
}
err = w.client.Logs(opts)
if err != nil {
    log.Printf("Error while fetching logs from container: %s\n", err)
}

fmt.Printf("buf.String() %+v\n", buf.String())

Where docker run simply returns:

{"name":"angular-resource","versions":["1.3.0-build.2893+sha.5963b5c"," [...]

[fsouza]

@gravis that's bizarre.

I'm able to reproduce the bug with the strange caracter in the method Logs, I will have a look.

I'm trying to reproduce now the attach issue.

Thanks for the reports!

[gravis]

That's "good" news, at least it's not related to my docker install nor my image/container :)
Thanks again for your time and patience.

[fsouza]

@gravis the bug is with the docker multiplexing capability. We need to interpret that character and find out whether it's stdout or stderr. utils.StdCopy does that for us.

I'll push a fix soon. Still trying to figure out the AttachToContainer issue.

[gravis]

Great!

Regarding AttachToContainer, were you able to reproduce it at least once?

[fsouza]

@gravis nope, not yet :(

[fsouza]

I fixed a bug in StdCopy implementation, I don't think it would hang, but it may be related.

I've also fixed the Logs issue. Can you give it another try (both for Logs and AttachToContainer)?

[gravis]

Great!

[gravis]

First test: Logs is hanging like AttachContainer now (+CPU @100%), so the issue is probably located around hijack or StdCopy

[fsouza]

Logs doesn't use hijack, so it's probably StdCopy. I'm still unable to reproduce, but I think we're closer to the solution now.

Please try setting RawTerminal: true on LogsOptions (or AttachToContainerOptions), you will get the bad characters again, but StdCopy won't get called.

[gravis]

Ouch, AttachContainer is returning weird chars now from container logs :(

d┘▒┼±⎺↑ce┌e⎼≤==2↓2↓7
d┘▒┼±⎺↑┐⎺└b┤>=▮↓9↓4
└☃└e⎻▒⎼⎽e>=▮↓1↓3
⎻≤├▒⎺┼↑d▒├e┤├☃┌==1↓5
⎻d°└☃┼e⎼==2▮11▮515
stripe==1.12.0
⎻≤c⎼≤⎻├⎺==2↓6
b⎺├⎺==2↓13↓3
d┘▒┼±⎺↑├☃└e≥⎺┼e⎽==▮↓2
d┘▒┼±⎺↑⎽e⎽==▮↓4↓1
Ge⎼▒┌d⎺==▮↓4↓16
d┘▒┼±⎺↑├▒⎽├≤⎻☃e==▮↓9↓12
┘⎺▒┼┼≤↑c▒c▒e==1↓4
d⎺c┤├☃┌⎽==▮↓9↓1
chardet==2.1.1
dj-database-url==0.2.1
psycopg2==2.4.5
gunicorn==0.17.2
django-s3-folder-storage==0.1
django-storages==1.1.5
python-memcached==1.48
W▒⎺⎺⎽▒==2↓4↓1
⎽☃└⎻┌e↑⎽▒┌e⎽°⎺⎼ce==▮↓51