[vz-users] Auswertung Protocol d0 / vzlogger crash

Eugen Sartoris eugen at sartoris.de
Mon Oct 22 11:30:52 CEST 2012 

Noch ein Hinweis zu Punkt a)

 
Die Timestamps/Werte beim d0 meter zeigen zum Teil sehr seltsame Graphen.

 
Hier mal ein Beispiel: ( s. Anhang  Daten sind in der Testumgebung )

 
Der Gesamtzähler der PV-Anlage (d0)  springt in der Anzeige im Takt von 1 -2 sec. zwischen ca 3500W und 7500W.um einen gleichbleibenden Mittelwert.

Das kann aber in der Realität nicht sein, da meine PV-Anlage max 6000W bringt und die Sonne kontinuierlich da war.....

 
Es sieht so aus als ob bei der Berechnung des Wertes / timestamp ein Timing Problem auftritt, sodass die Verbrauchswerte um einen Mittelwert stark schwanken.

 
ES.

 
 
 
 
-----Ursprüngliche Nachricht-----
Von:Thorben Thuermer <r00t at constancy.org>
Gesendet:Mo 22.10.2012 02:11
Betreff:Re: [vz-users] Auswertung Protocol d0 / vzlogger crash
An:volkszaehler-dev at lists.volkszaehler.org; 
CC:volkszaehler-users at lists.volkszaehler.org; 

toll was man alles findet, wenn man mal dabei ist...
gleich noch ZWEI neue bugs... aber crash erst nach ~16 stunden:
(nebenbei verlegen wir das thema mal auf die -dev liste...
 oder sind eh alle auf beiden?)

a)
[Oct 22 00:41:12][ch0]  JSON request body: [ [ 1350858306844.057129, 14926.195312 ], [ 1350858306844.476074, 82.000000 ],
[Oct 22 00:41:12][ch0]  Request failed: [400] PDOException: SQLSTATE[23000]: Integrity constraint violation: 1062 Duplicate entry '2-1350858306844' for key 'ts_uniq'

=> vzlogger hat zwei eintraege mit identischem (nach dem runden) timestamp erzeugt,
   die die middleware nicht eintragen kann.
   ist das ein middleware oder ein vzlogger-bug?

b)
crash beim return aus meter_read_d0, weil der stack ueberschrieben wurde...
das ist dann wohl wirklich ein bug im d0-parser.
(ggfs zusammenhang mit dem vollen puffer wegen des middleware-problems?)
leider hatte ich da wohl keinen efence an, sonst wuessten wir's genauer.
(ich habe die "something unexpected happened" meldung nebenbei mal
 etwas verbessert...) (log gekuerzt)
