A replacing Docker-Compose service container's (diverging) jobs are ignored

[vitoyucepi]

Summary

If I change the time interval in compose.yaml, the job is not rescheduled.
If I change the command in compose.yaml, the job command doesn't change.

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: echo 1
         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.

Expected behavior

After changing labels and redeploying, jobs should change.

Actual behavior

After changing labels and redeploying, jobs remain the same.

Versions

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

Additional

Maybe related to #113.

[funkyfuture]

i cannot reproduce what you describe. please invoke deck-chores in debug mode and post its output here.

docker run -e DEBUG=on -v /var/run/docker.sock:/var/run/docker.sock -e TZ=UTC funkyfuture/deck-chores:1.3.10

[vitoyucepi]

Hi @funkyfuture,

Log

2023-04-12 15:40:53,457|DEBUG   |Config: {'assert_hostname': False, 'client_timeout': 60, 'default_flags': ('image', 'service'), 'docker_host': 'unix://var/run/docker.sock', 'debug': True, 'default_max': 1, 'job_executor_pool_size': 10, 'job_name_regex': '[a-z0-9-]+', 'label_ns': 'deck-chores.', 'logformat': '{asctime}|{levelname:8}|{message}', 'service_identifiers': ('com.docker.compose.project', 'com.docker.compose.service'), 'stderr_level': 0, 'timezone': 'UTC', 'client': <docker.client.DockerClient object at 0x7f4267d1d3d0>}
2023-04-12 15:40:53,461|INFO    |Inspecting running containers.
2023-04-12 15:40:53,465|DEBUG   |Parsing labels: {'io.buildah.version': '1.23.1', 'org.opencontainers.image.created': '2023-03-26T04:52:26.532Z', 'org.opencontainers.image.description': 'A job scheduler for Docker containers, configured via labels.', 'org.opencontainers.image.documentation': 'https://deck-chores.readthedocs.org/', 'org.opencontainers.image.licenses': 'ISC', 'org.opencontainers.image.revision': '4ddd9d14a27928467a275eeac788272664173b30', 'org.opencontainers.image.source': 'https://github.com/funkyfuture/deck-chores', 'org.opencontainers.image.title': 'deck-chores', 'org.opencontainers.image.url': 'https://deck-chores.readthedocs.org/', 'org.opencontainers.image.version': '1.3.10'}
2023-04-12 15:40:53,465|DEBUG   |Considering labels for service id: {}
2023-04-12 15:40:53,465|DEBUG   |Parsed & resolved container flags: image,service
2023-04-12 15:40:53,467|DEBUG   |Considering labels for job definitions: {}
2023-04-12 15:40:53,467|DEBUG   |Job definitions: {}
2023-04-12 15:40:53,467|DEBUG   |Finished inspection of running containers.
2023-04-12 15:40:53,469|INFO    |Scheduler started
2023-04-12 15:40:53,470|DEBUG   |Looking for jobs to run
2023-04-12 15:40:53,470|DEBUG   |No jobs; waiting until a job is added
2023-04-12 15:40:53,470|INFO    |Listening to events.
2023-04-12 15:41:15,118|DEBUG   |Daemon event: {'status': 'start', 'id': '024277f43d07dbd147c94e0472a20fa529998fb1e537bd729c4c77c2884d8b57', 'from': 'alpine:3.17', 'Type': 'container', 'Action': 'start', 'Actor': {'ID': '024277f43d07dbd147c94e0472a20fa529998fb1e537bd729c4c77c2884d8b57', 'Attributes': {'com.docker.compose.config-hash': '90e7dd807be9f827d48e1eb2dbf28b0bdbb764d718a75f75919746a5464774f4', 'com.docker.compose.container-number': '1', 'com.docker.compose.depends_on': '', 'com.docker.compose.image': 'sha256:9ed4aefc74f6792b5a804d1d146fe4b4a2299147b0f50eaf2b08435d7b38c27e', 'com.docker.compose.oneoff': 'False', 'com.docker.compose.project': 'test', 'com.docker.compose.project.config_files': '/tmp/test/compose1.yaml', 'com.docker.compose.project.working_dir': '/tmp/test', 'com.docker.compose.service': 'test', 'com.docker.compose.version': '2.17.2', 'deck-chores.test.command': 'env', 'deck-chores.test.interval': 'every minute', 'image': 'alpine:3.17', 'name': 'test-test-1'}}, 'scope': 'local', 'time': 1681314075, 'timeNano': 1681314075116863194}
2023-04-12 15:41:15,118|DEBUG   |Handling start of 024277f43d07dbd147c94e0472a20fa529998fb1e537bd729c4c77c2884d8b57.
2023-04-12 15:41:15,123|DEBUG   |Parsing labels: {'com.docker.compose.config-hash': '90e7dd807be9f827d48e1eb2dbf28b0bdbb764d718a75f75919746a5464774f4', 'com.docker.compose.container-number': '1', 'com.docker.compose.depends_on': '', 'com.docker.compose.image': 'sha256:9ed4aefc74f6792b5a804d1d146fe4b4a2299147b0f50eaf2b08435d7b38c27e', 'com.docker.compose.oneoff': 'False', 'com.docker.compose.project': 'test', 'com.docker.compose.project.config_files': '/tmp/test/compose1.yaml', 'com.docker.compose.project.working_dir': '/tmp/test', 'com.docker.compose.service': 'test', 'com.docker.compose.version': '2.17.2', 'deck-chores.test.command': 'env', 'deck-chores.test.interval': 'every minute'}
2023-04-12 15:41:15,124|DEBUG   |Considering labels for service id: {'com.docker.compose.project': 'test', 'com.docker.compose.service': 'test'}
2023-04-12 15:41:15,131|DEBUG   |Considering labels for job definitions: {'deck-chores.test.command': 'env', 'deck-chores.test.interval': 'every minute'}
2023-04-12 15:41:15,131|DEBUG   |Job definitions: {'test': {'command': 'env', 'interval': 'every minute'}}
2023-04-12 15:41:15,131|DEBUG   |Processing test
2023-04-12 15:41:15,138|DEBUG   |Normalized definition: {'command': 'env', 'name': 'test', 'user': '', 'environment': {}, 'max': 1, 'timezone': 'UTC', 'trigger': (<class 'apscheduler.triggers.interval.IntervalTrigger'>, (0, 0, 0, 1, 0))}
2023-04-12 15:41:15,138|DEBUG   |Assigning service id: ('com.docker.compose.project=test', 'com.docker.compose.service=test')
2023-04-12 15:41:15,139|DEBUG   |Added lock for service ('com.docker.compose.project=test', 'com.docker.compose.service=test') on container 024277f43d07dbd147c94e0472a20fa529998fb1e537bd729c4c77c2884d8b57.
2023-04-12 15:41:15,139|DEBUG   |Adding jobs to container 024277f43d07dbd147c94e0472a20fa529998fb1e537bd729c4c77c2884d8b57.
2023-04-12 15:41:15,139|INFO    |Added job "test" to job store "default"
2023-04-12 15:41:15,140|DEBUG   |Looking for jobs to run
2023-04-12 15:41:15,140|DEBUG   |Next wakeup is due at 2023-04-12 15:42:15.139254+00:00 (in 59.998585 seconds)
2023-04-12 15:41:15,141|INFO    |test-test-1: Added 'test' (2c6c5703-bd06-5a9d-a08a-9c176c2081e5).
2023-04-12 15:41:16,346|DEBUG   |Daemon event: {'status': 'die', 'id': '024277f43d07dbd147c94e0472a20fa529998fb1e537bd729c4c77c2884d8b57', 'from': 'alpine:3.17', 'Type': 'container', 'Action': 'die', 'Actor': {'ID': '024277f43d07dbd147c94e0472a20fa529998fb1e537bd729c4c77c2884d8b57', 'Attributes': {'com.docker.compose.config-hash': '90e7dd807be9f827d48e1eb2dbf28b0bdbb764d718a75f75919746a5464774f4', 'com.docker.compose.container-number': '1', 'com.docker.compose.depends_on': '', 'com.docker.compose.image': 'sha256:9ed4aefc74f6792b5a804d1d146fe4b4a2299147b0f50eaf2b08435d7b38c27e', 'com.docker.compose.oneoff': 'False', 'com.docker.compose.project': 'test', 'com.docker.compose.project.config_files': '/tmp/test/compose1.yaml', 'com.docker.compose.project.working_dir': '/tmp/test', 'com.docker.compose.service': 'test', 'com.docker.compose.version': '2.17.2', 'deck-chores.test.command': 'env', 'deck-chores.test.interval': 'every minute', 'exitCode': '137', 'image': 'alpine:3.17', 'name': 'test-test-1'}}, 'scope': 'local', 'time': 1681314076, 'timeNano': 1681314076345781525}
2023-04-12 15:41:16,346|DEBUG   |Handling die of 024277f43d07dbd147c94e0472a20fa529998fb1e537bd729c4c77c2884d8b57.
2023-04-12 15:41:16,495|INFO    |test-test-1: Reassigning jobs to abdd8e9486bead4c7fbd8b78357058ebe79eb475f6a30c3795b66540b40b7992.
2023-04-12 15:41:16,495|DEBUG   |Handling job: {'command': 'env', 'name': 'test', 'user': '', 'environment': {}, 'max': 1, 'timezone': 'UTC', 'trigger': (<class 'apscheduler.triggers.interval.IntervalTrigger'>, (0, 0, 0, 1, 0)), 'service_id': ('com.docker.compose.project=test', 'com.docker.compose.service=test'), 'job_name': 'test', 'job_id': '2c6c5703-bd06-5a9d-a08a-9c176c2081e5', 'container_id': '024277f43d07dbd147c94e0472a20fa529998fb1e537bd729c4c77c2884d8b57'}
2023-04-12 15:41:16,496|DEBUG   |Reassigned lock for service ('com.docker.compose.project=test', 'com.docker.compose.service=test') from container 024277f43d07dbd147c94e0472a20fa529998fb1e537bd729c4c77c2884d8b57 to abdd8e9486bead4c7fbd8b78357058ebe79eb475f6a30c3795b66540b40b7992.
2023-04-12 15:41:16,496|DEBUG   |Looking for jobs to run
2023-04-12 15:41:16,496|DEBUG   |Next wakeup is due at 2023-04-12 15:42:15.139254+00:00 (in 58.642705 seconds)
2023-04-12 15:41:16,821|DEBUG   |Daemon event: {'status': 'start', 'id': 'abdd8e9486bead4c7fbd8b78357058ebe79eb475f6a30c3795b66540b40b7992', 'from': 'alpine:3.17', 'Type': 'container', 'Action': 'start', 'Actor': {'ID': 'abdd8e9486bead4c7fbd8b78357058ebe79eb475f6a30c3795b66540b40b7992', 'Attributes': {'com.docker.compose.config-hash': '4a8ae6011689842b90fadb037b459bb80382b8e55d7a6e1b83653950cd50ea79', 'com.docker.compose.container-number': '1', 'com.docker.compose.depends_on': '', 'com.docker.compose.image': 'sha256:9ed4aefc74f6792b5a804d1d146fe4b4a2299147b0f50eaf2b08435d7b38c27e', 'com.docker.compose.oneoff': 'False', 'com.docker.compose.project': 'test', 'com.docker.compose.project.config_files': '/tmp/test/compose2.yaml', 'com.docker.compose.project.working_dir': '/tmp/test', 'com.docker.compose.replace': '024277f43d07dbd147c94e0472a20fa529998fb1e537bd729c4c77c2884d8b57', 'com.docker.compose.service': 'test', 'com.docker.compose.version': '2.17.2', 'deck-chores.test.command': 'echo 1', 'deck-chores.test.interval': 'every second', 'image': 'alpine:3.17', 'name': 'test-test-1'}}, 'scope': 'local', 'time': 1681314076, 'timeNano': 1681314076821146949}
2023-04-12 15:41:16,821|DEBUG   |Handling start of abdd8e9486bead4c7fbd8b78357058ebe79eb475f6a30c3795b66540b40b7992.
2023-04-12 15:41:16,822|DEBUG   |Parsing labels: {'com.docker.compose.config-hash': '4a8ae6011689842b90fadb037b459bb80382b8e55d7a6e1b83653950cd50ea79', 'com.docker.compose.container-number': '1', 'com.docker.compose.depends_on': '', 'com.docker.compose.image': 'sha256:9ed4aefc74f6792b5a804d1d146fe4b4a2299147b0f50eaf2b08435d7b38c27e', 'com.docker.compose.oneoff': 'False', 'com.docker.compose.project': 'test', 'com.docker.compose.project.config_files': '/tmp/test/compose2.yaml', 'com.docker.compose.project.working_dir': '/tmp/test', 'com.docker.compose.replace': '024277f43d07dbd147c94e0472a20fa529998fb1e537bd729c4c77c2884d8b57', 'com.docker.compose.service': 'test', 'com.docker.compose.version': '2.17.2', 'deck-chores.test.command': 'echo 1', 'deck-chores.test.interval': 'every second'}
2023-04-12 15:41:16,822|DEBUG   |Considering labels for service id: {'com.docker.compose.project': 'test', 'com.docker.compose.service': 'test'}
2023-04-12 15:41:16,824|DEBUG   |Considering labels for job definitions: {'deck-chores.test.command': 'echo 1', 'deck-chores.test.interval': 'every second'}
2023-04-12 15:41:16,824|DEBUG   |Job definitions: {'test': {'command': 'echo 1', 'interval': 'every second'}}
2023-04-12 15:41:16,824|DEBUG   |Processing test
2023-04-12 15:41:16,825|DEBUG   |Normalized definition: {'command': 'echo 1', 'name': 'test', 'user': '', 'environment': {}, 'max': 1, 'timezone': 'UTC', 'trigger': (<class 'apscheduler.triggers.interval.IntervalTrigger'>, (0, 0, 0, 0, 1))}
2023-04-12 15:41:16,825|DEBUG   |Assigning service id: ('com.docker.compose.project=test', 'com.docker.compose.service=test')
2023-04-12 15:41:16,825|DEBUG   |Service id ('com.docker.compose.project=test', 'com.docker.compose.service=test') is locked by container abdd8e9486bead4c7fbd8b78357058ebe79eb475f6a30c3795b66540b40b7992.
2023-04-12 15:42:15,139|DEBUG   |Looking for jobs to run
2023-04-12 15:42:15,141|DEBUG   |Next wakeup is due at 2023-04-12 15:43:15.139254+00:00 (in 59.999588 seconds)
2023-04-12 15:42:15,142|INFO    |test-test-1: Executing 'test'.
2023-04-12 15:42:15,153|DEBUG   |Daemon event: {'status': 'exec_start: env ', 'id': 'abdd8e9486bead4c7fbd8b78357058ebe79eb475f6a30c3795b66540b40b7992', 'from': 'alpine:3.17', 'Type': 'container', 'Action': 'exec_start: env ', 'Actor': {'ID': 'abdd8e9486bead4c7fbd8b78357058ebe79eb475f6a30c3795b66540b40b7992', 'Attributes': {'com.docker.compose.config-hash': '4a8ae6011689842b90fadb037b459bb80382b8e55d7a6e1b83653950cd50ea79', 'com.docker.compose.container-number': '1', 'com.docker.compose.depends_on': '', 'com.docker.compose.image': 'sha256:9ed4aefc74f6792b5a804d1d146fe4b4a2299147b0f50eaf2b08435d7b38c27e', 'com.docker.compose.oneoff': 'False', 'com.docker.compose.project': 'test', 'com.docker.compose.project.config_files': '/tmp/test/compose2.yaml', 'com.docker.compose.project.working_dir': '/tmp/test', 'com.docker.compose.replace': '024277f43d07dbd147c94e0472a20fa529998fb1e537bd729c4c77c2884d8b57', 'com.docker.compose.service': 'test', 'com.docker.compose.version': '2.17.2', 'deck-chores.test.command': 'echo 1', 'deck-chores.test.interval': 'every second', 'execID': '26177c74c1772fa932ed3965842b67258bbedf6149e1bfe7ed97299fc31d81f0', 'image': 'alpine:3.17', 'name': 'test-test-1'}}, 'scope': 'local', 'time': 1681314135, 'timeNano': 1681314135152909667}
2023-04-12 15:42:15,261|DEBUG   |Daemon event: {'status': 'exec_die', 'id': 'abdd8e9486bead4c7fbd8b78357058ebe79eb475f6a30c3795b66540b40b7992', 'from': 'alpine:3.17', 'Type': 'container', 'Action': 'exec_die', 'Actor': {'ID': 'abdd8e9486bead4c7fbd8b78357058ebe79eb475f6a30c3795b66540b40b7992', 'Attributes': {'com.docker.compose.config-hash': '4a8ae6011689842b90fadb037b459bb80382b8e55d7a6e1b83653950cd50ea79', 'com.docker.compose.container-number': '1', 'com.docker.compose.depends_on': '', 'com.docker.compose.image': 'sha256:9ed4aefc74f6792b5a804d1d146fe4b4a2299147b0f50eaf2b08435d7b38c27e', 'com.docker.compose.oneoff': 'False', 'com.docker.compose.project': 'test', 'com.docker.compose.project.config_files': '/tmp/test/compose2.yaml', 'com.docker.compose.project.working_dir': '/tmp/test', 'com.docker.compose.replace': '024277f43d07dbd147c94e0472a20fa529998fb1e537bd729c4c77c2884d8b57', 'com.docker.compose.service': 'test', 'com.docker.compose.version': '2.17.2', 'deck-chores.test.command': 'echo 1', 'deck-chores.test.interval': 'every second', 'execID': '26177c74c1772fa932ed3965842b67258bbedf6149e1bfe7ed97299fc31d81f0', 'exitCode': '0', 'image': 'alpine:3.17', 'name': 'test-test-1'}}, 'scope': 'local', 'time': 1681314135, 'timeNano': 1681314135261694434}
2023-04-12 15:42:15,263|INFO    |Command `env` in container abdd8e9486bead4c7fbd8b78357058ebe79eb475f6a30c3795b66540b40b7992 finished with exit code 0.
2023-04-12 15:42:15,263|INFO    |== BEGIN of captured stdout & stderr ==
2023-04-12 15:42:15,263|INFO    |PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin
2023-04-12 15:42:15,263|INFO    |HOSTNAME=abdd8e9486be
2023-04-12 15:42:15,263|INFO    |HOME=/root
2023-04-12 15:42:15,263|INFO    |== END of captured stdout & stderr ====

[funkyfuture]

a'ight, so what's happening is that (to me somewhat unexpected) the replacing container is already found when its start hasn't been processed yet. and the then executed main.reassign_jobs just doesn't consider that the job definitions might have changed.

so, as a workaround, just don't hurry. kill the old container first, give deck-chores some time to deal with the recent die event. then proceed with the new one.

i don't know when i will look into fixing this, might be a couple of months. i'm happy to review Pull Requests with a solution and can be of informative assistance beforehand, just ask.

note: i spotted a new (to me) label on the containers in the com.docker.compose namespace named replace. it should be researched and may lay the course for a possibly simpler, more reliable implementation. but it shouldn't be directly changed with a fix for this bug.

[codersaur]

I started using deck-chores today and immediately ran into this bug. I generally edit my docker compose files and simply run docker compose up -d, rarely using docker compose down. I ended up with a job that should have been running daily but was running every minute and couldn't work out why! Would be good to fix this issue.