IPConnection loopt im Disconnect, C Bindings 2.0.7

[remotecontrol]

Hallo,

 

ich habe ein Problem im Disconnect, wenn der Enumerate bzw. die Netzwerkverbindung "langsam" ist: das Aufräumen klappt dann nicht, der Prozess loopt im pthread_join und lässt sich nur noch durch "kill -9" beenden:

 

0x00007f36bda2d1cf in pthread_join () from /lib64/libpthread.so.0
(gdb) where
#0  0x00007f36bda2d1cf in pthread_join () from /lib64/libpthread.so.0
#1  0x000000000042d469 in ipcon_disconnect_unlocked (ipcon=0x7fff85466888) at ip_connection.c:1509
#2  0x000000000042ead2 in ipcon_disconnect (ipcon=0x7fff85466888) at ip_connection.c:1656
#3  0x000000000042eb05 in ipcon_destroy (ipcon=0x7fff85466888) at ip_connection.c:1585
#4  0x000000000041ea6b in brickapi::BrickConnector::~BrickConnector (this=0x7fff85466880, __in_chrg=<optimized out>)
    at BrickConnector.cpp:68
...

 

Wenn ich mich remote gegen einen auf dem PI laufenden Brickd connecte kommt das relativ oft vor. Die WLAN-Verbindung zum PI reagiert aber teilweise sehr träge. Beim Beenden loopt es dann (Multi-Core CPU) bzw. der Enumerate bringt nicht alle Devices, was zum Beenden führt und dann auch loopt.

 

Noch habe ich keine Idee woran das liegen kann. Scheint mit den Bindungs 2.0.6 auch zu passieren.

 

Läuft das Programm direkt auf dem PI, so beendet es sich normal (Single-Core CPU). In beiden Fällen g++ 4.6.2 mit Linux.

[photron]

pthread_join() blockt weil es darauf wartet, dass sich der Receive Thread beendet, was aber nicht zu passieren scheint. Ich denke, dass der in recv() steht und der shutdown() Aufruf den recv() Aufruf nicht abgebrochen hat.

 

Kannst du das Problem einfach reproduzieren? Mich interessiert ein gdb Backtrace für alle Threads:

 

thread apply all backtrace full

 

Um zu sehen wo der Receive Thread wirklich steht.

[remotecontrol]

das sieht dann so aus:

Thread 3 (Thread 0x7f280a80e700 (LWP 15655)):
#0  0x00007f280b730010 in sem_wait () from /lib64/libpthread.so.0
No symbol table info available.
#1  0x000000000042dc75 in semaphore_acquire (semaphore=<optimized out>) at ip_connection.c:479
No locals.
#2  queue_get (length=<synthetic pointer>, data=<synthetic pointer>, kind=<synthetic pointer>, queue=0x647aa8) at ip_connection.c:731
        item = <optimized out>
#3  ipcon_callback_loop (opaque=0x647aa0) at ip_connection.c:1125
        callback = 0x647aa0
        kind = <optimized out>
        data = <optimized out>
        length = <optimized out>
#4  0x000000000042d24e in thread_wrapper (opaque=<optimized out>) at ip_connection.c:534
        thread = <optimized out>
#5  0x00007f280b729f05 in start_thread () from /lib64/libpthread.so.0
Thread 2 (Thread 0x7f280980c700 (LWP 15658)):
#0  table_get (table=0x7fff7f872fa0, key=0) at ip_connection.c:639
No locals.
#1  0x000000000042e07e in ipcon_handle_response (response=0x7f280980bb50, ipcon=0x7fff7f872f58) at ip_connection.c:1233
        device = <optimized out>
        sequence_number = 0 '\000'
