Unexpected stacktrace with `@reboot`

[eric239]

• Yet Another Cron version: 0.8.0
• Python version: 3.7
• Operating System: alpine 3.8

Description

Trying to run a simple echo upon startup (i.e. using @reboot)

What I Did

Running insider docker, using the example Dockerfile as a reference. Here's config file:

defaults:
  concurrencyPolicy: Forbid
jobs:
  - name: startup
    command: 'echo "Running!"'
    schedule: '@reboot'

and here's the output (as captured by docker logs)

INFO:yacron:Starting job startup
Running!
INFO:yacron:Job startup spawned
INFO:yacron:Job startup exit code 0; has stdout: false, has stderr: false; failed: false
INFO:yacron:Cron job startup: reporting success

so far so good... but soon it's followed by

Traceback (most recent call last):
  File "/usr/local/bin/yacron", line 11, in <module>
    sys.exit(main())
  File "/usr/local/lib/python3.7/site-packages/yacron/__main__.py", line 44, in main
    main_loop(_loop)
  File "/usr/local/lib/python3.7/site-packages/yacron/__main__.py", line 31, in main_loop
    loop.run_until_complete(cron.run())
  File "/usr/local/lib/python3.7/asyncio/base_events.py", line 568, in run_until_complete
    return future.result()
  File "/usr/local/lib/python3.7/site-packages/yacron/cron.py", line 73, in run
    await self.spawn_jobs(startup)
  File "/usr/local/lib/python3.7/site-packages/yacron/cron.py", line 107, in spawn_jobs
    if crontab.test(get_now(job.utc)):
AttributeError: 'str' object has no attribute 'test'
ERROR:asyncio:Task was destroyed but it is pending!
task: <Task pending coro=<Cron._wait_for_running_jobs() running at /usr/local/lib/python3.7/site-packages/yacron/cron.py:161> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f0e33ca73d8>()]>>
ERROR:asyncio:Task was destroyed but it is pending!
task: <Task pending coro=<Event.wait() running at /usr/local/lib/python3.7/asyncio/locks.py:293> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f0e305e8e88>()]> cb=[_release_waiter(<Future pendi...e33ca73d8>()]>)() at /usr/local/lib/python3.7/asyncio/tasks.py:362]>

Happy to provide any additional info!

[eric239]

The same command with a "normal" schedule runs just fine

[eric239]

Hmm I hope this project has maintainer(s)

[gjcarneiro]

I think you're using an older version of yacron. Possibly due to docker caching. This line in the dockerfile:

RUN virtualenv -p /usr/bin/python3 /yacron && \
    /yacron/bin/pip install yacron

If you have that layer cached, you might get an older version. Try adding an explicit version request:

RUN virtualenv -p /usr/bin/python3 /yacron && \
    /yacron/bin/pip install yacron==0.8.0

[eric239]

@gjcarneiro why did you suggest to check version? I specified in my initial report that I'm running 0.8.0

/ # pip --version
pip 18.0 from /usr/local/lib/python3.7/site-packages/pip (python 3.7)

/ # pip list -v | fgrep yacron
yacron          0.8.0   /usr/local/lib/python3.7/site-packages pip

[gjcarneiro]

Works for me:

(yacron) 10:16:17 {master} ~/projects/yacron/example/docker$ docker run -ti yacrondemo -l DEBUG
DEBUG:yacron:Job test-01 (@reboot) is scheduled for startup (@reboot)
DEBUG:yacron:Job test-01 retry config: {'initialDelay': 1, 'maximumDelay': 300, 'maximumRetries': 0, 'backoffMultiplier': 2}
INFO:yacron:Starting job test-01
DEBUG:yacron:test-01: will execute argv ['/bin/sh', '-c', 'echo "hello from $HOSTNAME"']
INFO:yacron:Job test-01 spawned
DEBUG:yacron:Will sleep for 35.8 seconds
[test-01 stdout] hello from cf77aab00f97
INFO:yacron:Job test-01 exit code 0; has stdout: true, has stderr: false; failed: false
INFO:yacron:Cron job test-01: reporting success

Check carefully the yacron version that is inside the docker image:

docker run -ti --entrypoint=sh yacrondemo -c "/yacron/bin/pip list | grep yacron"

I still strongly suspect docker caching issues, that's why I suggest changing the Dockerfile.

[eric239]

@gjcarneiro what I posted earlier was in fact from within the container (having attached via docker exec)

I'm using a different Dockerfile

FROM python:3-alpine

