Compose: Event watcher thread dies when service is restarted

[caervs]

When running

docker-compose up

and subsequently restarting one of the services (well after it is fully up) there seems to be an exception that causes the thread monitoring events to die. What I see in the original log stream is

bms_bms_1 exited with code 137
bms_bms_1 exited with code 137
Exception in thread Thread-9:
Traceback (most recent call last):
  File "threading.py", line 810, in __bootstrap_inner
  File "threading.py", line 763, in run
  File "compose/cli/log_printer.py", line 197, in watch_events
  File "compose/project.py", line 343, in events
  File "site-packages/docker/client.py", line 259, in _stream_helper
  File "json/__init__.py", line 338, in loads
  File "json/decoder.py", line 369, in decode
ValueError: Extra data: line 2 column 1 - line 2 column 616 (char 612 - 1227)

Since it's easy for me to reproduce I can do some debugging to try to provide some more detail.

[shin-]

Per our Slack exchange:

Seems like Client.events in docker-py sometimes receives multiple events at once and doesn't handle it properly. This needs to be fixed in docker-py.

[stromnet]

Was this perhaps fixed with https://github.com/docker/docker-py/issues/1059? I..e it should be working with current compose.

I have the same issue on Docker for Mac 1.12.1, which seems to include docker-compose 1.8.0

[shin-]

@stromnet That issue was fixed in docker-py 1.10 which is included in Compose 1.8.1. Unfortunately, the bug @caervs describes was reproduced using 1.8.1, indicating we're probably dealing with a slightly different incarnation of the issue.

[stromnet]

Running docker-compose version 1.8.1 878cff1 from homebrew, I've added some dump-code to dump the JSON it fails on.

The JSON below is sent in one long string, here beautified (and cleaned up a bit):

{
    "status": "start",
    "id": "23643fdeb531be28823e8ce18b009e1db5161989122fc125e2cf09f8a9263e10",
    "from": "nginx:1.11-alpine",
    "Type": "container",
    "Action": "start",
    "Actor": {
        "ID": "23643fdeb531be28823e8ce18b009e1db5161989122fc125e2cf09f8a9263e10",
        "Attributes": {
            "com.docker.compose.config-hash": "ff289be41eb800e7c429dbecdc02d4be08e6bea564b679713b33a35d6d2091b4",
            "com.docker.compose.container-number": "1",
            "com.docker.compose.oneoff": "False",
            "com.docker.compose.project": "xxxxyyyy",
            "com.docker.compose.service": "frontend",
            "com.docker.compose.version": "1.8.1",
            "image": "nginx:1.11-alpine",
            "name": "xxxxyyyy_frontend_1"
        }
    },
    "time": 1478780747,
    "timeNano": 1478780747846511815
}
{
    "status": "restart",
    "id": "23643fdeb531be28823e8ce18b009e1db5161989122fc125e2cf09f8a9263e10",
    "from": "nginx:1.11-alpine",
    "Type": "container",
    "Action": "restart",
    "Actor": {
        "ID": "23643fdeb531be28823e8ce18b009e1db5161989122fc125e2cf09f8a9263e10",
        "Attributes": {
            "com.docker.compose.config-hash": "ff289be41eb800e7c429dbecdc02d4be08e6bea564b679713b33a35d6d2091b4",
            "com.docker.compose.container-number": "1",
            "com.docker.compose.oneoff": "False",
            "com.docker.compose.project": "xxxxyyyy",
            "com.docker.compose.service": "frontend",
            "com.docker.compose.version": "1.8.1",
            "image": "nginx:1.11-alpine",
            "name": "xxxxyyyy_frontend_1"
        }
    },
    "time": 1478780747,
    "timeNano": 1478780747846596744
}

Hope it can help to find the issue.

[stromnet]

Actually, I was wrong.

Modified the code to dump failed values as hex:

xxxx_yyyy_1 exited with code 143
FAILED TO DECODE DATA '{"status":"start",..."timeNano":1478782525003457864}
{"status":"restart"...,timeNano":1478782525003728827}'
Hex bytes: ['0x7b', ....., '0x7d', '0xa', '0x7b', ..., '0x7d']

docker/client.py:

257                     # split the data at any newlines
258                     data_list = data.split("\r\n")

Data sent with \n only, docker/client.py splits on \r\n.
Changed to split on \n only, and now i cannot reproduce the error.

[eexit]

Hello,

I have the same issue when I restart my container:

Exception in thread Thread-2:
Traceback (most recent call last):
  File "threading.py", line 810, in __bootstrap_inner
  File "threading.py", line 763, in run
  File "compose/cli/log_printer.py", line 197, in watch_events
  File "compose/project.py", line 343, in events
  File "site-packages/docker/client.py", line 259, in _stream_helper
  File "json/__init__.py", line 338, in loads
  File "json/decoder.py", line 369, in decode
ValueError: Extra data: line 2 column 1 - line 2 column 662 (char 658 - 1319)

Docker version 1.12.3, build 6b644ec
docker-compose version 1.8.1, build 878cff1
Docker for Mac:
Version 1.12.3 (13776)
Channel: Stable
583d1b8ffe

[whitecolor]

Seem to be the same issue https://github.com/docker/compose/issues/4318

Also seem to be kind of important and annoying bug. Was it chased down?

[dkolba]

@shin- I still get this error on Docker for Mac:
Version 1.13.0 (15072)
Channel: Stable
0c6d765c54

[shin-]

@dkolba The Docker for Mac team has to vet the new version (1.10.1) and package it, so it might take a little bit of time until you can take advantage of the fix. Alternatively, you can install it manually https://github.com/docker/compose/releases/tag/1.10.1