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 <r...@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 <r...@constancy.org> > wrote: > > On Sat, 20 Oct 2012 17:32:26 +0200 > > Thorben Thuermer <r...@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 <eu...@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 <r...@constancy.org> hat am 19. September 2012 um 22:45 > > > > geschrieben: > > > > > On Wed, 19 Sep 2012 22:13:49 +0200 (CEST) > > > > > Eugen Sartoris <eu...@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