[SOLVED] illegal attempt to update using time

  • Hallo Monitorer,
    ich habe nun das gesamte Internet nach einer Lösung durchsucht, jedoch nicht wirklich was gefunden.


    PNP funktionierte wunderbar, bis ich letzte Woche auf Icinga 1.7.1 geupdatet hab.


    perfdata.log

    Code
    1. RRDs::update ERROR /usr/local/pnp4nagios/var/perfdata/azs-dt100-02/Network_Ping.rrd: illegal attempt to update using time 1342521488 when last update time is 1342521488 (minimum one second step)


    Soll ja glaub ich bedeuten, 2 Checks zur gleichen Zeit.


    Von diesen Kandidaten gibt es immer so 1-2 pro Minute, mal Ping mal CPU Load.


    Nur habe ich nichts geändert, bis auf das Icinga Update. Aus Verzweiflung habe ich dann noch RRD, sowie PNP aktualisiert.


    Hier das Ergebnis vom Verify-Script


    Gibt es Lösungsvorschläge?
    ./stiftmaster

  • icinga.debug


    perfdata.log

    Code
    1. 2012-07-17 14:59:42 [30179] [0] RRDs::update /usr/local/pnp4nagios/var/perfdata/srv-vc01/Processes_-Total_Processes.rrd 1342529970:62.000000
    2. 2012-07-17 14:59:42 [30179] [0] RRDs::update ERROR /usr/local/pnp4nagios/var/perfdata/srv-vc01/Processes_-Total_Processes.rrd: illegal attempt to update using time 1342529970 when last update time is 1342529970 (minimum one second step)


    Oder welches Log meinst Du

  • ich meinte icinga.debug, aber ueber die zeit gesehen - wenn du sagst, dass da checks innerhalb der selben sekunde stattfinden, dann moechte ich das in eingem groben interval sehen - sagen wir mal 5 bis 10 minuten. um ggf ein muster zu erkennen.

  • Das sind die Kandidaten in diesem Zeitraum



    [1342534530.076669] srv-icinga01/Network_Netstat_-_SSH_Connections
    [1342534530.085126] pabx-101/Network_Ping
    [1342534530.181864] srv-vc01/Processes_-Total_Processes
    [1342534561.268499] srv-ns01/Memory_Free



    editiert:

    Files

    • icinga.zip

      (99.03 kB, downloaded 193 times, last: )

    The post was edited 2 times, last by stiftmaster ().

  • ich hab mal ein .zip draus gemacht und angehaengt. ich mag externe urls auf logs nicht, die halten meist nicht ewig...selbiges wuerde ich dir auch fuer die zukunft empfehlen.
    jetzt mal in ruhe lesen.

  • Code
    1. 2012-07-17 14:59:42 [30179] [0] RRDs::update /usr/local/pnp4nagios/var/perfdata/srv-vc01/Processes_-Total_Processes.rrd 1342529970:62.000000 2012-07-17 14:59:42 [30179] [0] RRDs::update ERROR /usr/local/pnp4nagios/var/perfdata/srv-vc01/Processes_-Total_Processes.rrd: illegal attempt to update using time 1342529970 when last update time is 1342529970 (minimum one second step)


    Wenn sowas passiert würde ich im Log erst mal nach dem Timestamp suchen und analysieren ob die Daten wirklich zweimal reingekommen sind.


    Code
    1. grep 1342529970 perfdata.log
  • grep 1342529970 /usr/local/pnp4nagios/var/perfdata.log

    Code
    1. 2012-07-17 14:59:42 [30180] [0] RRDs::update ERROR /usr/local/pnp4nagios/var/perfdata/srv-ns01/Memory_Free.rrd: illegal attempt to update using time 1342529950 when last update time is 1342529970 (minimum one second step)
    2. 2012-07-17 14:59:42 [30180] [0] RRDs::update ERROR /usr/local/pnp4nagios/var/perfdata/srv-prn01/CPU_Load.rrd: illegal attempt to update using time 1342529950 when last update time is 1342529970 (minimum one second step)
    3. 2012-07-17 14:59:42 [30179] [0] RRDs::update /usr/local/pnp4nagios/var/perfdata/srv-vc01/Processes_-Total_Processes.rrd 1342529970:62.000000
    4. 2012-07-17 14:59:42 [30179] [0] RRDs::update ERROR /usr/local/pnp4nagios/var/perfdata/srv-vc01/Processes_-Total_Processes.rrd: illegal attempt to update using time 1342529970 when last update time is 1342529970 (minimum one second step)
  • darf ich die service definitionen zu den checks die du da auflistest, mal sehen? irgendwelche addons installiert, die in diesen checkmechanismus eingreifen?

  • Für den srv-icinga01 z.B.
    (also Addons sind keine weiter konfiguriert)


    Code
    1. define service{
    2. use 24x7-service-check-one-times-per-minute,pnp-service
    3. host_name srv-icinga01
    4. service_description Network Netstat - SSH Connections
    5. check_command check_local_netstat!22!4!6!22
    6. }


    Code
    1. define service{
    2. name pnp-service
    3. register 0
    4. action_url /pnp4nagios/index.php/graph?host=$HOSTNAME$&srv=$SERVICEDESC$' class='tips' rel='/pnp4nagios/index.php/popup?host=$HOSTNAME$&srv=$SERVICEDESC$
    5. }


    Code
    1. define service{
    2. name 24x7-service-check-one-times-per-minute
    3. use generic-service
    4. max_check_attempts 3
    5. normal_check_interva 1
    6. retry_check_interval 2
    7. register 0
    8. }



  • is das ein copypaste fehler, oder tatsaechlich so?


    andere frage - wieso checkt man einen service jede minute, um dann im fehlerfall alle 2 minuten zu rechecken?
    ansonsten hat sich mein verdacht, es hier mit passiven checks only zu tun zu haben, wohl in luft aufgeloest.


    zum problem an sich - ich sehe um 1342534550 massig checkresults, die eingelesen werden. dazu wuerde mich die icinga.cfg interessieren, insbesondere das reaping interval.


    Code
    1. # egrep -v "^#|^$" icinga.cfg


    und gemessen an der ausfuehrung, und der relativ geringen latenz - der check wird scheduled und ist 5sec spaeter schon wieder in der queue. ich wuerde mal annehmen, dass das reaping interval bei etwa 5sec liegt.


    sieht fuer mich also sehr normal aus - den service gibts natuerlich massig, weil er vielen verschiedenen hosts zugeordnet ist, jede relation fuer sich unique.

  • michael


    lass uns erst mal auf PNP Seite analysieren.


    stiftmaster


    Ich finde es komisch das rrdtool anmäckert das es bereits einen eintrob für einen gewissen Timestamp gibt, dieser aber nicht zwei mal im log auftaucht.
    Weiterhin ist es komisch das es im Log Einträge zur gleichen Zeit von zwei process_perfdata.pl Prozessen gibt.


    Daraufhin solltest du deine PNP Logs mal genauer untersuchen.

  • Kann es sein, dass es das gleiche wie bei mir ist?
    Es wird ja auch der NPCD genutzt


    Vielleicht hilft da das NPCD-Logfile weiter

    ~~ Never touch a running system ~~
    ~~ Never run a touchy system ~~

  • Anmerkung: Hier ist nicht überall exakt derselbe Zeitstempel unterwegs:

    14:59:42 [30180] using time 1342529950 when last update time is 1342529970
    14:59:42 [30180] using time 1342529950 when last update time is 1342529970
    14:59:42 [30179] [0] RRDs::update 1342529970:62.000000
    14:59:42 [30179] using time 1342529970 when last update time is 1342529970

    (14:59:42 = 1342529982)


    Also ein Geschehen, das über mehr als 30 Sekunden verteilt ist. Wenn da wirklich Intervalle von 5s u.ä. eingestellt sind, klemmt platten-/filesystemseitig 'was.

  • Morgen Monitorer,


    ja das retry interval hab ich angepasst :wacko:


    Anbei noch die cfg und das Log vom NPCD

  • Code
    1. [07-17-2012 14:59:42] NPCD: A thread was started on thread_counter = 3
    2. [07-17-2012 14:59:42] NPCD: Have to wait: Filecounter = 4 - thread_counter = 4
    3. [07-17-2012 14:59:42] NPCD: Processing file host-perfdata.1342529980 with ID 140098671748864 - going to exec /usr/local/pnp4nagios/libexec/process_perfdata.pl -n -b /usr/local/pnp4nagios/var/spool//host-perfdata.1342529980
    4. [07-17-2012 14:59:42] NPCD: Processing file 'host-perfdata.1342529980'
    5. [07-17-2012 14:59:42] NPCD: Processing file service-perfdata.1342529980 with ID 140098652776192 - going to exec /usr/local/pnp4nagios/libexec/process_perfdata.pl -n -b /usr/local/pnp4nagios/var/spool//service-perfdata.1342529980
    6. [07-17-2012 14:59:42] NPCD: Processing file 'service-perfdata.1342529980'
    7. [07-17-2012 14:59:42] NPCD: Processing file service-perfdata.1342529965 with ID 140098661168896 - going to exec /usr/local/pnp4nagios/libexec/process_perfdata.pl -n -b /usr/local/pnp4nagios/var/spool//service-perfdata.1342529965
    8. [07-17-2012 14:59:42] NPCD: Processing file 'service-perfdata.1342529965'


    [07-17-2012 14:59:42] NPCD: Have to wait: Filecounter = 4 - thread_counter = 4


    IMHO musst du mal den Thread count hochdrehen.

    ~~ Never touch a running system ~~
    ~~ Never run a touchy system ~~

  • Wir reden aber andeuernd vom perfdata.log das von process_perfdata.pl erzeugt wird.


    Zum Hntergrund:


    rrdtool kann nur neue Werte an ein RRD File anhängen.


    Quote

    using time 1342529950 when last update time is 1342529970


    hier sollen also werte für 1342529950 geschriebn werden, es sind aber schon werte für 1342529970 geschriebn worden.


    Daher auch Jochens und Stefans Vermutung das process_perfdata.pl auf deinem System etwas aus dem Tritt kommt.
    Möglichwerweise zu hoher IO Wait oder schlicht schlechtes Timing