• Willkommen im Linux Club - dem deutschsprachigen Supportforum für GNU/Linux. Registriere dich kostenlos, um alle Inhalte zu sehen und Fragen zu stellen.

cron hat massive Verspätung

A

apollo

Newbie
Hallo Forum!

Heute konnte ich etwas seltsames auf einer unserer Linux-Kisten beobachten. Cron startete zwei Jobs mit mehreren Stunden Verspätung.
Die Crontab sah wie folgt aus:
Code: 
05  05  *  *  *    /pfad/2nd_job
30 23 * * *        /pfad/1st_job
Nachweislich (laut logfiles die diese jobs schreiben) wurde

1st_job am 29.09 nicht wie geplant um 23:30 gestartet
2nd_job am 30.09 nicht wie geplant um 5:05 gestartet

Stattdessen wurde

1st_job am 30.09. um 9:40 gestartet
2nd_job auch am 30.09. um 9:40 gestartet, kurz nachdem 1st_job gestartet wurde

Ich kann noch zusätzlich sagen:
- Der Rechner wurde seit mehreren Tagen nicht gebootet
- Die Rechnerzeit wurde zwar zwei Tage vorher manipuliert. Seitdem liefen aber die jobs mindestens einmal ohne Probleme.
- Ein manueller start kann ausgeschlossen werden. Die beiden Programme wurden nachweilich vom gewünschten user gestartet. Dieser hat in der history keinen passenden Eintrag. Bleibt nur die crontab übrig.

Wie kommt das?
 
haveaniceday

haveaniceday

Hacker
Nur Vermutungen:

cron reagiert nicht/verspätet auf Zeitänderungen (?). Könntest du probieren.

Bei manchen Änderungen greift auf eine "Sommerzeitregel"
=> Siehe "man 8 cron".

Haveaniceday
 
OP
A

apollo

Newbie
haveaniceday schrieb:
Nur Vermutungen:

cron reagiert nicht/verspätet auf Zeitänderungen (?). Könntest du probieren.

Bei manchen Änderungen greift auf eine "Sommerzeitregel"
=> Siehe "man 8 cron".
Zum Vergrößern anklicken....
Wir benutzen übrigens SLES 8. Die Sommerzeit wird ja erst nächsten Monat zurückgestellt. Das war zwar früher mal im September, aber da gab's SLES 8 garantiert noch nicht. In der Zwischenzeit habe ich auch mal die Zeitzone überprüft. Sie ist CEST. Das stimmt soweit. RTP oder ähnliches benutzen wir auch nicht.

Übrigens habe ich nur die halbe Wahrheit erzaehlt. Es wurde fast die gesamte crontab um 9:40 ausgeführt. Anscheinend in der Reihenfolge der crontab-Zeiten.
Das rot gefärbte wurde definitiv um 9:40 ausgeführt. Das grüne wurde definitiv nicht ausgeführt. Schwarz ist nicht nachweißbar, da dieser job nur im Fehlerfall Ausgaben erzeugt.
30 03 * * * /...
05 05 * * * /...
50 23 28 * * /...
00 06 * * * /...
*/10 7-21 * * 1-6 /...
30 23 * * * /...
15 23 * * * /...
05 23 * * * /...


P.S.: Schade, dass man code nicht einfärben kann.
 
A

Anonymous

Gast
Woraus entnimmst du dass die Jobs alle zu dieser Zeit gemacht wurden, aus einer Logdatei?

Das Ganze erinnert mich irgendwie an ein Problem das wir mal hatten, als aus unterklärlichen Gründen der log-Daemon stundenlang gehängt hat, und dann alles mit dem selben Zeitstempel rausgegeben hat was in der Zwischenzeit aufgelaufen war.

robi
 
OP
A

apollo

