<!DOCTYPE HTML PUBLIC "-//W3C//DTD HTML 4.01 Transitional//EN" "http://www.w3.org/TR/html4/loose.dtd"><html>
<head>
<meta name="Generator" content="Zarafa WebAccess v7.1.0-36420">
<meta http-equiv="Content-Type" content="text/html; charset=utf-8">
<title>AW: [vz-users] Auswertung Protocol d0 / vzlogger crash</title>
<style type="text/css">
body
{
font-family: Arial, Verdana, Sans-Serif ! important;
font-size: 12px;
padding: 5px 5px 5px 5px;
margin: 0px;
border-style: none;
background-color: #ffffff;
}
p, ul, li
{
margin-top: 0px;
margin-bottom: 0px;
}
</style>
</head>
<body>
<p><br />Noch ein Hinweis zu Punkt a)</p><p> </p><p>Die Timestamps/Werte beim d0 meter zeigen zum Teil sehr seltsame Graphen.</p><p> </p><p>Hier mal ein Beispiel: ( s. Anhang Daten sind in der Testumgebung )</p><p> </p><p>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.</p><p>Das kann aber in der Realität nicht sein, da meine PV-Anlage max 6000W bringt und die Sonne kontinuierlich da war.....</p><p> </p><p>Es sieht so aus als ob bei der Berechnung des Wertes / timestamp ein Timing Problem auftritt, sodass die Verbrauchswerte um einen Mittelwert stark schwanken.</p><p> </p><p>ES.</p><p> </p><p> </p><p> </p><p> </p><blockquote style="border-left: 2px solid #325FBA; padding-left: 5px;margin-left:5px;">-----Ursprüngliche Nachricht-----<br /><strong>Von:</strong> Thorben Thuermer <r00t@constancy.org><br /><strong>Gesendet:</strong> Mo 22.10.2012 02:11<br /><strong>Betreff:</strong> Re: [vz-users] Auswertung Protocol d0 / vzlogger crash<br /><strong>An:</strong> volkszaehler-dev@lists.volkszaehler.org; <br /><strong>CC:</strong> volkszaehler-users@lists.volkszaehler.org; <br /><br />toll was man alles findet, wenn man mal dabei ist...<br />gleich noch ZWEI neue bugs... aber crash erst nach ~16 stunden:<br />(nebenbei verlegen wir das thema mal auf die -dev liste...<br /> oder sind eh alle auf beiden?)<br /><br />a)<br />[Oct 22 00:41:12][ch0] JSON request body: [ [ 1350858306844.057129, 14926.195312 ], [ 1350858306844.476074, 82.000000 ],<br />[Oct 22 00:41:12][ch0] Request failed: [400] PDOException: SQLSTATE[23000]: Integrity constraint violation: 1062 Duplicate entry '2-1350858306844' for key 'ts_uniq'<br /><br />=> vzlogger hat zwei eintraege mit identischem (nach dem runden) timestamp erzeugt,<br /> die die middleware nicht eintragen kann.<br /> ist das ein middleware oder ein vzlogger-bug?<br /><br />b)<br />crash beim return aus meter_read_d0, weil der stack ueberschrieben wurde...<br />das ist dann wohl wirklich ein bug im d0-parser.<br />(ggfs zusammenhang mit dem vollen puffer wegen des middleware-problems?)<br />leider hatte ich da wohl keinen efence an, sonst wuessten wir's genauer.<br />(ich habe die "something unexpected happened" meldung nebenbei mal<br /> etwas verbessert...) (log gekuerzt)<br />[Oct 22 00:41:44][mtr0] unexpected byte while reading vendor: 34 '4'!<br />[Oct 22 00:41:44][mtr0] unexpected byte while reading vendor: 38 '8'!<br />[Oct 22 00:41:44][mtr0] unexpected byte while reading vendor: 5f '_'!<br />[Oct 22 00:41:44][mtr0] unexpected byte while reading vendor: 34 '4'!<br />[Oct 22 00:41:44][mtr0] unexpected byte while reading vendor: 38 '8'!<br />[Oct 22 00:41:44][mtr0] unexpected byte while reading vendor: 5f '_'!<br />[Oct 22 00:41:44][ch0] Buffer dump (size=86 keep=0): {14926.20!,82.00,14926.20,...<br />[Oct 22 00:41:44][ch1] Buffer dump (size=0 keep=0): {}<br />[Oct 22 00:41:44][mtr0] unexpected byte while reading vendor: 34 '4'!<br />[Oct 22 00:41:44][ch0] Buffer dump (size=86 keep=0): {14926.20!,82.00,14926.20,...<br />[Oct 22 00:41:44][ch1] Buffer dump (size=0 keep=0): {}<br />[Oct 22 00:41:44][mtr0] unexpected byte while reading vendor: 30 '0'!<br />*** stack smashing detected ***: /vz/vzlogger.stv0g/src/vzlogger terminated<br />(gdb) bt<br />#4 0x00007ffff6d628d0 in __stack_chk_fail () from /lib/x86_64-linux-gnu/libc.so.6<br />#5 0x0000000000407379 in meter_read_d0 (mtr=0x634350, rds=0x7fffec0008c0, max_readings=32) at protocols/d0.c:282<br />282 }<br />$5 = {id = "mtr0", interval = 1, protocol = meter_protocol_d0, handle = {file = {path = 0x0,<br /> format = 0x6343e0 "/dev/lesekopf0", rewind = 9600, fd = 0x500}, exec = {command = 0x0,<br /> format = 0x6343e0 "/dev/lesekopf0"}, random = {min = 0, max = 3.2141144150814789e-317,<br /> last = 1.6975971070752379e-313}, s0 = {device = 0x0, resolution = 6505440, fd = 0, old_tio = {c_iflag = 9600,<br /> c_oflag = 8, c_cflag = 1280, c_lflag = 0, c_line = 173 '\255',<br /> 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,<br /> fd = 8, oldtio = {c_iflag = 1280, c_oflag = 0, c_cflag = 3501, c_lflag = 2608, c_line = 0 '\000',<br /> c_cc = "\003\034\177\025\004\000\001\000\021\023\032\000\022\017\027\026", '\000' <repeats 15 times>,<br /> c_ispeed = 13, c_ospeed = 13}}, fluksov2 = {fifo = 0x0, fd = 6505440}, sml = {host = 0x0,<br /> device = 0x6343e0 "/dev/lesekopf0", baudrate = 9600, fd = 8, old_tio = {c_iflag = 1280, c_oflag = 0, c_cflag = 3501,<br /> c_lflag = 2608, c_line = 0 '\000',<br /> c_cc = "\003\034\177\025\004\000\001\000\021\023\032\000\022\017\027\026", '\000' <repeats 15 times>,<br /> c_ispeed = 13, c_ospeed = 13}}}}<br /><br />#6 0x0000000000405439 in reading_thread (arg=0x634350) at threads.c:62<br /><br />- T.<br /><br />On Sun, 21 Oct 2012 17:27:26 +0200<br />Thorben Thuermer <r00t@constancy.org> wrote:<br />> Hallo,<br />> <br />> das problem ist dann geklaert:<br />> der resolver in libcurl ist _nicht_ thread-safe.<br />> <br />> d.h., wenn zwei threads gleichzeitig einen namen aufloesen, gibt es eine<br />> race-condition die zu dem crash fuehrt.<br />> <br />> das ist recht eindeutig ein bug in libcurl...<br />> unter: http://curl.haxx.se/libcurl/features.html<br />> wird angegeben, libcurl sei dann thread-safe, wenn die gethostbyname()<br />> funktion des betriebssystems thead-safe ist,<br />> aber das problem liegt nicht in gethostbyname(), sondern in der benutzung<br />> von alarm() um einen timeout fuer gethostbyname() zu erzwingen.<br />> (related: https://bugzilla.redhat.com/show_bug.cgi?id=539809 ) <br />> <br />> in Eugen's konfiguration tritt das problem vor allem deshalb auf,<br />> weil aus einem meter zwei channels erzeugt werden,<br />> d.h. jedesmal wenn vom meter daten kommen, werden gleichzeitig zwei<br />> middleware-aufrufe gestartet, um die daten der beiden channels zu<br />> uebermitteln, was dann irgendwann das richtige timing fuer die race-condition<br />> liefert und zum crash fuehrt.<br />> <br />> der crash tritt seltener auf, wenn man statt "localhost" direkt "127.0.0.1"<br />> fuer den middleware-server angibt, vermutlich weil die aufloesung dann<br />> schneller geht.<br />> (ein externer dns-server ist in beiden faellen nicht involviert,<br />> da der name im hostsfile steht.)<br />> <br />> als fix waehre entweder der bug in libcurl zu beheben...<br />> oder libcurl mit unterstuetzung fuer einen alternativen resolver zu kompilieren:<br />> http://curl.haxx.se/dev/readme-ares.html<br />> <br />> ansonsten kann man als workaround libcurl ohne HAVE_ALARM kompilieren<br />> (nach dem ./configure den HAVE_ALARM eintrag in lib/curl_config.h<br />> entfernen oder auskommentieren (nicht 1 durch 0 ersetzen!).<br />> (das hat den nachteil, dass das programm u.U. bei der aufloesung<br />> haengenbleibt, falls der timeout-mechanismus des betriebssystems<br />> nicht greift.)<br />> <br />> (Eugen: letzteres ist momentan bei dir in /vz/libcurl-7.28.0-prefix bzw<br />> /vz/curl-7.28.0 implementiert, vzlogger laeuft jetzt seit ueber<br />> zehn stunden durch.)<br />> <br />> - T.<br />> <br />> On Sat, 20 Oct 2012 22:41:27 +0200 Thorben Thuermer <r00t@constancy.org> wrote:<br />> > On Sat, 20 Oct 2012 17:32:26 +0200<br />> > Thorben Thuermer <r00t@constancy.org> wrote:<br />> > > Hallo Eugen und andere,<br />> > > <br />> > > Eugen hat mir inzwischen einen testzugang gegeben, und ich versuche das<br />> > > weiter zu debuggen.<br />> > > <br />> > > meine momentane vermutung ist, dass der bug nicht direkt in vzlogger ist,<br />> > > sondern es ein problem mit libcurl (in verbindung mit einer mit fortify<br />> > > kompilierten libc?) gibt.<br />> > > (der crash passiert scheinbar immer aus libcurl heraus.)<br />> > > https://wiki.ubuntu.com/Security/Features#Built_with_Fortify_Source<br />> > > https://wiki.ubuntu.com/ToolChain/CompilerFlags#A-D_FORTIFY_SOURCE.3D2<br />> > > ein derartiges problem gab es wohl zB. hier schonmal:<br />> > > https://bugzilla.redhat.com/show_bug.cgi?id=539809<br />> > <br />> > libcurl mit debug kompiliert, man lese und staune...<br />> > der crash passiert wohl reproduzierbar an der gleichen stelle in libcurl...<br />> > hat also tatsaechlich was mit libcurl und dns zu tun,<br />> > und wenn es an dns-timeouts liegt,<br />> > wuerde das das zufaellige timing der crashes erklaeren.<br />> > <br />> > [Oct 20 18:34:05][ch1] CURL: Connection #0 to host localhost left intact<br />> > [Oct 20 18:34:05][ch1] Request succeeded: 200<br />> > <br />> > Program received signal SIGSEGV, Segmentation fault.<br />> > 0x00007ffff6e52118 in addbyter (output=110, data=0x7ffff01b2580) at mprintf.c:1013<br />> > 1013 infop->buffer[0] = outc; /* store */<br />> > (gdb) bt full<br />> > #0 0x00007ffff6e52118 in addbyter (output=110, data=0x7ffff01b2580) at mprintf.c:1013<br />> > infop = 0x7ffff01b2580<br />> > outc = 110 'n'<br />> > #1 0x00007ffff6e50e4c in dprintf_formatf (data=0x7ffff01b2580, stream=0x7ffff6e520df <addbyter>,<br />> > format=0x7ffff6e808f3 "name lookup timed out", ap_save=0x7ffff01b25d0) at mprintf.c:671<br />> > [...]<br />> > f = 0x7ffff6e808f3 "name lookup timed out"<br />> > [...]<br />> > #2 0x00007ffff6e52198 in curl_mvsnprintf (<br />> > buffer=0x404a30 "\377M\211l$\020A\211D$\b1\300ë¸ hostip.c:611<br />> > keep_sigact = {__sigaction_handler = {sa_handler = 0x7ffff01b27e0, sa_sigaction = 0x7ffff01b27e0}, sa_mask = {<br />> > <br />> > <br />> > > - Thorben<br />> > - T.<br />> > <br />> > > On Fri, 21 Sep 2012 15:54:30 +0200 (CEST)<br />> > > Eugen Sartoris <eugen@sartoris.de> wrote:<br />> > > > Hallo Thorben,<br />> > > > <br />> > > > danke für die Hinweise.<br />> > > > Ich werde eine neue Testumgebung aufbauen unter ubuntu 10.04 und dann auch mit<br />> > > > einem Deamon je Lesekopf ( insges. 3 )<br />> > > > Wenn die Fehler isoliert sind melde ich mich wieder. Je nach Konfig der<br />> > > > Testumgebung kann ich die einen Zugang einrichtern, sofern das für dich in Frage<br />> > > > kommt.<br />> > > > <br />> > > > gruss<br />> > > > <br />> > > > eugen<br />> > > > <br />> > > > <br />> > > > Thorben Thuermer <r00t@constancy.org> hat am 19. September 2012 um 22:45<br />> > > > geschrieben:<br />> > > > > On Wed, 19 Sep 2012 22:13:49 +0200 (CEST)<br />> > > > > Eugen Sartoris <eugen@sartoris.de> wrote:<br />> > > > > > ... ich werde noch weiter testen und die Infos dazu schicken.<br />> > > > > > Vorab schon mal ein kleines TraceFile und das passende Log dazu.<br />> > > > > kann da leider nichts sinnvolles drin erkennen...<br />> > > > > (waehre auch vor allem zusammen mit dem dazugehoerigen backtrace hilfreich,<br />> > > > > um zu sehen was der abgestuerzte thread zuletzt getan hat,<br />> > > > > ich kann aus dem log nicht sehen, welcher thread den crash verursacht hat.)<br />> > > > ><br />> > > > > > Bisher habe ich alles auf Ubuntu 12.04 getestet.<br />> > > > > > Damit ich ausschließen kann das es etwas mit der OS Version zu tun hat werde<br />> > > > > > ich<br />> > > > > > mir noch ein VM mit 10.04 installieren und die Test auch da noch machen...<br />> > > > ><br />> > > > > wenn du zeit zum herumprobieren hast, waehre es wohl vor allem sinnvoll zu<br />> > > > > testen, ob der fehler mit einer anderen konstellation von zaehlern auch<br />> > > > > auftritt,<br />> > > > > zB wenn du fuer die vier zaehler vier einzelne vzlogger-instanzen<br />> > > > > konfigurierst<br />> > > > > und startest...<br />> > > > ><br />> > > > > alles in allem ist es schwer solche fehler zu debuggen, wenn man sie nicht<br />> > > > > selbst<br />> > > > > reproduzieren kann...<br />> > > > ><br />> > > > > > Gruss<br />> > > > > > Eugen<br />> > > > ><br />> > > > > - Thorben<br /></blockquote>
</body>
</html>