#2  ipcon_receive_loop (opaque=0x7fff7f872f58) at ip_connection.c:1309
        ipcon = 0x7fff7f872f58
        socket_id = 1
        pending_data = {{header = {uid = 0, length = 0 '\000', function_id = 0 '\000', sequence_number_and_options = 0 '\000', 
              error_code_and_future_use = 0 '\000'}, 
            payload = '\000' <repeats 26 times>, "0\237\000\000\"\375\b\000d7C\000\000\000\000\000\066\062DrY6\000\000c\001\000\000\002\000\001\335\000\000\000\000\000", optional_data = "\000\000\000\000\000\000\000"}, {header = {uid = 0, length = 0 '\000', 
              function_id = 0 '\000', sequence_number_and_options = 0 '\000', error_code_and_future_use = 0 '\000'}, 
            payload = '\000' <repeats 63 times>, optional_data = "\000\000\000\000\000\000\000"}, {header = {uid = 0, length = 0 '\000', 
              function_id = 0 '\000', sequence_number_and_options = 0 '\000', error_code_and_future_use = 0 '\000'}, 
            payload = '\000' <repeats 63 times>, optional_data = "\000\000\000\000\000\000\000"}, {header = {uid = 0, length = 0 '\000', 
              function_id = 0 '\000', sequence_number_and_options = 0 '\000', error_code_and_future_use = 0 '\000'}, 
            payload = '\000' <repeats 63 times>, optional_data = "\000\000\000\000\000\000\000"}, {header = {uid = 0, length = 0 '\000', 
              function_id = 0 '\000', sequence_number_and_options = 0 '\000', error_code_and_future_use = 0 '\000'}, 
            payload = '\000' <repeats 63 times>, optional_data = "\000\000\000\000\000\000\000"}, {header = {uid = 0, length = 0 '\000', 
              function_id = 0 '\000', sequence_number_and_options = 0 '\000', error_code_and_future_use = 0 '\000'}, 
            payload = '\000' <repeats 63 times>, optional_data = "\000\000\000\000\000\000\000"}, {header = {uid = 0, length = 0 '\000', 
              function_id = 0 '\000', sequence_number_and_options = 0 '\000', error_code_and_future_use = 0 '\000'}, 
            payload = '\000' <repeats 63 times>, optional_data = "\000\000\000\000\000\000\000"}, {header = {uid = 0, length = 0 '\000', 
              function_id = 0 '\000', sequence_number_and_options = 0 '\000', error_code_and_future_use = 0 '\000'}, 
            payload = '\000' <repeats 63 times>, optional_data = "\000\000\000\000\000\000\000"}, {header = {uid = 0, length = 0 '\000', 
              function_id = 0 '\000', sequence_number_and_options = 0 '\000', error_code_and_future_use = 0 '\000'}, 
            payload = '\000' <repeats 63 times>, optional_data = "\000\000\000\000\000\000\000"}, {header = {uid = 0, length = 0 '\000', 
              function_id = 0 '\000', sequence_number_and_options = 0 '\000', error_code_and_future_use = 0 '\000'}, 
            payload = '\000' <repeats 63 times>, optional_data = "\000\000\000\000\000\000\000"}}
        pending_length = 34
        length = 0
#3  0x000000000042d24e in thread_wrapper (opaque=<optimized out>) at ip_connection.c:534
        thread = <optimized out>
#4  0x00007f280b729f05 in start_thread () from /lib64/libpthread.so.0

Thread 1 (Thread 0x7f280be11720 (LWP 15654)):
#0  0x00007f280b72b1cf in pthread_join () from /lib64/libpthread.so.0
No symbol table info available.
#1  0x000000000042d479 in ipcon_disconnect_unlocked (ipcon=0x7fff7f872f58) at ip_connection.c:1509
No locals.
#2  0x000000000042eae2 in ipcon_disconnect (ipcon=0x7fff7f872f58) at ip_connection.c:1656
        callback = <optimized out>
        meta = {function_id = 232 '\350', parameter = 64 '@', socket_id = 140735332953808}
#3  0x000000000042eb15 in ipcon_destroy (ipcon=0x7fff7f872f58) at ip_connection.c:1585
No locals.
#4  0x000000000041eaab in brickapi::BrickConnector::~BrickConnector (this=0x7fff7f872f50, __in_chrg=<optimized out>)
    at BrickConnector.cpp:68