Newbie
robi schrieb:
Woraus entnimmst du dass die Jobs alle zu dieser Zeit gemacht wurden, aus einer Logdatei?
Zum Vergrößern anklicken....
Ja!
Das Ganze erinnert mich irgendwie an ein Problem das wir mal hatten, als aus unterklärlichen Gründen der log-Daemon stundenlang gehängt hat, und dann alles mit dem selben Zeitstempel rausgegeben hat was in der Zwischenzeit aufgelaufen war.
Zum Vergrößern anklicken....
Log-Deamon? Meines Wissens verwenden wir keinen Log-Deamon.
Das die Programme tatsächlich um diese Zeit anliefen sagen auch die User, die mit der Datenbank auf diesem Rechner arbeiten sollten. Diese wurde mitten währen der Arbeitszeit für eine Offline-Sicherung heruntergefahren. Außerdem schreiben mindestens 2 der Cronjobs zeitversetzt in das gleiche Logfile. Es wurde aber gleichzeitig in die Logfiles geschrieben (Die Zeilen im Logfile sind abwechselnd von unterschiedlichen Programmen).
 
A

Anonymous

Gast
apollo schrieb:
Log-Deamon? Meines Wissens verwenden wir keinen Log-Deamon.
Zum Vergrößern anklicken....
Code: 
 robi@linux:~> ps -efl | grep  logd
5 S root      2157     1  0  76   0 -   359 schedu 20:01 ?        00:00:00 /sbin/syslogd -a /var/lib/ntp/dev/log
5 S root      2160     1  0  75   0 -   576 syslog 20:01 ?        00:00:00 /sbin/klogd -c 1 -2
Die beiden hier meine ich, der eine für den Kernel, der andere vom System, die sollten wohl überall laufen.
apollo schrieb:
Das die Programme tatsächlich um diese Zeit anliefen sagen auch die User, die mit der Datenbank auf diesem Rechner arbeiten sollten. Diese wurde mitten währen der Arbeitszeit für eine Offline-Sicherung heruntergefahren.
Zum Vergrößern anklicken....
Autsch, das gibt bestimmt ne Menge unangenehmer Fragen. Aber das System mit dem cron lahmlegen ist viel zu auffällig. Nimm das nächste mal liebe so was hier
Code: 
 sleep 300 && kill -30 1
und nach dem Enter einfach Kaffee trinken gehen, ist schwerer nachzuweisen und sowas kann man dann immer noch auf den Elektriker schieben. :lol:

Aber mal Spass beiseite, cron ist meines Wissens pünklich, Wenn ihr vorher an der Systemuhr rumgespielt habt, dann könnte vielleicht die Driftfiles /etc/adjtime oder /var/lib/ntp/drift/ntp.drift damit was zu tun gehabt haben, allerdings bei dem was du berichtest hätte die Uhr wohl um einige Tage verstellt werden müssen, damit es überhaupt zu solchen Schwankungen hätte kommen können. Wenn es seit dem stabil und pünktlich funktioniert, dann würde ich nach der nächsten "Zeitverstellaktion" mal diese beiden Dateien löschen, falls sie auf dem Rechner existieren.
Ansonsten fällt mir auch nichts konstruktives mehr dazu ein

robi
 
OP
A

apollo

Newbie
robi schrieb:
Code: 
 sleep 300 && kill -30 1
und nach dem Enter einfach Kaffee trinken gehen, ist schwerer nachzuweisen und sowas kann man dann immer noch auf den Elektriker schieben. :lol:
Zum Vergrößern anklicken....
Oder auf die Putzfrau...

Reboot tut gut. Seitdem funktioniert wieder alles. Ich mag es nur nicht, wenn man solche Fehler nicht erklären kann.
 
OP
A

apollo

Newbie
apollo schrieb:
Reboot tut gut. Seitdem funktioniert wieder alles. Ich mag es nur nicht, wenn man solche Fehler nicht erklären kann.
Zum Vergrößern anklicken....
Toll! Kaum habe ich innerlich mit dem Problem abgeschlossen, taucht es schon wieder auf.