[Oct 22 00:41:44][mtr0] unexpected byte while reading vendor: 34 '4'!
[Oct 22 00:41:44][mtr0] unexpected byte while reading vendor: 38 '8'!
[Oct 22 00:41:44][mtr0] unexpected byte while reading vendor: 5f '_'!
[Oct 22 00:41:44][mtr0] unexpected byte while reading vendor: 34 '4'!
[Oct 22 00:41:44][mtr0] unexpected byte while reading vendor: 38 '8'!
[Oct 22 00:41:44][mtr0] unexpected byte while reading vendor: 5f '_'!
[Oct 22 00:41:44][ch0]  Buffer dump (size=86 keep=0): {14926.20!,82.00,14926.20,...
[Oct 22 00:41:44][ch1]  Buffer dump (size=0 keep=0): {}
[Oct 22 00:41:44][mtr0] unexpected byte while reading vendor: 34 '4'!
[Oct 22 00:41:44][ch0]  Buffer dump (size=86 keep=0): {14926.20!,82.00,14926.20,...
[Oct 22 00:41:44][ch1]  Buffer dump (size=0 keep=0): {}
[Oct 22 00:41:44][mtr0] unexpected byte while reading vendor: 30 '0'!
*** stack smashing detected ***: /vz/vzlogger.stv0g/src/vzlogger terminated
(gdb) bt
#4  0x00007ffff6d628d0 in __stack_chk_fail () from /lib/x86_64-linux-gnu/libc.so.6
#5  0x0000000000407379 in meter_read_d0 (mtr=0x634350, rds=0x7fffec0008c0, max_readings=32) at protocols/d0.c:282
282     }
$5 = {id = "mtr0", interval = 1, protocol = meter_protocol_d0, handle = {file = {path = 0x0,
      format = 0x6343e0 "/dev/lesekopf0", rewind = 9600, fd = 0x500}, exec = {command = 0x0,
      format = 0x6343e0 "/dev/lesekopf0"}, random = {min = 0, max = 3.2141144150814789e-317,
      last = 1.6975971070752379e-313}, s0 = {device = 0x0, resolution = 6505440, fd = 0, old_tio = {c_iflag = 9600,
        c_oflag = 8, c_cflag = 1280, c_lflag = 0, c_line = 173 '\255',
        c_cc = "\r\000\000\060\n\000\000\000\003\034\177\025\004\000\001\000\021\023\032\000\022\017\027\026\000\000\000\000\000\000\000", c_ispeed = 0, c_ospeed = 0}}, d0 = {host = 0x0, device = 0x6343e0 "/dev/lesekopf0", baudrate = 9600,
      fd = 8, oldtio = {c_iflag = 1280, c_oflag = 0, c_cflag = 3501, c_lflag = 2608, c_line = 0 '\000',
        c_cc = "\003\034\177\025\004\000\001\000\021\023\032\000\022\017\027\026", '\000' <repeats 15 times>,
        c_ispeed = 13, c_ospeed = 13}}, fluksov2 = {fifo = 0x0, fd = 6505440}, sml = {host = 0x0,
      device = 0x6343e0 "/dev/lesekopf0", baudrate = 9600, fd = 8, old_tio = {c_iflag = 1280, c_oflag = 0, c_cflag = 3501,
        c_lflag = 2608, c_line = 0 '\000',
        c_cc = "\003\034\177\025\004\000\001\000\021\023\032\000\022\017\027\026", '\000' <repeats 15 times>,
        c_ispeed = 13, c_ospeed = 13}}}}

#6  0x0000000000405439 in reading_thread (arg=0x634350) at threads.c:62

- T.

On Sun, 21 Oct 2012 17:27:26 +0200
Thorben Thuermer <r00t at constancy.org> wrote:
> Hallo,
> 
> das problem ist dann geklaert:
> der resolver in libcurl ist _nicht_ thread-safe.
> 
> d.h., wenn zwei threads gleichzeitig einen namen aufloesen, gibt es eine
> race-condition die zu dem crash fuehrt.
> 
> das ist recht eindeutig ein bug in libcurl...
> unter: http://curl.haxx.se/libcurl/features.html
> wird angegeben, libcurl sei dann thread-safe, wenn die gethostbyname()
> funktion des betriebssystems thead-safe ist,
> aber das problem liegt nicht in gethostbyname(), sondern in der benutzung
> von alarm() um einen timeout fuer gethostbyname() zu erzwingen.
> (related: https://bugzilla.redhat.com/show_bug.cgi?id=539809 ) 
> 
> in Eugen's konfiguration tritt das problem vor allem deshalb auf,
> weil aus einem meter zwei channels erzeugt werden,
> d.h. jedesmal wenn vom meter daten kommen, werden gleichzeitig zwei
> middleware-aufrufe gestartet, um die daten der beiden channels zu
> uebermitteln, was dann irgendwann das richtige timing fuer die race-condition
> liefert und zum crash fuehrt.
> 
> der crash tritt seltener auf, wenn man statt "localhost" direkt "127.0.0.1"
> fuer den middleware-server angibt, vermutlich weil die aufloesung dann
> schneller geht.
> (ein externer dns-server ist in beiden faellen nicht involviert,
>  da der name im hostsfile steht.)
> 
> als fix waehre entweder der bug in libcurl zu beheben...
> oder libcurl mit unterstuetzung fuer einen alternativen resolver zu kompilieren:
> http://curl.haxx.se/dev/readme-ares.html
> 
> ansonsten kann man als workaround libcurl ohne HAVE_ALARM kompilieren
> (nach dem ./configure den HAVE_ALARM eintrag in lib/curl_config.h
> entfernen oder auskommentieren (nicht 1 durch 0 ersetzen!).
> (das hat den nachteil, dass das programm u.U. bei der aufloesung
>  haengenbleibt, falls der timeout-mechanismus des betriebssystems
>  nicht greift.)
> 
> (Eugen: letzteres ist momentan bei dir in /vz/libcurl-7.28.0-prefix bzw
>  /vz/curl-7.28.0 implementiert, vzlogger laeuft jetzt seit ueber
>  zehn stunden durch.)
> 
> - T.
> 
> On Sat, 20 Oct 2012 22:41:27 +0200 Thorben Thuermer <r00t at constancy.org> wrote:
> > On Sat, 20 Oct 2012 17:32:26 +0200
> > Thorben Thuermer <r00t at constancy.org> wrote:
> > > Hallo Eugen und andere,
> > > 
> > > Eugen hat mir inzwischen einen testzugang gegeben, und ich versuche das
> > > weiter zu debuggen.
> > > 
> > > meine momentane vermutung ist, dass der bug nicht direkt in vzlogger ist,
> > > sondern es ein problem mit libcurl (in verbindung mit einer mit fortify
> > > kompilierten libc?) gibt.
> > > (der crash passiert scheinbar immer aus libcurl heraus.)
> > > https://wiki.ubuntu.com/Security/Features#Built_with_Fortify_Source
> > > https://wiki.ubuntu.com/ToolChain/CompilerFlags#A-D_FORTIFY_SOURCE.3D2
> > > ein derartiges problem gab es wohl zB. hier schonmal:
> > > https://bugzilla.redhat.com/show_bug.cgi?id=539809
> > 
> > libcurl mit debug kompiliert, man lese und staune...
> > der crash passiert wohl reproduzierbar an der gleichen stelle in libcurl...
> > hat also tatsaechlich was mit libcurl und dns zu tun,
> > und wenn es an dns-timeouts liegt,
> > wuerde das das zufaellige timing der crashes erklaeren.
> > 
> > [Oct 20 18:34:05][ch1]  CURL: Connection #0 to host localhost left intact
> > [Oct 20 18:34:05][ch1]  Request succeeded: 200
> > 
> > Program received signal SIGSEGV, Segmentation fault.
> > 0x00007ffff6e52118 in addbyter (output=110, data=0x7ffff01b2580) at mprintf.c:1013
> > 1013        infop->buffer[0] = outc; /* store */
> > (gdb) bt full
> > #0  0x00007ffff6e52118 in addbyter (output=110, data=0x7ffff01b2580) at mprintf.c:1013
> >         infop = 0x7ffff01b2580
> >         outc = 110 'n'
> > #1  0x00007ffff6e50e4c in dprintf_formatf (data=0x7ffff01b2580, stream=0x7ffff6e520df <addbyter>,
> >     format=0x7ffff6e808f3 "name lookup timed out", ap_save=0x7ffff01b25d0) at mprintf.c:671
> > [...]
> >         f = 0x7ffff6e808f3 "name lookup timed out"
> > [...]
> > #2  0x00007ffff6e52198 in curl_mvsnprintf (
> >     buffer=0x404a30 "\377M\211l$\020A\211D$\b1\300ë¸ hostip.c:611
> >           keep_sigact = {__sigaction_handler = {sa_handler = 0x7ffff01b27e0, sa_sigaction = 0x7ffff01b27e0}, sa_mask = {
> > 
> > 
> > > - Thorben
> > - T.
> > 
> > > On Fri, 21 Sep 2012 15:54:30 +0200 (CEST)
> > > Eugen Sartoris <eugen at sartoris.de> wrote:
> > > > Hallo Thorben,
> > > > 
> > > > danke für die Hinweise.
> > > > Ich werde eine neue Testumgebung aufbauen unter ubuntu 10.04 und dann auch mit
> > > > einem Deamon je Lesekopf ( insges. 3 )
> > > > Wenn die Fehler isoliert sind melde ich mich wieder. Je nach Konfig der
> > > > Testumgebung kann ich die einen Zugang einrichtern, sofern das für dich in Frage
> > > > kommt.
> > > > 
> > > > gruss
> > > > 
> > > > eugen
> > > > 
> > > > 
> > > > Thorben Thuermer <r00t at constancy.org> hat am 19. September 2012 um 22:45
> > > > geschrieben:
> > > > > On Wed, 19 Sep 2012 22:13:49 +0200 (CEST)
> > > > > Eugen Sartoris <eugen at sartoris.de> wrote:
> > > > > > ... ich werde noch weiter testen und die Infos dazu schicken.
> > > > > > Vorab schon mal ein kleines TraceFile und das passende Log dazu.
> > > > > kann da leider nichts sinnvolles drin erkennen...
> > > > > (waehre auch vor allem zusammen mit dem dazugehoerigen backtrace hilfreich,
> > > > > um zu sehen was der abgestuerzte thread zuletzt getan hat,
> > > > > ich kann aus dem log nicht sehen, welcher thread den crash verursacht hat.)
> > > > >
> > > > > > Bisher habe ich alles auf Ubuntu 12.04 getestet.
> > > > > > Damit ich ausschließen kann das es etwas mit der OS Version zu tun hat werde
> > > > > > ich
> > > > > > mir noch ein VM mit 10.04 installieren und die Test auch da noch machen...
> > > > >
> > > > > wenn du zeit zum herumprobieren hast, waehre es wohl vor allem sinnvoll zu
> > > > > testen, ob der fehler mit einer anderen konstellation von zaehlern auch
> > > > > auftritt,
> > > > > zB wenn du fuer die vier zaehler vier einzelne vzlogger-instanzen
> > > > > konfigurierst
> > > > > und startest...
> > > > >
> > > > > alles in allem ist es schwer solche fehler zu debuggen, wenn man sie nicht
> > > > > selbst
> > > > > reproduzieren kann...
> > > > >
> > > > > > Gruss
> > > > > > Eugen
> > > > >
> > > > > - Thorben
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://volkszaehler.org/pipermail/volkszaehler-users/attachments/20121022/ee24e785/attachment-0001.html>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: PV-Anlage.png
Type: image/png
Size: 80950 bytes
Desc: not available
URL: <http://volkszaehler.org/pipermail/volkszaehler-users/attachments/20121022/ee24e785/attachment-0001.png>

More information about the volkszaehler-users mailing list