RUN apk --no-cache update && apk --no-cache add --update curl bind-tools jq && rm -f /var/cache/apk/*
RUN pip --no-cache-dir install yacron

COPY yacrontab.yaml /etc/yacron.d/yacrontab.yaml

ENTRYPOINT ["/usr/local/bin/yacron"]

So in my case yacron is installed in /usr/local/bin but I don't think that would matter. Maybe it is because of me using alpine -- I'll check with ubuntu or debian (although I've never had problems with alpine and python code myself, I've seen some complaints)

[eric239]

@gjcarneiro unfortunately I'm getting the same error with the current stable debian (stretch). Here's my simplified Dockerfile:

FROM python:3-stretch

RUN pip --no-cache-dir install yacron

COPY yacrontab.yaml /etc/yacron.d/yacrontab.yaml

ENTRYPOINT ["/usr/local/bin/yacron"]

here's the simplified crontab:

jobs:

  - name: startup
    command: 'echo Running!'
    schedule: '@reboot'

I have confirmed that the version used in the container is 0.8.0 The error is the same:

INFO:yacron:Starting job startup
Running!
INFO:yacron:Job startup spawned
INFO:yacron:Job startup exit code 0; has stdout: false, has stderr: false; failed: false
INFO:yacron:Cron job startup: reporting success
Traceback (most recent call last):
  File "/usr/local/bin/yacron", line 11, in <module>
    sys.exit(main())
  File "/usr/local/lib/python3.7/site-packages/yacron/__main__.py", line 44, in main
    main_loop(_loop)
  File "/usr/local/lib/python3.7/site-packages/yacron/__main__.py", line 31, in main_loop
    loop.run_until_complete(cron.run())
  File "/usr/local/lib/python3.7/asyncio/base_events.py", line 568, in run_until_complete
    return future.result()
  File "/usr/local/lib/python3.7/site-packages/yacron/cron.py", line 73, in run
    await self.spawn_jobs(startup)
  File "/usr/local/lib/python3.7/site-packages/yacron/cron.py", line 107, in spawn_jobs
    if crontab.test(get_now(job.utc)):
AttributeError: 'str' object has no attribute 'test'
ERROR:asyncio:Task was destroyed but it is pending!
task: <Task pending coro=<Cron._wait_for_running_jobs() running at /usr/local/lib/python3.7/site-packages/yacron/cron.py:161> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f50c8085d38>()]>>
ERROR:asyncio:Task was destroyed but it is pending!
task: <Task pending coro=<Event.wait() running at /usr/local/lib/python3.7/asyncio/locks.py:293> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f50c8085f18>()]> cb=[_release_waiter(<Future pendi...0c8085d38>()]>)() at /usr/local/lib/python3.7/asyncio/tasks.py:362]>

The error occurs around 2 minutes after the container boots, that is

INFO:yacron:Starting job startup
Running!
INFO:yacron:Job startup spawned
INFO:yacron:Job startup exit code 0; has stdout: false, has stderr: false; failed: false
INFO:yacron:Cron job startup: reporting success

is printed right upon boot, as expected, then for couple minutes nothing new, then the error trace.

[eric239]

I've modified the command to be a little more informative

jobs:

  - name: startup
    command: /usr/bin/env && pip show yacron
    schedule: '@reboot'

which outputs

INFO:yacron:Starting job startup
INFO:yacron:Job startup spawned
HOSTNAME=4e6f48ba0110
PYTHON_PIP_VERSION=18.1
HOME=/root
GPG_KEY=0D96DF4D4110E5C43FBFB17F2D347EA6AA65421D
PATH=/usr/local/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin
LANG=C.UTF-8
PYTHON_VERSION=3.7.0
PWD=/
Name: yacron
Version: 0.8.0
Summary: A modern Cron replacement that is Docker-friendly
Home-page: https://github.com/gjcarneiro/yacron
Author: Gustavo Carneiro
Author-email: gustavocarneiro@gambitresearch.com
License: MIT license
Location: /usr/local/lib/python3.7/site-packages
Requires: strictyaml, raven-aiohttp, aiosmtplib, raven, jinja2, crontab, aiohttp
Required-by:
INFO:yacron:Job startup exit code 0; has stdout: false, has stderr: false; failed: false
INFO:yacron:Cron job startup: reporting success
Traceback (most recent call last):
  File "/usr/local/bin/yacron", line 11, in <module>
    sys.exit(main())
  File "/usr/local/lib/python3.7/site-packages/yacron/__main__.py", line 44, in main
    main_loop(_loop)
  File "/usr/local/lib/python3.7/site-packages/yacron/__main__.py", line 31, in main_loop
    loop.run_until_complete(cron.run())
  File "/usr/local/lib/python3.7/asyncio/base_events.py", line 568, in run_until_complete
    return future.result()
  File "/usr/local/lib/python3.7/site-packages/yacron/cron.py", line 73, in run
    await self.spawn_jobs(startup)
  File "/usr/local/lib/python3.7/site-packages/yacron/cron.py", line 107, in spawn_jobs
    if crontab.test(get_now(job.utc)):
AttributeError: 'str' object has no attribute 'test'
ERROR:asyncio:Task was destroyed but it is pending!
task: <Task pending coro=<Cron._wait_for_running_jobs() running at /usr/local/lib/python3.7/site-packages/yacron/cron.py:161> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7fa641248ee8>()]>>
ERROR:asyncio:Task was destroyed but it is pending!
task: <Task pending coro=<Event.wait() running at /usr/local/lib/python3.7/asyncio/locks.py:293> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7fa641248fd8>()]> cb=[_release_waiter(<Future pendi...641248ee8>()]>)() at /usr/local/lib/python3.7/asyncio/tasks.py:362]>

(error is delayed by couple minutes)

[gjcarneiro]

Oh, I think I see the logic error in the code. The error would appear not immediately, but instead every minute after 1 minute.

Yep, confirmed.

[eric239]

Thanks @gjcarneiro 👍