No locals.
#5  0x000000000040ce6d in showStatus (host=0x7fff7f876112 "pi", props=0x430441 "application.properties", logName=0x430226 "weather.csv", 
    noWelcome=true) at main.cpp:103
        connector = {_vptr.BrickConnector = 0x4320f0, ipcon = {host = 0x6471c0 "pi", port = 4223, timeout = 2500, auto_reconnect = true, 
            auto_reconnect_allowed = false, auto_reconnect_pending = false, sequence_number_mutex = {handle = {__data = {__lock = 0, 
                  __count = 0, __owner = 0, __nusers = 0, __kind = 0, __spins = 0, __list = {__prev = 0x0, __next = 0x0}}, 
                __size = '\000' <repeats 39 times>, __align = 0}}, next_sequence_number = 13, devices = {mutex = {handle = {__data = {
                    __lock = 0, __count = 0, __owner = 0, __nusers = 0, __kind = 0, __spins = 0, __list = {__prev = 0x0, __next = 0x0}}, 
                  __size = '\000' <repeats 39 times>, __align = 0}}, used = 5, allocated = 16, keys = 0x6470e0, values = 0x647130}, 
            registered_callbacks = {0x0 <repeats 253 times>, 0x41edec, 0x0, 0x0}, registered_callback_user_data = {
              0x0 <repeats 253 times>, 0x7fff7f872f50, 0x0, 0x0}, socket_mutex = {handle = {__data = {__lock = 1, __count = 0, 
                  __owner = 15654, __nusers = 1, __kind = 0, __spins = 0, __list = {__prev = 0x0, __next = 0x0}}, 
                __size = "\001\000\000\000\000\000\000\000&=\000\000\001", '\000' <repeats 26 times>, __align = 1}}, socket = 0x6471e0, 
            socket_id = 1, receive_flag = false, receive_thread = {handle = 139809934853888, 
              function = 0x42df00 <ipcon_receive_loop(void*)>, opaque = 0x7fff7f872f58}, callback = 0x647aa0, 
            disconnect_probe_flag = false, disconnect_probe_thread = {handle = 139809943246592, 
              function = 0x42ede0 <ipcon_disconnect_probe_loop(void*)>, opaque = 0x7fff7f872f58}, disconnect_probe_event = {condition = {
                __data = {__lock = 0, __futex = 10, __total_seq = 5, __wakeup_seq = 5, __woken_seq = 5, __mutex = 0x7fff7f874090, 
                  __nwaiters = 0, __broadcast_seq = 0}, 
                __size = "\000\000\000\000\n\000\000\000\005\000\000\000\000\000\000\000\005\000\000\000\000\000\000\000\005\000\000\000\000\000\000\000\220@\207\177\377\177\000\000\000\000\000\000\000\000\000", __align = 42949672960}, mutex = {__data = {__lock = 0, 
                  __count = 0, __owner = 0, __nusers = 0, __kind = 0, __spins = 0, __list = {__prev = 0x0, __next = 0x0}}, 
                __size = '\000' <repeats 39 times>, __align = 0}, flag = true}, wait = {object = {
                __size = "\000\000\000\000\200", '\000' <repeats 19 times>, "0h\341\v(\177\000", __align = 549755813888}, 
              pointer = 0x7fff7f8740c0}}, devices = {<std::_List_base<brickapi::DeviceItem*, std::allocator<brickapi::DeviceItem*> >> = {
              _M_impl = {<std::allocator<std::_List_node<brickapi::DeviceItem*> >> = {<__gnu_cxx::new_allocator<std::_List_node<brickapi::DeviceItem*> >> = {<No data fields>}, <No data fields>}, _M_node = {_M_next = 0x7f27fc002690, 
                  _M_prev = 0x7f27fc00be10}}}, <No data fields>}, master = 0x7f27fc0025f0, motorMaster = 0x0, servo = 0x0, lcd = 
    0x7f27fc006310, dualRelay = 0x0, quadRelay = 0x0, distanceIR = 0x0, ambiLight = 0x7f27fc006220}
        master = 0x7f27fc0025f0
        lcd = 0x7f27fc006310
        log = 0x647860
        rc = 4
#6  0x000000000040d345 in main (argc=5, argv=0x7fff7f874668) at main.cpp:233
        host = 0x7fff7f876112 "pi"
        pidFile = 0x0
        noWelcome = true
        props = 0x430441 "application.properties"
...

Ich werde mir nochmal die C-Bindings 2.0.5 runterladen, die ich bis dato im Einsatz hatte. Damit ging es auch remote ohne Probleme.

 

Auf dem PI direkt läuft aus auch mit 2.0.7 ohne Probleme.

[remotecontrol]

Mein Vermutung ist, dass es an den Bindungs 2.0.7 liegt:

wenn ich die 2.0.5 nutze sieht es gut aus (bekomme das Problem zumindest nicht reproduziert und hatte bisher ja auch keine Probleme damit). Bei 2.0.7 bekomme ich die Probleme. Ich hab' gerade 2x hin und her gewechselt ...

 

Auf dem PI habe ich auch noch die 2.0.5, vielleicht lief es deswegen ohne Probleme.

 

Host-CPU ist ein Quad-Core.

[photron]

Das ist komisch. Ich habe mir gerade die Änderungen zwischen 2.0.5 und 2.0.7 angesehen und da ist nichts dabei was diese Verhalten auf Anhieb erklärt.

 

Okay zum Backtrace: der Receive Thread (Thread 2 in gdb) scheint im table_get() zu stehen. Das ist komisch. Auch das der table_get() Aufruf für UID 0ist, ist komisch, da UID keine gültige UID für ein Brick oder Bricklet ist. Weiterhin ist im ipcon_receive_loop() Aufruf pending_length = 34, der erste Header in pending_data ist aber voller Nullen. Will sagen, da ist was sehr faul.

 

