[vz-dev] Bug in C++Port von vzlogger - Puffer entleert sich nicht mehr

[Kai Krueger]

Hallo Justin,

> Am 06.08.2012 um 07:47 schrieb Kai Krueger:
>> Dem Log nach scheint der logging thread im 'curl_send' zu haengen.
>> Kannst Du aus dem spaeteren Verlauf des Log feststellen, ob es ein
>> Timeout gab?
> wie kann ich das erkennen?
> Die Situation hatte sich nicht selbst wieder eingerenkt; ich habe vzlogger
> gestoppt, nachdem mehr als 1.000 Werte im Puffer waren.
> Hab ich Dich falsch verstanden?
Du kannst bei libcurl eine Debugmethode konfigurieren. (Hier:
curl_custom_debug_callback() [2])
Die gibt Dir aus was bzw. wie viel gesendet und empfangen wurde [3].
D.h. auf ein 'CURL: Sent 40 bytes..' muss irgendwann ein 'CURL: Recv '
folgen. Ein Timeout sollte jenach Einstellung etwa nach 30-120 sec.
zuschlagen. Ich entnehme Deiner Antwort, dasz Du den Logger nach etwa 15
Minuten neu gestartet hast. Das wuerde darauf hindeuten, dasz hier punkto
Timeout etwas getan werden muesste.

>> Im zweiten Fall bekommt der Aufruf zu mindest 'CURL: Recv failure:
>> Connection reset by peer' als antwort und kann entsprechend reagieren.
> ist das nicht schon bevor der Puffer sich füllt? Zeilen 78-86; Puffer
> füllt sich ab Zeile 115
>
>> Kann man den IP-wechsel exakt an dem Zeitstempel 'Aug 02 20:45:21' fest
>> machen?
> nicht sicher; ich vermute es aber stark:
> 20:45:21 meldet vzlogger die letzte erfolgreiche Anfrage (iconnect)
> 20:45:21 habe ich den letzten Eintrag im Log des Apache auf
> demo.volkszaehler.org
> 20:45:24 meldet vzlogger zum ersten Mal, dass es schief gegangen ist
> 21:00:02 kommt vzmonitor vorbei (läuft auch auf dem iconnect) und will
> wissen, ob mit dem Kanal alles in Butter ist; das ist dann schon mit der
> neuen IP
>
> vzlogger loggt dann erst nach einem händischen Neustart wieder.
>
> Die beiden Rechner (iconnect mit vzlogger und demo.volkszaehler.org)
> verwenden NTP; einen passenden Zeitstempel vom DSL-Router habe ich nicht.
>
> Beantwortet das Deine Frage?
Ja danke. (s.o).

>> Der IP-Wechsel ist Clientseitig?
> jepp, ich hab am DSL-Anschluss ne neue IP bekommen.
>
>> Ich schaue mal ob ich ein haengenbleiben im 'curl_send'
>> (curl_easy_perform()) reproduzieren kann, um dann zu sehen in wie weit
>> man
>> hier ein Timeout provozieren kann.
> ok. Wie sieht denn der Ablauf an der Stelle aus:

Reading thread:
> 1 [Aug 02 20:45:21][chn0] Adding reading to queue (value=2276.80
> ts=1343933121.627)

Logging thread
> 2 [Aug 02 20:45:21][api]  ==> number of tuples: 1
> 3 [Aug 02 20:45:21][CURL] compare: 1343933118801 1343933121627
> 1343933121626.678955
> 4 [Aug 02 20:45:21][chn0] JSON request body: [ [ 1343933121626.678955,
> 2276.800000 ] ]
5 [....][chn0] curlaufruf curl_easy_perform(curl());
  [....][chn0] debug aufgaben libcurl
6 [Aug 03 15:32:47][chn0] CURL: Sent 268 bytes..
7 [Aug 03 15:32:47][CURL] CURL: Sent '[ [...]' bytes
8 [Aug 03 15:32:47][chn0] CURL: Received 17 bytes
9 [Aug 03 15:32:47][chn0] CURL Request succeeded with code: 200
oder
9 [Aug 03 15:32:17][chn0] CURL: Recv failure: Connection reset by peer


> Zeile 1: das ist in beiden Fällen (Wert wird geloggt und Wert wird nicht
> geloggt) zu sehen
> Zeilen 2-4: die Zeilen finden sich nur, wenn das Logging auch klappt;
> anderenfalls füllt sich der Puffer
> Zeilen 2-4 werden in Methode vz::api::Volkszaehler::api_json_tuples [1]
> generiert und diese wird in vz::api::Volkszaehler::send [2] aufgerufen,
> korrekt?
Bis dahin korrekt.

> Läuft das dann nicht schon vor dem Absetzen des CURL-Requests schief?
Eigentlich nicht, weil der vorgehende CURL-Requests noch nicht fertig war.
In Deinem ersten Durchlauf fehlen die Zeilen 7-9.
Daher meine Vermutung: der logging thread haengt im Senden, oder, viel
schlimmer, hat sich beendet.

> Welche Fälle können denn dazu führen, dass der Puffer gefüllt wird?
> Kannst Du mir sagen, an welchen Codestellen diese Fälle abgefragt werden?
Gefuellt wird der Puffer im reading-thread in [4] welches dann effektiv
[5] ausgefuehrt wird.


> Falls Du neue Fragen hast: her damit :-)
>
> Danke schon mal!
Danke fuer die Antworten.
Viele Gruesse
Kai

> [1]
https://github.com/kaikrueger/vzlogger/blob/c%2B%2B-port/src/api/Volkszaehler.cpp#L150
>
[2]
https://github.com/kaikrueger/vzlogger/blob/c%2B%2B-port/src/api/Volkszaehler.cpp#L79
[3]
https://github.com/kaikrueger/vzlogger/blob/c%2B%2B-port/src/api/Volkszaehler.cpp#L244
und folgende
[4]
https://github.com/kaikrueger/vzlogger/blob/c%2B%2B-port/src/threads.cpp#L106
[5]
https://github.com/kaikrueger/vzlogger/blob/c%2B%2B-port/src/Buffer.cpp#L40