ANDERER Rechner, selbe crontab, selbes Problem:
- am 3.Oktober 9:47 wurde eine Zeile in der crontab "entkommentiert"
- in der Nacht vom 3./4. Oktober lief daraufhin NICHTS
- am 4. Oktober 21:14 lief dann auf einmal alles los. Diesmal auch die Zeile, die ich im vorherigen Beitrag schwarz markiert habe.
- Die Zeit auf dem Rechner wurde zuletzt am 30.September manipuliert.
- Es existiert kein Verzeichnis /var/lib/ntp
- Allerdings existiert eine Datei /etc/adjtime:
Code: 
prompt> ls -l /etc/adjtime
-rw-r--r--    1 root     root           49 Oct  5 07:36 /etc/adjtime
prompt> cat /etc/adjtime
-235.743591 1128490562 0.000000
1128490562
LOCAL
Was sagt mir das?
 
haveaniceday

haveaniceday

Hacker
Schau mal in man 8 adjtimex. ( gefunden über "man -k adjtime" )
Die Ursache weiss ich nicht.

Aber als Analyse/Verhinderung vom Fehler würde ich so vorgehen:
- xntp zum Rechnerzeit ändern einführen. ( Warum werden bei euch die Zeiten manuell modifiziert ?)
- Falls die Rechnerzeit doch manuell geändert wird: cron neu starten mit "/etc/init.d/cron restart"
- Ab und zu mal "hwclock --systohc", sollte eigentlich beim Shutdown laufen. Sorgt dafür, das die interne Hardwareclock richtig gesetzt wird. Bei einem "Power Failure" hat der Rechner dann keine so große Differenz zur "echten Zeit".

Haveaniceday
 
haveaniceday

haveaniceday

Hacker
Nur mal so als Hilfe, wenn mal jemand die Zeit umrechnen möchte:

prompt> timet2date 1128490562
2005-10-05 07:36:02 +0200 Mittwoch
prompt> cat `which timet2date`
#!/bin/bash

date -d "1970-01-01 UTC $1 seconds" +"%Y-%m-%d %T %z %A"

prompt>
 
A

Anonymous

Gast
also die adjtime sieht normal aus,
Und ihr ändert die crontab Dateien auch mir crontab -e und nicht etwa mit dem vi oder sonst was :?: :shock:

robi
 
OP
A

apollo

Newbie
robi schrieb:
also die adjtime sieht normal aus,
Und ihr ändert die crontab Dateien auch mir crontab -e und nicht etwa mit dem vi oder sonst was :?: :shock:

robi
Zum Vergrößern anklicken....
Natürlich mit "crontab -e". Die crontab-Dateien in /var/spool rühre ich nicht manuell an. Ich bin in der Zwischenzeit dazu übergegangen auf einem Testrechner durch wildes Zeitumstellen einen solchen Fehler zu provozieren. Schaun mer mal ...
 
OP
A

apollo

Newbie
Heureka! Ich hab zumindest die halbe Lösung. Man kann cron durcheinander bringen wenn man:

1. Die Systemzeit in die Vergangenheit setzt (z.B. minus ein Tag)
2. ein paar Minuten wartet
3. Die Systemzeit wieder in die Gegenwart setzt

Ergebnis: cron funktioniert nicht mehr. Ich vermute, dass hängt mit der Sommerzeit-logik zusammen (das nichts wahrend der Zeitumstellung doppelt oder gar nicht ausgeführt wird)

Als Test habe ich meine root-crontab mit zwei Zeilen gefüllt:
Code: 
*/5 * * * * echo "`/bin/date` */5" >> /tmp/crondate.log
*/6 * * * * echo "`/bin/date` */6" >> /tmp/crondate.log
Danach habe ich mein Test-Script laufen lassen (bitte nur mit root auf einem Testrechner ausführen):
Code: 
#!/bin/sh

# vorher "crontab -e" !!!

LOGFILE=/tmp/crondate.log

echo sleeping ...
sleep 361

# minus 24:00 h
echo "`date --set='now -1440 min'` set" >> $LOGFILE