Da der Header voller Nullen ist ist length in Zeile 1302 auch 0 und damit bleibt pending_data auf 34 und die while (true) Schleife in Zeile 1296 bricht nicht ab und der Thread endet nicht. Der Receive Thread steht also nicht in table_get(), sondern du hast den Thread nur gerade zufällig da angehalten.

 

Das Problem ist also, dass im pending_data Buffer falsche Daten stehen (lauter Nullen). Die Frage ist jetzt wie die dahin gekommen sind: Hat brickd die wirklich geschickt? Du könntest mit Version 2.0.7 nach dem socket_receive in Zeile 1272 einmal die Werte von length, pending_length und den Inhalt von pending_data per printf oder Ähnlichem ausgeben, um zu sehen ob da die Nullen wegkommen.

 

Als Änderung für die IP Connection werde ich erstmal die while (true) Schleife in Zeile 196 durch eine while (ipcon->receive_flag) Schleife ändern, dann sollte das pthread_join() nicht mehr vergeblich warten.

 

Das eigentliche Problem, dass im pending_data Buffer bei dir 34 Nullen stehen ist damit allerdings nicht behoben oder erklärt.

 

[remotecontrol]

OK, ich werde auch die Optimierung mal abschalten, dann sieht man ggf. einige Werte besser. Da komme ich die nächsten Tage aber nicht zu.

 

Das Programm läuft eigentlich schon seit einigen Monaten stabil.

Ich habe jetzt durch den Umbau in ein neues Gehäuse mal die Firmware aktualisiert und dabei auch die Bindings.

 

Vorhin hat es 1-2x auch mit Bindings 2.0.7 funktioniert, d. h. irgendwie kommt mehr oder weniger oft im Startup was durcheinander, je nach Initialisierungsreihenfolge der Threads. Wenn die Initialisierung OK ist, dann läuft es danach auch sauber weiter.

[remotecontrol]

Optimierung ist nun in allen Teilen aus. Ein paar Traces habe ich eingebaut, das sieht dann so aus:

 

ipcon_callback_loop: ipcon_dispatch_meta
Wait before socket_receive
ipcon_receive_loop: got 34 bytes
ipcon_receive_loop: got 34 bytes
ipcon_handle_response(func = 253)
Wait before socket_receive
ipcon_callback_loop: ipcon_dispatch_packet(dc351631,34,253,
ipcon_receive_loop: got 102 bytes
ipcon_receive_loop: got 34 bytes
ipcon_handle_response(func = 253)
ipcon_receive_loop: got 0 bytes
ipcon_handle_response(func = 0)
ipcon_handle_response: ignoring response for an unknown device
ipcon_receive_loop: got 0 bytes
ipcon_handle_response(func = 0)
ipcon_handle_response: ignoring response for an unknown device
ipcon_receive_loop: got 0 bytes
ipcon_handle_response(func = 0)
ipcon_handle_response: ignoring response for an unknown device
ipcon_receive_loop: got 0 bytes
ipcon_handle_response(func = 0)
ipcon_handle_response: ignoring response for an unknown device
ipcon_receive_loop: got 0 bytes
ipcon_handle_response(func = 0)
ipcon_handle_response: ignoring response for an unknown device
ipcon_receive_loop: got 0 bytes
ipcon_handle_response(func = 0)
..

 

binnen von 2 Sekunden wird 1 Gigabyte and log-Daten geschrieben wird: es loopt in der receive-loop, es kommen immer 0 Bytes zurück, die pending_data sind 0-initialisiert, pending_length steht aber auf 214.

 

Die ersten Pakete a 34 Bytes sind mal mehr mal weniger, aber meist loopt es nach 2-5 Paketen.

[remotecontrol]

Ich glaub' ich hab den Fehler  : in ipcon_receive_loop:

ipcon_handle_response(ipcon, pending_data);

memmove(pending_data, pending_data + length, pending_length - length);
pending_length -= length;

 

Muss der memmove so aussehen:

memmove(pending_data, ((uint8_t *)pending_data) + length, pending_length - length);

 

da pending_data grob gesagt ein Array von structs ist und "pending_data + length" das x.-te Element aus einem Array ist und nicht ein Byte Offset um "length" Bytes.

 

Der Fehler ist immer genau dann passiert, wenn mehr als 1 Paket vom recv() gelesen wurde und der memmove tatsächlich was verschoben hat.

[photron]

Richtig, das ist exakt das Problem. Danke für's Debuggen und sorry, dass mir das nicht aufgefallen ist.

 

In C/C++ 2.0.8 Bindings ist das jetzt korrigiert.