[vz-users] [vz-dev] Auswertung Protocol d0 / vzlogger crash

Thorben Thuermer r00t at constancy.org
Mon Oct 22 16:23:12 CEST 2012


On Mon, 22 Oct 2012 02:04:42 +0200
Thorben Thuermer <r00t at constancy.org> wrote:
> b)
> crash beim return aus meter_read_d0, weil der stack ueberschrieben wurde...
> das ist dann wohl wirklich ein bug im d0-parser.

nach einem blick auf den code eruebrigt sich weiteres suchen.
in meter_read_d0 in protocols /d0.c, im context-abhangige code unter
"switch (context) {" wird zwar im fall VENDOR geprueft, ob die daten in
den puffer passen, aber in den nachfolgenden faellen (IDENTIFICATION,
OBIS_CODE, VALUE, UNIT) nichtmehr.
sobald falsche daten vom zaehler kommen, oder nur der parser mal im
faschen zustand ist oder ein zeichen das ein feld beendet durch einen
uebertragungsfehler verloren geht, wird ueber den puffer hinaus
geschrieben, und es kommt zum crash.

- T.

> (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


More information about the volkszaehler-users mailing list