echo sleeping ...
sleep 120

# plus 24:00 h
echo "`date --set='now +1440 min'` set" >> $LOGFILE

Und dann beobachtet mal das Logfile, ob es sich nach der Zeitumstellung +1440 noch irgendwie verändert. Bei mir sieht es nach über zehn Minuten so aus:
Code: 
prompt> date
Mit Okt  5 16:33:57 CEST 2005
prompt> cat crondate.log
Wed Oct  5 16:18:00 CEST 2005 */6
Wed Oct  5 16:20:00 CEST 2005 */5
Die Okt  4 16:20:29 CEST 2005 set
Mit Okt  5 16:22:29 CEST 2005 set
 
Frankie777

Frankie777

Advanced Hacker
hast Du evtl. einen Pentium IV HT mit 2.6.11 smp kernel.

Ich schlage mich mit einem ähnlichen Problem rum.

http://www.linux-club.de/viewtopic.php?p=232907#232907

Der Rechner läuft zwar mittlerweile mit vielen Cronjobs und rcnetwork restart irgendwie besser als vorher.

Doch habe ich auch das Problem, daß cron jobs ab und zu vergessen werden.

Ein Update auf 2.6.13 konnte ich noch nicht testen.
 
OP
A

apollo

Newbie
Frankie777 schrieb:
hast Du evtl. einen Pentium IV HT mit 2.6.11 smp kernel.
Zum Vergrößern anklicken....
Nope!
Die Ausgabe von "uname -a" ist:
Code: 
Linux ve4523 2.4.7-64GB-SMP #1 SMP Fri Aug 17 03:20:05 GMT 2001 i686 unknown
In ein paar Stunden läuft mein Versuch über einen Tag. Mal sehen ob sich die cron entschließt wieder anzulaufen. Ich vermute: Ja. In diesem Fall wäre mein Problem geklärt.
 
OP
A

apollo

Newbie
apollo schrieb:
Heureka! Ich hab zumindest die halbe Lösung. Man kann cron durcheinander bringen wenn man:

1. Die Systemzeit in die Vergangenheit setzt (z.B. minus ein Tag)
2. ein paar Minuten wartet
3. Die Systemzeit wieder in die Gegenwart setzt

Ergebnis: cron funktioniert nicht mehr.
Zum Vergrößern anklicken....
Es gibt Neuigkeiten: auf meinem Testrechner ist cron wieder auferstanden. Heute, um 16:22:15 wurde die gesamt crontab ausgeführt. Nach fast einem Tag. Jetzt werden die cron-jobs wieder normal abgearbeitet.
Ich habe auf dem Testrechner seit gestern nichts verändert. Die crontab ist die gleiche, es wurde nicht gebootet und der cron-deamon wurde nicht restartet.
Meine logfile sieht jetzt so aus:
Code: 
Wed Oct  5 16:18:00 CEST 2005 */6
Wed Oct  5 16:20:00 CEST 2005 */5
Die Okt  4 16:20:29 CEST 2005 set
Mit Okt  5 16:22:29 CEST 2005 set
Thu Oct  6 16:22:15 CEST 2005 */5
Thu Oct  6 16:22:15 CEST 2005 */6
Thu Oct  6 16:24:00 CEST 2005 */6
Thu Oct  6 16:25:00 CEST 2005 */5
Thu Oct  6 16:30:00 CEST 2005 */5
Thu Oct  6 16:30:00 CEST 2005 */6
Damit ist mein ursprünglicher Fehler absolut nachvollziebar. :D
Ich frage mich nur, was passiert, wenn man nicht nur einen Tag sondern mehrere Tage zurückgeht...
 
scg

scg

Hacker
Leute, ich werde das langsam mal in Richtung "Uhrzeit" verschieben, scheint mir mehr auf ne Zeitgeschichte rauszulaufen als auf ein Konsolenproblem.
 
Du musst dich einloggen oder registrieren, um hier zu antworten.
Oben