The unhandled exception could crash the deck-chores container

[vitoyucepi]

Summary

I found a case when managing the containers labels related to deck-chores could trigger various exceptions.

This exception causes the deck-chores container to crash.

Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/docker/api/client.py", line 268, in _raise_for_status
    response.raise_for_status()
  File "/usr/local/lib/python3.11/site-packages/requests/models.py", line 1021, in raise_for_status
    raise HTTPError(http_error_msg, response=self)
requests.exceptions.HTTPError: 404 Client Error: Not Found for url: http+docker://localhost/v1.41/containers/af2812dcb93a9b79e1460e7ce058887fe1e785e05868b46666780830d575fca2/json

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/deck_chores/main.py", line 320, in main
    listen(since=last_event_time + timedelta(microseconds=1))
  File "/usr/local/lib/python3.11/site-packages/deck_chores/main.py", line 204, in listen
    handle_die(event)
  File "/usr/local/lib/python3.11/site-packages/deck_chores/main.py", line 220, in handle_die
    if reassign_jobs(container_id, consider_paused=True) is None:
       ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/deck_chores/main.py", line 132, in reassign_jobs
    log.info(f"{container_name(container_id)}: Reassigning jobs to {new_id}.")
                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/deck_chores/indexes.py", line 13, in container_name
    return cfg.client.containers.get(container_id).name
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/docker/models/containers.py", line 925, in get
    resp = self.client.api.inspect_container(container_id)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/docker/utils/decorators.py", line 19, in wrapped
    return f(self, resource_id, *args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/docker/api/container.py", line 783, in inspect_container
    return self._result(
           ^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/docker/api/client.py", line 274, in _result
    self._raise_for_status(response)
  File "/usr/local/lib/python3.11/site-packages/docker/api/client.py", line 270, in _raise_for_status
    raise create_api_error_from_http_exception(e) from e
          ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/docker/errors.py", line 39, in create_api_error_from_http_exception
    raise cls(e, response=response, explanation=explanation) from e
docker.errors.NotFound: 404 Client Error for http+docker://localhost/v1.41/containers/af2812dcb93a9b79e1460e7ce058887fe1e785e05868b46666780830d575fca2/json: Not Found ("No such container: af2812dcb93a9b79e1460e7ce058887fe1e785e05868b46666780830d575fca2")

Reproduction

1. Start deck-chores docker run -it -v /var/run/docker.sock:/var/run/docker.sock -e TZ=UTC funkyfuture/deck-chores:1.3.10.
2. Create two compose configs for the same server.
   compose1.yaml

   services:
     test:
       image: alpine:3.17
       labels:
         deck-chores.test.command: env
         deck-chores.test.interval: every minute
       command: sleep 1000
       stop_grace_period: 1s

   compose2.yaml

   services:
     test:
       image: alpine:3.17
       labels:
         deck-chores.test.command: env
         deck-chores.test.interval: every second
       command: sleep 1000
       stop_grace_period: 1s

3. Run command docker-compose -f compose1.yaml up -d; docker-compose -f compose2.yaml up -d; docker-compose -f compose1.yaml up -d.

Version

• docker: 20.10.23
• docker-compose: 2.16.0
• deck-chores: 1.3.10

Additional

There are also other exceptions, but they don't terminate the container.

exception 1

Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/docker/api/client.py", line 268, in _raise_for_status
    response.raise_for_status()
  File "/usr/local/lib/python3.11/site-packages/requests/models.py", line 1021, in raise_for_status
    raise HTTPError(http_error_msg, response=self)
requests.exceptions.HTTPError: 404 Client Error: Not Found for url: http+docker://localhost/v1.41/containers/5b4187e9c9f99aba5ea729006bdb602f23cad836340af557841907c99669a315/exec

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/apscheduler/executors/base.py", line 125, in run_job
    retval = job.func(*job.args, **job.kwargs)
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/deck_chores/jobs.py", line 103, in exec_job
    return cfg.client.containers.get(container_id).exec_run(
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/docker/models/containers.py", line 193, in exec_run
    resp = self.client.api.exec_create(
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/docker/utils/decorators.py", line 19, in wrapped
    return f(self, resource_id, *args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/docker/api/exec_api.py", line 78, in exec_create
    return self._result(res, True)
           ^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/docker/api/client.py", line 274, in _result
    self._raise_for_status(response)
  File "/usr/local/lib/python3.11/site-packages/docker/api/client.py", line 270, in _raise_for_status
    raise create_api_error_from_http_exception(e) from e
          ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/docker/errors.py", line 39, in create_api_error_from_http_exception
    raise cls(e, response=response, explanation=explanation) from e
docker.errors.NotFound: 404 Client Error for http+docker://localhost/v1.41/containers/5b4187e9c9f99aba5ea729006bdb602f23cad836340af557841907c99669a315/exec: Not Found ("No such container: 5b4187e9c9f99aba5ea729006bdb602f23cad836340af557841907c99669a315")

Error notifying listener
Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/apscheduler/schedulers/base.py", line 835, in _dispatch_event
    cb(event)
  File "/usr/local/lib/python3.11/site-packages/deck_chores/jobs.py", line 67, in on_error
    definition = scheduler.get_job(event.job_id).kwargs
                 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
AttributeError: 'NoneType' object has no attribute 'kwargs'

exception 2

Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/docker/api/client.py", line 268, in _raise_for_status
    response.raise_for_status()
  File "/usr/local/lib/python3.11/site-packages/requests/models.py", line 1021, in raise_for_status
    raise HTTPError(http_error_msg, response=self)
requests.exceptions.HTTPError: 404 Client Error: Not Found for url: http+docker://localhost/v1.41/containers/771566280f258ced0e81f1e5128ef7e3872e633ef316cc3785374e3219eda983/exec

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/apscheduler/executors/base.py", line 125, in run_job
    retval = job.func(*job.args, **job.kwargs)
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/deck_chores/jobs.py", line 103, in exec_job
    return cfg.client.containers.get(container_id).exec_run(
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/docker/models/containers.py", line 193, in exec_run
    resp = self.client.api.exec_create(
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/docker/utils/decorators.py", line 19, in wrapped
    return f(self, resource_id, *args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/docker/api/exec_api.py", line 78, in exec_create
    return self._result(res, True)
           ^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/docker/api/client.py", line 274, in _result
    self._raise_for_status(response)
  File "/usr/local/lib/python3.11/site-packages/docker/api/client.py", line 270, in _raise_for_status
    raise create_api_error_from_http_exception(e) from e
          ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/docker/errors.py", line 39, in create_api_error_from_http_exception
    raise cls(e, response=response, explanation=explanation) from e
docker.errors.NotFound: 404 Client Error for http+docker://localhost/v1.41/containers/771566280f258ced0e81f1e5128ef7e3872e633ef316cc3785374e3219eda983/exec: Not Found ("No such container: 771566280f258ced0e81f1e5128ef7e3872e633ef316cc3785374e3219eda983")

exception 3

Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/docker/api/client.py", line 268, in _raise_for_status
    response.raise_for_status()
  File "/usr/local/lib/python3.11/site-packages/requests/models.py", line 1021, in raise_for_status
    raise HTTPError(http_error_msg, response=self)
requests.exceptions.HTTPError: 409 Client Error: Conflict for url: http+docker://localhost/v1.41/containers/49578007e090ab7dede4e73bec55a019afc6ed5a7e0dad045e7054c293923e3f/exec

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/apscheduler/executors/base.py", line 125, in run_job
    retval = job.func(*job.args, **job.kwargs)
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/deck_chores/jobs.py", line 103, in exec_job
    return cfg.client.containers.get(container_id).exec_run(
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/docker/models/containers.py", line 193, in exec_run
    resp = self.client.api.exec_create(
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/docker/utils/decorators.py", line 19, in wrapped
    return f(self, resource_id, *args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/docker/api/exec_api.py", line 78, in exec_create
    return self._result(res, True)
           ^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/docker/api/client.py", line 274, in _result
    self._raise_for_status(response)
  File "/usr/local/lib/python3.11/site-packages/docker/api/client.py", line 270, in _raise_for_status
    raise create_api_error_from_http_exception(e) from e
          ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/docker/errors.py", line 39, in create_api_error_from_http_exception
    raise cls(e, response=response, explanation=explanation) from e
docker.errors.APIError: 409 Client Error for http+docker://localhost/v1.41/containers/49578007e090ab7dede4e73bec55a019afc6ed5a7e0dad045e7054c293923e3f/exec: Conflict ("Container 49578007e090ab7dede4e73bec55a019afc6ed5a7e0dad045e7054c293923e3f is restarting, wait until the container is running")

[tabedzki]

I found a fun one that is in a similar vein to this: if you have jobs that occur at the same time (haven't figured out if it is start or finished) then you can easily crash the deck-chores container.

I tried it out for a bunch of different times (1s, 5s, 10s) and it can consistent cause an unhandled error and freeze the officer container.

services:
  officer:
    restart: always
    image: funkyfuture/deck-chores:1
    environment:
      TIMEZONE: "America/New York"
    volumes:
      - /var/run/docker.sock:/var/run/docker.sock

  neverending:
    restart: always
    image: alpine
    command: tail -f /dev/null
    labels:
      deck-chores.herenow.command: sh -c "echo 'mario'  &> /proc/1/fd/1"
      deck-chores.herenow.interval: every 10 seconds
      deck-chores.dump.command: sh -c 'echo hello > /proc/1/fd/1 2> /proc/1/fd/2'
      deck-chores.dump.interval: every 10  seconds
      deck-chores.kherenow.command: sh -c '>&2 echo error 2> /proc/1/fd/2'
      deck-chores.kherenow.interval: every 10 seconds

LOG:

 ➜  bug-reporting docker compose up
[+] Running 2/2
 ✔ Container bug-reporting-officer-1      Created                                                                                           0.0s 
 ✔ Container bug-reporting-neverending-1  Recreated                                                                                         0.0s 
Attaching to neverending-1, officer-1
officer-1      | Deck Chores 1.3.24 started.
officer-1      | 2025-02-21 00:59:53,110|INFO    |Inspecting running containers.
officer-1      | 2025-02-21 00:59:53,149|INFO    |bug-reporting-neverending-1: Added 'dump' (eeea07bd-c6f9-5488-930c-7d36bdbca92e).
officer-1      | 2025-02-21 00:59:53,149|INFO    |bug-reporting-neverending-1: Added 'herenow' (29710dc1-d225-5c83-9409-7b44bad09afb).
officer-1      | 2025-02-21 00:59:53,149|INFO    |bug-reporting-neverending-1: Added 'kherenow' (84b2324a-aa8b-51fd-bd9e-1949ec3bc2b8).
officer-1      | 2025-02-21 00:59:53,160|INFO    |Listening to events.
officer-1      | 2025-02-21 01:00:03,152|INFO    |bug-reporting-neverending-1: Executing 'dump'.
officer-1      | 2025-02-21 01:00:03,158|INFO    |bug-reporting-neverending-1: Executing 'herenow'.
officer-1      | 2025-02-21 01:00:03,162|INFO    |bug-reporting-neverending-1: Executing 'kherenow'.
neverending-1  | mario
neverending-1  | hello
officer-1      | 2025-02-21 01:00:03,241|INFO    |Command `sh -c '>&2 echo error 2> /proc/1/fd/2'` in container e66de7e99d61d09e5934bf28295d33e713cb309b8e9b4219133028e4f0959e58 finished with exit code 0.
officer-1      | 2025-02-21 01:00:03,242|INFO    |== BEGIN of captured stdout & stderr ==
officer-1      | 2025-02-21 01:00:03,242|INFO    |error
officer-1      | 2025-02-21 01:00:03,242|INFO    |== END of captured stdout & stderr ====
officer-1      | 2025-02-21 01:00:03,242|INFO    |Command `sh -c "echo 'mario'  &> /proc/1/fd/1"` in container e66de7e99d61d09e5934bf28295d33e713cb309b8e9b4219133028e4f0959e58 finished with exit code 0.
officer-1      | 2025-02-21 01:00:03,243|INFO    |Command `sh -c 'echo hello > /proc/1/fd/1 2> /proc/1/fd/2'` in container e66de7e99d61d09e5934bf28295d33e713cb309b8e9b4219133028e4f0959e58 finished with exit code 0.
officer-1      | 2025-02-21 01:00:13,149|INFO    |bug-reporting-neverending-1: Executing 'dump'.
officer-1      | 2025-02-21 01:00:13,155|INFO    |bug-reporting-neverending-1: Executing 'herenow'.
officer-1      | 2025-02-21 01:00:13,158|INFO    |bug-reporting-neverending-1: Executing 'kherenow'.
officer-1      | 2025-02-21 01:00:13,193|ERROR   |Caught an unhandled exception:
officer-1      | Traceback (most recent call last):
officer-1      |   File "/usr/local/lib/python3.12/site-packages/deck_chores/main.py", line 320, in main
officer-1      |     listen(since=last_event_time + timedelta(microseconds=1))
officer-1      |   File "/usr/local/lib/python3.12/site-packages/deck_chores/main.py", line 195, in listen
officer-1      |     event = json.loads(event_json)
officer-1      |             ^^^^^^^^^^^^^^^^^^^^^^
officer-1      |   File "/usr/local/lib/python3.12/json/__init__.py", line 346, in loads
officer-1      |     return _default_decoder.decode(s)
officer-1      |            ^^^^^^^^^^^^^^^^^^^^^^^^^^
officer-1      |   File "/usr/local/lib/python3.12/json/decoder.py", line 340, in decode
officer-1      |     raise JSONDecodeError("Extra data", s, end)
officer-1      | json.decoder.JSONDecodeError: Extra data: line 2 column 1 (char 1711)
neverending-1  | hello
neverending-1  | mario

[vitoyucepi]

Hi @tabedzki,
Your crash looks like a race condition. I think two concurrent jobs are outputting JSON to a single file without locking.