Comment to task #5647 in hc-cron: hc-cron czasami odpala dwukrotnie zadania

[Flyspray - The bug killer!]

Project: PLD 2.x (Ac)
  
  Package: hc-cron
  Summary: hc-cron czasami odpala dwukrotnie zadania
  Commented by: Marcin Kaminski (maxiu)
  Comment: Nie jest uruchamiana, nawet nie ma nic zainstalowanego do
obsługi ntp czy rdate.

Wycinek strace kiedy zaszło to zdarzenie (wywaliłem rzeczy
niezwiązane):

stat64("cron", {st_mode=S_IFDIR|S_ISVTX|0730, st_size=6, ...}) = 0
stat64("/etc/crontab", 0xbfffd50c)      = -1 ENOENT (No such file or
directory)
stat64("/etc/cron.d", {st_mode=S_IFDIR|0750, st_size=4096, ...}) = 0
open("/etc/cron.d", O_RDONLY|O_NONBLOCK|O_LARGEFILE|O_DIRECTORY) = 5
close(5)
time(NULL)                              = 1117023900
time(NULL)                              = 1117023900
clone(child_stack=0,
flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD,
child_tidptr=0x40138708) = 32454
time(NULL)                              = 1117023900
nanosleep({60, 0}, 0xbfffd844)          = ? ERESTART_RESTARTBLOCK (To
be restarted)
--- SIGCHLD (Child exited) @ 0 (0) ---
waitpid(-1, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], WNOHANG) = 32455
nanosleep({60, 0}, 0xbfffd844)          = ? ERESTART_RESTARTBLOCK (To
be restarted)
--- SIGCHLD (Child exited) @ 0 (0) ---
waitpid(-1, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], WNOHANG) = 32457
nanosleep({59, 0}, 0xbfffd844)          = ? ERESTART_RESTARTBLOCK (To
be restarted)
--- SIGCHLD (Child exited) @ 0 (0) ---
waitpid(-1, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], WNOHANG) = 32454
nanosleep({57, 0}, 0xbfffd844)          = ? ERESTART_RESTARTBLOCK (To
be restarted)
--- SIGCHLD (Child exited) @ 0 (0) ---
waitpid(-1, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], WNOHANG) = 32460
nanosleep({53, 0}, 0xbfffd844)          = ? ERESTART_RESTARTBLOCK (To
be restarted)
--- SIGCHLD (Child exited) @ 0 (0) ---
waitpid(-1, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], WNOHANG) = 32461
nanosleep({48, 0}, {48, 0})             = 0
stat64("cron", {st_mode=S_IFDIR|S_ISVTX|0730, st_size=6, ...}) = 0
stat64("/etc/crontab", 0xbfffd50c)      = -1 ENOENT (No such file or
directory)
stat64("/etc/cron.d", {st_mode=S_IFDIR|0750, st_size=4096, ...}) = 0
open("/etc/cron.d", O_RDONLY|O_NONBLOCK|O_LARGEFILE|O_DIRECTORY) = 5
getdents64(5, /* 7 entries */, 4096)    = 200
close(5)                                = 0
time(NULL)                              = 1117023959
time(NULL)                              = 1117023959
time(NULL)                              = 1117023959
nanosleep({1, 0}, 0xbfffd844)           = ? ERESTART_RESTARTBLOCK (To
be restarted)
--- SIGCHLD (Child exited) @ 0 (0) ---
waitpid(-1, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], WNOHANG) = 2037
nanosleep({1, 0}, 0xbfffd844)           = ? ERESTART_RESTARTBLOCK (To
be restarted)
--- SIGCHLD (Child exited) @ 0 (0) ---
waitpid(-1, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], WNOHANG) = 2039
stat64("cron", {st_mode=S_IFDIR|S_ISVTX|0730, st_size=6, ...}) = 0
stat64("/etc/crontab", 0xbfffd50c)      = -1 ENOENT (No such file or
directory)
stat64("/etc/cron.d", {st_mode=S_IFDIR|0750, st_size=4096, ...}) = 0
open("/etc/cron.d", O_RDONLY|O_NONBLOCK|O_LARGEFILE|O_DIRECTORY) = 5
getdents64(5, /* 7 entries */, 4096)    = 200
close(5)                                = 0
time(NULL)                              = 1117023960
time(NULL)                              = 1117023960
time(NULL)                              = 1117023960
nanosleep({60, 0}, 0xbfffd844)          = ? ERESTART_RESTARTBLOCK (To
be restarted)
--- SIGCHLD (Child exited) @ 0 (0) ---
waitpid(-1, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], WNOHANG) = 2054
nanosleep({60, 0}, 0xbfffd844)          = ? ERESTART_RESTARTBLOCK (To
be restarted)
--- SIGCHLD (Child exited) @ 0 (0) ---


Mała analiza:
1. Zaczyna się od sprawdzenia czy są jakieś zmainyw plikach
konfiguracyjnych, odpalenie zadań
2. Pobierany jest czas, wychodzi 1117023900
3. Cron wylicza że następna minuta kończy się o 1117023960 i daje
sleepa na 60
4. Kończą się kolejne rozpoczęte zadania, za każdym razem sleep
jest przerywany i potem wznawiany z nowym czasem, ilośc sekund jest
pewnie pobierana z wyniku nanosleep, ALE liczba nanosekund jest zawsze
zerowana.
5. Tak sobie dochodzi do momentu aż nanosleep normalnie się skończy
i wszystko od nowa
6. Pobierany jest czas, ALE wychodzi 1117023959, czyli nie minęło
pełne 60 sekund od tamtego czasu :(
7. Cron wylicza że następna minuta kończy się o 1117023960 i daje
sleepa na 1

No i tu pies pogrzebany bo w trakcie minuty dwa razy odpala.
Zajrzę zaraz w źródła, ale wygląda mi na to że autor przyjął
błędne założenie że te jego składane nanosleepy dadzą
przynajmniej minutę, a nie dają. Nie wiem czy jest to wina mojego
serwera (może ma coś z czasem nie tak? Ale raczej chodzi dobrze) czy
też tego że odpalane jest sporo zadań na raz co 5 minut. Być może
jest to wina tego że zerowane są nanosekundy po powrocie z nanosleep,
niestety strace nie pokazuje *req, jedynie adres i nie można z tego
wyciągnąć pozostałego czasu podanego przez system.


For more further see:
http://bugs.pld-linux.org/index.php?do=details&id=5647&area=comments#tabs}

------------------------------------------------------------------------
THIS IS AN AUTOMATICALLY GENERATED MESSAGE, DO NOT REPLY