Why do cron commands inside a docker container show up in log but don't actually run?

Viewed 134

Dockerfile

FROM almalinux:8

# [... supervisord setup ...]

RUN dnf install -y \
    crontabs
RUN sed -ri '/-session(\s+)optional(\s+)pam_systemd.so/d' /etc/pam.d/system-auth && \
    sed -ri '/^[^#]/ s/systemd//g' /etc/nsswitch.conf
COPY $TEMPLATE_DIR/supervisord/crond.conf /etc/supervisord.d/crond.conf

crond.conf

[program:crond]
    command=/usr/sbin/crond -nsm off
    stdout_logfile_maxbytes=0
    stdout_logfile=/dev/stdout
    stderr_logfile=/dev/stderr
    stderr_logfile_maxbytes=0

syslog:

2022-06-13 18:39:07,939 INFO success: crond entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)

crontab -e

*       *       *       *       *       touch /var/www/html/test.txt

syslog:

Jun 13 18:57:59 e60d29fd100e crontab[331]: (root) BEGIN EDIT (root)
Jun 13 18:58:15 e60d29fd100e crontab[331]: (root) REPLACE (root)
Jun 13 18:58:15 e60d29fd100e crontab[331]: (root) END EDIT (root)
Jun 13 18:59:01 e60d29fd100e CROND[334]: (root) CMD (touch /var/www/html/test.txt)

I thought the file is never touched... tried also echo, running an absolute path command... nothing. But after waiting a little (longer) and running cron with debug flags on, it seems the command does get run, but with something like a 5s to 50s delay:

load_entry()...about to parse command
2022-06-13T16:17:01.352923611Z linenum=21
2022-06-13T16:17:01.352929349Z load_entry()...returning successfully
2022-06-13T16:17:01.352934854Z ...load_user() done
2022-06-13T16:17:01.352940748Z unlinking old database:
2022-06-13T16:17:01.352960040Z check_inotify_database is done
2022-06-13T16:17:01.352966537Z user [root:0:0:...] cmd="touch /var/www/html/test.txt"
2022-06-13T16:17:01.352972511Z [10] do_command(touch /var/www/html/test.txt, (root,0,0))
2022-06-13T16:17:01.352979069Z [10] main process returning to work
2022-06-13T16:17:01.352984792Z 

The huge delay seems to also pile up what I presume are queued commands to run, and the pile grows forever larger:

root         335  0.0  0.0  69708  5188 ?        S    19:15   0:00 /usr/sbin/CROND -nsm off -x ext,sch,proc,pars,load,misc
root         336 94.4  0.0  69708  1440 ?        Rs   19:15   8:52 /usr/sbin/CROND -nsm off -x ext,sch,proc,pars,load,misc

... multiply 10x the 2 processes above after a few minutes ...

Any clues why the huge delay and weird behavior? Disabling inotify (-i) on crond does not improve things... I'm thinking maybe a time skew issue?

0 Answers
Related