[Gelöst] VDR 2.6.1 SVDRP POLL TIMERS: timeout while waiting for response

  • Ich poste mein Thema von hier mit mehr Details nochmals in VDR Core in der Hoffnung, kls hat einen Tipp.

    Ich glaube inzwischen nicht mehr, dass das was mit epgd zu tun hat, außer vielleicht, dass er zusätzliche Last auf den svdrp Schnittstelle erzeugt und damit die Meldung häufiger kommt.

    Umgebung: Zwei vdr 2.6.1 Backends, die über Peering mit einander verbunden sind.

    Ich bekomme im 10-20 Minutentakt folgende Meldung ins Syslog:

    Code
    1. Jun 24 19:14:51 user.err VDR-2204 vdr: [439] SVDRP VDR-2204 < 10.1.5.143:6419 timeout while waiting for response from 'VDR-2204-Dev'
    2. Jun 24 19:14:51 user.err VDR-2204 vdr: [439] ERROR: can't send 'POLL VDR-2204 TIMERS' to 'VDR-2204-Dev'
    3. Jun 24 19:25:11 user.err VDR-2204 vdr: [439] SVDRP VDR-2204 < 10.1.5.143:6419 timeout while waiting for response from 'VDR-2204-Dev'
    4. Jun 24 19:25:11 user.err VDR-2204 vdr: [439] ERROR: can't send 'POLL VDR-2204 TIMERS' to 'VDR-2204-Dev'

    Ich habe mal versucht den Timeout näher zu analysieren (Syslog von der Gegenseite zum ersten Eintrag, mit zusätzlich eingebauten Meldungen):

    Dadurch, dass der MutexLock 5s braucht, gibt es auf der Gegenseite einen Timeout. Hochsetzen des Timeouts bringt nichts, dann braucht der MutexLock entsprechend länger ?!

    Ich habe nur Timeout zu POLL TIMERS im syslog, keine andern. Das Peering funktioniert aber ohne Einschränkungen, da der Befehl nur sporadisch in den Timeout läuft.

    Mit ist es nicht gelungen, rauszufinden, wer/was diesen Lock hält und warum genau für die Dauer des Timeouts. kls hast du einen Tipp, wo es hängt ?

    Als Anlage die Änderungen um die zusätzlichen Logs zu erzeugen.

    Files

    • logs.patch

      (5.59 kB, downloaded 29 times, last: )
    VDR
  • Ich glaube, ich habe den Auslösers des Timeouts gefunden: Das Problem tritt auf, wenn beide VDRs fast zeitgleich einen POLL TIMERS aufführen. Dann gibt es wohl einen Deadlock in irgendeinem Lock. Der Timeout des Clients löst ihn dann zwar auf, aber dann ist auch der Serverrequest so weit verzögert, dass die zugehörige Anfrage auch in den Timeout läuft. Damit bringt es auch nichts, den Timeout zu erhöhen.

    VDR1:

    VDR2:

    Ich suche noch nach einer Lösung, jegliche Hilfe oder Tipps sind willkommen.

    VDR
  • kls ,

    vielen Dank, dass du dir das nach deinem Urlaub anschaust.

    Mit der Ursache bin ich wohl auf der richtigen Spur, angehängter proof of concept reduziert die Timeouts um ca. Faktor 10. Ein kleiner Rest bleibt aber übrig. Ich nenne es bewusst nicht Fix, weil der Code so sicher nicht zur Übernahme geeignet ist. Dazu verstehe ich die Locks in svdrp immer noch zu wenig.

    Schönen Rest-Urlaub noch.

    Files

    • poc.patch

      (2.21 kB, downloaded 34 times, last: )
    VDR
  • Und hier noch eine bessere Variante, die jetzt alle Timeouts beseitigt. Die Idee dazu ist, bei einem Deadlock den Lock vom svdp Client Request aus timen zu lassen, um dann den Server Request bedienen zu können. Mit dem angehängten Patch habe ich jetzt seit 12h keinen Timeout mehr, es sind aber natürlich noch ein paar zusätzliche Debug Meldungen drin.

    Files

    • poc2.patch

      (3.36 kB, downloaded 39 times, last: )
    VDR
  • kls

    Ich wärme das Thema nochmals auf: Der angehängte Patch läuft bei mir seit Juni ohne Timeouts. Er ist mit dem Ziel erstellt, möglichst wenig bestehen VDR Code zu ändern. Natürlich könnte man die Timeout Funktion auch in die bestehende Methoden integrieren, was aber zusätzliche Änderungen im VDR Code erfordern würde.

    Files

    • patch.txt

      (2.98 kB, downloaded 20 times, last: )
    VDR
  • kfb77 Dein Patch würde zwar das akute Problem lösen, die Ursache liegt aber vermutlich tiefer.

    Magst du bitte mal den beiliegenden Patch ausprobieren? Bitte ohne deine cMutexTimedWait Änderung, aber gerne mit den Debug-Ausgaben für weitere Untersuchungen. Ich glaube nämlich, dass die "externen" Lock/Unlock-Aufrufe überflüssig und vielleicht sogar störend sind.

    Bitte mach auch Debug-Ausgaben in die Funktion ExecSVDRPCommand() rein:

  • kls

    Der Patch und deine Debugs sind jetzt in beiden VDRs drin.

    Ich gehe mal davon aus, dass die Timeouts weg sind, da ja der ursächliche Lock entfernt wurde. Ich werde das mal ein paar Tage beobachten, ob mir Probleme damit auffallen.

    Danke.

    VDR
  • Zu früh gefreut, ich habe die Timeouts wieder:

    Code
    1. Nov 15 14:07:42 user.err VDR-2204-Dev vdr: [14289] SVDRP VDR-2204-Dev < 10.1.5.144:6419 timeout while waiting for response from 'VDR-2204'
    2. Nov 15 14:07:42 user.err VDR-2204-Dev vdr: [14289] ERROR: can't send 'POLL VDR-2204-Dev TIMERS' to 'VDR-2204'
    3. Nov 15 14:16:28 user.err VDR-2204 vdr: [67944] SVDRP VDR-2204 < 10.1.5.143:6419 timeout while waiting for response from 'VDR-2204-Dev'
    4. Nov 15 14:16:28 user.err VDR-2204 vdr: [67944] ERROR: can't send 'POLL VDR-2204 TIMERS' to 'VDR-2204-Dev'
    5. Nov 15 14:19:03 user.err VDR-2204 vdr: [67944] SVDRP VDR-2204 < 10.1.5.143:6419 timeout while waiting for response from 'VDR-2204-Dev'
    6. Nov 15 14:19:03 user.err VDR-2204 vdr: [67944] ERROR: can't send 'POLL VDR-2204 TIMERS' to 'VDR-2204-Dev'

    Syslog beider VDRs zum Timeout um 14:16 Uhr siehe Anlage.

    Ich werde mal wieder ein paar zusätzliche Debug Outputs rein bauen, damit man die Ursache erkennen kann, das Syslog gibt (für mich) nichts her..

    Files

    • syslog.txt

      (10.32 kB, downloaded 8 times, last: )
    VDR
  • Ja, Meldungen kommen, aber zu anderen Zeitpunkten.

    VDR
  • Ich habe noch ein Log mit mehr Debug Infos:



    Für sieht das so aus, als ob es einen deadlock über die beiden VDRs gibt. Jeder locked den gleichen Mutex für seinen eigenen SVDRP Client Request und zur Bearbeitung des ankommenden Server Request.


    Im Log habe ich nur den Lock vom Server Teil, den vom Client habe ich noch nicht gefunden.

    Eigentlich müsste der doch hier sein:

    Code
    1. bool cSVDRPClientHandler::Execute(const char *ServerName, const char *Command, cStringList *Response)
    2. {
    3. dsyslog("cSVDRPClientHandler::Execute want mutex");
    4. cMutexLock MutexLock(&mutex);
    5. dsyslog("cSVDRPClientHandler::Execute got mutex");
    6. if (cSVDRPClient *Client = GetClientForServer(ServerName))
    7. return Client->Execute(Command, Response);
    8. return false;
    9. }

    Aber da bekomme ich keine Log Ausgabe ???

    VDR
  • Hier das Syslog davon. Erstaunlicherweise hatte mein zentraler syslog Server kein Problem mit der Flut an Meldungen. ;-)

    Files

    • syslog.txt

      (7.43 kB, downloaded 11 times, last: )
    VDR

    The post was edited 1 time, last by kfb77 ().

  • Ich habe mich inzwischen dran gewagt, deine Logs zu interpretieren. Sie bestätigen meinen Verdacht des Deadlocks meiner Meinung nach.

    Minimaler Auszug aus o.g. syslog:


    VDR
  • kfb77 Bitte teste beiliegenden Patch (gegen die original svdrp.c).

    Ich habe das Locking in cSVDRPClientHandler lokaler gehalten, denn der Mutex schützt ja nur Veränderungen an clientConnections, sollte also nicht zu lange gehalten werden.

    Die Debug-Ausgaben habe ich noch drin gelassen, für den Fall, dass das noch nicht die Lösung ist.

  • Kein Problem, habe es eh erst nach dem 2. Post gelesen.

    fix 4 ist drin, jetzt ist wieder warten auf timeouts angesagt, oder hoffentlich nicht ...

    VDR