sancane
commented
6 years ago Trace was completely screwed up. Attaching it as a file instead trace.txt
Open sancane opened 6 years ago
sancane
commented
6 years ago Trace was completely screwed up. Attaching it as a file instead trace.txt
tuexen
commented
6 years ago If the lower layer breaks aways, I would call usrsctp_close() after setting the linger option to trigger an non-graceful shutdown. Would that be a better fit for your situation?
Regarding your above description, I'm not sure I understand which two threads deadlock each other and on which mutex this should happen.
sancane
commented
6 years ago Hi, I forgot to mention that linger option is already set. More details about enabled options here: https://github.com/EricssonResearch/openwebrtc-gst-plugins/blob/master/ext/sctp/sctpassociation.c#L515 The problem is that when I try to tear down the association, I got a thread locked trying to send something in the function usrsctp_conninput , stack trace about Thread 5 has more details, it seems it gets locked trying to acquire a mutex no notify a change state:
sctp_notify_assoc_change (state=1, stcb=0x7ff2f80009d0, error=0, abort=0x0, from_peer=0 '\000', so_locked=0) at netinet/sctputil.c:2900
It's weird, because only it gets locked when I see the SCTP debug trace: 'Timer type 16 goes off' I do not know if it might have any kind of relation regarding the lock, but whenever it does not get stalled, just the tnext race is displayed: 'Timer type 17 goes off Timer now complete (type = 17) '
If after that, the timer type 16 (SCTP_TIMER_TYPE_ASOCKILL)) comes to play, the thread that is locked in the function usrsctp_conninput never get unocked. Not sure at all, but It seems that something with the timer type 16 goes wrong.
Tell me if I can provide more info about this stuff to help to diagnose this stuff
tuexen
commented
6 years ago I don't see in Thread 5 that you want to send something. It is the input path ending up in an SCTP_COMM_UP notification, which looks OK. The question is, who else is holding the lock Thread 5 is waiting for. Can you provide that information? If not, which line is netinet/sctputil.c:2900 in your code?
sancane
commented
6 years ago I'm using master branch but I added some debug traces to try to figure out by myself what it is happening in there. The line netinet/sctputil.c:2900 matches with this one in your repo: https://github.com/sctplab/usrsctp/blob/master/usrsctplib/netinet/sctputil.c#L2903
Some other times the test is aborted because of the next trace: ../nptl/pthread_mutex_lock.c:81: pthread_mutex_lock: Assertion `mutex->data.__owner == 0' failed. Unfortunately, no stack trace is dumped when this happen.
Googling a bit, it seems that it might be because any thread is trying to lock a mutex that has already been disposed, what makes me think that it could be a race condition when the connection is being set up and from other thread is closed. In other executions, the program gets stalled when an sctp association is closed just when it is managing the cookie_ack, here is the stack trace in this case:
Thread 8 (Thread 0x7fb6a57fb700 (LWP 10387)):
Thread 7 (Thread 0x7fb6a7fff700 (LWP 10383)):
Thread 6 (Thread 0x7fb6b4a7f700 (LWP 10382)):
Thread 5 (Thread 0x7fb6b5280700 (LWP 10381)):
Thread 4 (Thread 0x7fb6b5a81700 (LWP 10380)):
Here, the line user_socket.c:389 matches this one: https://github.com/sctplab/usrsctp/blob/master/usrsctplib/user_socket.c#L387, just calling the pthread_cond_broadcast function.
Interesting the Thread 7 locked in sctputil.c:1706 iterating over timers, in you code: https://github.com/sctplab/usrsctp/blob/master/usrsctplib/netinet/sctputil.c#L1708 and the Thread 4 that is waiting in a condition variable sctp_bsd_addr.c:149, in your code https://github.com/sctplab/usrsctp/blob/master/usrsctplib/netinet/sctp_bsd_addr.c#L151.
The test basically connects two sctp sockets, and as soon as I get the ready event from one of them, I tear down the transport (only UDP in this case in order no to mess up with DTLS stuff) and call to usrsctp_close in both sockets. the close operation is usually done from the application thread, (not the same that fired the SCTP_COMM_UP event), I guess this is not relevant but it could make worse the race condition between the opening and closing operations.
sancane
commented
6 years ago Hi @tuexen, Have a look at this trace, I set my logger to point at your master branch lines. I think there is a race condition when a close operation is done when a notification is taking place. If you see at the end of the trace, after closing the socket 0xd7f300, the socket is releasedm and afterwards, the thread that was calling sctp_ulp_notify tries to lock here SOCKBUF_LOCK(&(so)->so_snd) breaks because that socket was released. I think that is why sometimes the programs breaks down and other it gets stick calling here https://github.com/sctplab/usrsctp/blob/master/usrsctplib/netinet/sctputil.c#L2903.
I think that socket should not be released as long as there is a thread using it, perhaps something in the refcount is not working as expected?, I tried to fix it by myself but it is not that easy, I'm afraid that I'm not very familiarizated with this code.
sancane
commented
6 years ago I realized that there is a race condition when a socket is being set up, cookies and notifications are being managed and a close operation takes place. Have a look at my workaround, it does not solves the problem at all, but minimizes it. If you see it, there are some points where mutexes are manipulated once the socket is destroyed. I only checked for those flags, but I think that I do not know this code well enough as to fix this issue problem properly. I'm just sending it to you to raise awareness about this stuff. 0001-Work-around-avoiding-wakeups.txt
sancane
commented
6 years ago @tuexen I think that the problem is that when the usrsctp_close operation is called, it calls to sorele that frees the socket eventhough there are references to it in other structs. This is why somethimes i got segmentation faults or deadlocks when some thread is manipulating the socket's mutexes when they are about or were already disposed.
tuexen
commented
6 years ago I'll look into this. Just right now being busy with other things (like the day job)...
Hi I came across a problem when it comes to tear down an sctp connection when the underlaying transport is closed abruptly. In this use case, there is no place to gracefully shutdown the sctp association given that the transport is already over, so I explicitly call usrsctp_close function instead, when I do it, I sometimes see that there is a thread blocked in usrsctp_conninput function. This is not an easily reproducible issue, the only way I managed to get this deadlock is running a script that continuously launches a program that opens two sctpassociations and as soon as one of them gets the SCTP_COMM_UP I tear down the transport and call to usrctp_close on the sockets. Here is a backtrace:
Thread 5 (Thread 0x7ff315ffb700 (LWP 20605))
0 __lll_lock_wait () at ../sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:135
1 0x00007ff32a429dbd in __GI___pthread_mutex_lock (mutex=0x1786138) at ../nptl/pthread_mutex_lock.c:80
2 0x00007ff31eddaa7e in sctp_notify_assoc_change (state=1, stcb=0x7ff2f80009d0, error=0, abort=0x0, from_peer=0 '\000', so_locked=0) at netinet/sctputil.c:2900
3 0x00007ff31eddd078 in sctp_ulp_notify (notification=1, stcb=0x7ff2f80009d0, error=0, data=0x0, so_locked=0) at netinet/sctputil.c:3789
4 0x00007ff31ed78a4c in sctp_handle_cookie_ack (cp=0x7ff2f001635c, stcb=0x7ff2f80009d0, net=0x7ff2f8001320) at netinet/sctp_input.c:3174
5 0x00007ff31ed7f281 in sctp_process_control (m=0x7ff2f0016300, iphlen=0, offset=0x7ff315ffa760, length=16, src=0x7ff315ffa8f0, dst=0x7ff315ffa900, sh=0x7ff2f0016350, ch=0x7ff2f001635c, inp=0x17862a0, stcb=0x7ff2f80009d0, netp=0x7ff315ffa7a8, fwd_tsn_seen=0x7ff315ffa77c, vrf_id=0, port=0) at netinet/sctp_input.c:5456
6 0x00007ff31ed806f9 in sctp_common_input_processing (mm=0x7ff315ffa8d8, iphlen=0, offset=12, length=16, src=0x7ff315ffa8f0, dst=0x7ff315ffa900, sh=0x7ff2f0016350, ch=0x7ff2f001635c, compute_crc=1 '\001', ecn_bits=0 '\000', vrf_id=0, port=0) at netinet/sctp_input.c:5892
7 0x00007ff31ed4c23c in usrsctp_conninput (addr=0x7ff3080025c0, buffer=0x17614e0, length=16, ecn_bits=0 '\000') at user_socket.c:3493
8 0x00007ff31f0011ee in my_sctp_association_incoming_packet ()
Thread 4 (Thread 0x7ff31cd2e700 (LWP 20601)):
0 __lll_lock_wait () at ../sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:135
1 0x00007ff32a429dbd in __GI___pthread_mutex_lock (mutex=0x7ff2f8001258) at ../nptl/pthread_mutex_lock.c:80
2 0x00007ff31edd846b in sctp_timeout_handler (t=0x7ff2f8000b68) at netinet/sctputil.c:1706
3 0x00007ff31ed597d8 in sctp_handle_tick (delta=10) at netinet/sctp_callout.c:164
4 0x00007ff31ed598f9 in user_sctp_timer_iterate (arg=0x0) at netinet/sctp_callout.c:204
5 0x00007ff32a4276ba in start_thread (arg=0x7ff31cd2e700) at pthread_create.c:333
6 0x00007ff32b05d3dd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109
Thread 3 (Thread 0x7ff31d52f700 (LWP 20600)):
0 0x00007ff32b05e34d in recvmsg () at ../sysdeps/unix/syscall-template.S:84
1 0x00007ff31ed44f22 in recv_function_udp6 (arg=0x0) at user_recv_thread.c:932
2 0x00007ff32a4276ba in start_thread (arg=0x7ff31d52f700) at pthread_create.c:333
3 0x00007ff32b05d3dd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109
Thread 2 (Thread 0x7ff31dd30700 (LWP 20599)):
0 0x00007ff32b05e34d in recvmsg () at ../sysdeps/unix/syscall-template.S:84
1 0x00007ff31ed44894 in recv_function_udp (arg=0x0) at user_recv_thread.c:722
2 0x00007ff32a4276ba in start_thread (arg=0x7ff31dd30700) at pthread_create.c:333
3 0x00007ff32b05d3dd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109
Thread 1 (Thread 0x7ff31e531700 (LWP 20598)):
0 pthread_cond_wait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
1 0x00007ff31ed58ffa in sctp_iterator_thread (v=0x0) at netinet/sctp_bsd_addr.c:149
2 0x00007ff32a4276ba in start_thread (arg=0x7ff31e531700) at pthread_create.c:333
3 0x00007ff32b05d3dd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109
Whe this happens, If I wait for the sending thread 5 to finish, It will block forever and the program will never finish.
This is a trace I got enabling sctp_debug, perhaps it is not very descriptive by itself but perhaps it helps to diagnose the problem:
0:00:00.046542524 20594 0x174d300 WARN sctpenc gstsctpenc.c:241:gst_sctp_enc_src_activate_mode:<assoc_1:src> pad 0x1761000 activate_mode: active 1, ret 0 vrf_id 0x0: adding address: AF_CONN address: 0x177b330 ** INFO: SCTP association state change! 0x177b330 SCTP: add HMAC id 1 to list SCTP: added chunk 193 (0xc1) to Auth list SCTP: added chunk 128 (0x80) to Auth list ** INFO: SCTP association state change! 0x177b330 0:00:00.047361487 20594 0x174d300 WARN sctpdec gstsctpdec.c:227:sink_pad_activate_func:<assoc_1> activate_mode: active 1, ret 1 Bind called port: 9999 Addr: AF_CONN address: 0x177b330 Main hash to bind at head:0x177fbd8, bound port:9999 - in tcp_pool=0 Allocate an association for peer:AF_CONN address: 0x177b330 Port:9999 0:00:00.047584303 20594 0x174d300 WARN sctpenc gstsctpenc.c:241:gst_sctp_enc_src_activate_mode:<sctpenc_0:src> pad 0x1760700 activate_mode: active 1, ret 0 vrf_id 0x0: adding address: AF_CONN address: 0x7ff3080025c0 0:00:00.047735168 20594 0x174d300 WARN sctpenc gstsctpenc.c:257:gst_sctp_enc_src_activate_mode:<sctpenc_0:src> pad 0x1760700 activate_mode: active 1, ret 1 0:00:00.047761960 20594 0x174d300 WARN sctpdec gstsctpdec.c:217:sink_pad_activate_func:<assoc_0:sink> 0x17604c0 activate_mode: active 1, ret 0 ** INFO: SCTP association state change! 0x7ff3080025c0 SCTP: add HMAC id 1 to list SCTP: added chunk 193 (0xc1) to Auth list SCTP: added chunk 128 (0x80) to Auth list ** INFO: SCTP association state change! 0x7ff3080025c0 0:00:00.047899129 20594 0x174d300 WARN sctpdec gstsctpdec.c:227:sink_pad_activate_func:<assoc_0> activate_mode: active 1, ret 1 Bind called port: 9999 Addr: AF_CONN address: 0x7ff3080025c0 Ok laddr->ifa:0x1783030 is possible, Main hash to bind at head:0x177fbd8, bound port:9999 - in tcp_pool=0 Allocate an association for peer:AF_CONN address: 0x7ff3080025c0 Port:9999 Adding an address (from:1) to the peer: AF_CONN address: 0x177b330 Association 0x7ff3040009d0 now allocated Sending INIT Sending INIT - calls lowlevel_output ** INFO: usrsctp: PMTUD disabled, MTU set to 1200 0:00:00.051169648 20594 0x1766cf0 WARN sctpdec gstsctpdec.c:297:association_incoming_packet:<assoc_0:sink> pad 0x17604c0 chain: 0x7ff3080025c0 Ok laddr->ifa:0x17859c0 is possible, stcb:(nil) inp:0x17862a0 stcb is (nil) Ok, Common input processing called, m:0x7ff2f0016300 iphlen:0 offset:12 length:100 stcb:(nil) sctp_process_control: iphlen=0, offset=12, length=100 stcb:(nil) Its an INIT of len:86 vtag:0 sctp_process_control: processing a chunk type=1, len=86 SCTP_INIT sctp_handle_init: handling INIT tcb:(nil) 0:00:00.051240094 20594 0x1766cf0 WARN sctpdec gstsctpdec.c:304:association_incoming_packet:<assoc_0:sink> pad 0x17604c0 chained: 0x7ff3080025c0 Adding an address (from:1) to the peer: AF_CONN address: 0x7ff3080025c0 Association 0x7ff2f80009d0 now allocated Sending INIT Sending INIT - calls lowlevel_output ** INFO: usrsctp: PMTUD disabled, MTU set to 1200 0:00:00.052417742 20594 0x1766b70 WARN sctpdec gstsctpdec.c:297:association_incoming_packet:<assoc_1:sink> pad 0x1760dc0 chain: 0x177b330 Ok laddr->ifa:0x17859c0 is possible, Ok laddr->ifa:0x1783030 is possible, stcb:0x7ff3040009d0 inp:0x17843b0 stcb is 0x7ff3040009d0 Ok, Common input processing called, m:0x7ff2fc001e00 iphlen:0 offset:12 length:100 stcb:0x7ff3040009d0 stcb:0x7ff3040009d0 state:2 sctp_process_control: iphlen=0, offset=12, length=100 stcb:0x7ff3040009d0 Its an INIT of len:86 vtag:0 sctp_process_control: processing a chunk type=1, len=86 SCTP_INIT sctp_handle_init: handling INIT tcb:0x7ff3040009d0 sctp_handle_init: sending INIT-ACK Check for unrecognized param's Hit default param 8004 move on 0:00:00.052571565 20594 0x1766b70 WARN sctpdec gstsctpdec.c:304:association_incoming_packet:<assoc_1:sink> pad 0x1760dc0 chained: 0x177b330 0:00:00.052658144 20594 0x1766cf0 WARN sctpdec gstsctpdec.c:297:association_incoming_packet:<assoc_0:sink> pad 0x17604c0 chain: 0x7ff3080025c0 Ok, Common input processing called, m:0x7ff2f0016300 iphlen:0 offset:12 length:412 stcb:0x7ff2f80009d0 stcb:0x7ff2f80009d0 state:2 sctp_process_control: iphlen=0, offset=12, length=412 stcb:0x7ff2f80009d0 sctp_process_control: processing a chunk type=2, len=400 SCTP_INIT_ACK sctp_handle_init_ack: handling INIT-ACK Check for unrecognized param's Hit default param 8004 move on SCTP: add HMAC id 1 to list SCTP: added chunk 128 (0x80) to Auth list SCTP: added chunk 193 (0xc1) to Auth list SCTP: negotiated peer HMAC id 1 moving to COOKIE-ECHOED state Leaving handle-init-ack end 0:00:00.053548582 20594 0x1766b70 WARN sctpdec gstsctpdec.c:297:association_incoming_packet:<assoc_1:sink> pad 0x1760dc0 chain: 0x177b330 Ok, Common input processing called, m:0x7ff2fc003e00 iphlen:0 offset:12 length:324 stcb:0x7ff3040009d0 stcb:0x7ff3040009d0 state:2 sctp_process_control: iphlen=0, offset=12, length=324 stcb:0x7ff3040009d0 sctp_process_control: processing a chunk type=10, len=312 SCTP_COOKIE_ECHO, stcb 0x7ff3040009d0 sctp_handle_cookie: handling COOKIE-ECHO SCTP: add HMAC id 1 to list SCTP: added chunk 128 (0x80) to Auth list SCTP: added chunk 193 (0xc1) to Auth list ** INFO: Event: SCTP_ASSOC_CHANGE ** INFO: SCTP_COMM_UP() 0x177b330 ** INFO: SCTP association connected! 0x177b330 ** INFO: SCTP association state change! 0x177b330 0:00:00.053763283 20594 0x1766b70 DEBUG SCTP association 1 established Check for chunk output prw:131072 tqe:0 tf=0 Calling chunk OUTPUT m-c-o put out 1 Ok, we have put out 1 chunks chunk OUTPUT returns 0:00:00.053812179 20594 0x1766b70 WARN sctpdec gstsctpdec.c:304:association_incoming_packet:<assoc_1:sink> pad 0x1760dc0 chained: 0x177b330 m-c-o put out 0 Ok, we have put out 0 chunks Check for chunk output prw:131072 tqe:0 tf=0 Calling chunk OUTPUT m-c-o put out 0 Ok, we have put out 0 chunks chunk OUTPUT returns 0:00:00.053875446 20594 0x1766cf0 WARN sctpdec gstsctpdec.c:304:association_incoming_packet:<assoc_0:sink> pad 0x17604c0 chained: 0x7ff3080025c0 0:00:00.053900605 20594 0x1766cf0 WARN sctpdec gstsctpdec.c:297:association_incoming_packet:<assoc_0:sink> pad 0x17604c0 chain: 0x7ff3080025c0 Ok, Common input processing called, m:0x7ff2f0016300 iphlen:0 offset:12 length:16 stcb:0x7ff2f80009d0 stcb:0x7ff2f80009d0 state:4 sctp_process_control: iphlen=0, offset=12, length=16 stcb:0x7ff2f80009d0 sctp_process_control: processing a chunk type=11, len=4 SCTP_COOKIE_ACK, stcb 0x7ff2f80009d0 sctp_handle_cookie_ack: handling COOKIE-ACK moving to OPEN state ** INFO: Event: SCTP_ASSOC_CHANGE ** INFO: SCTP_COMM_UP() 0x7ff3080025c0 ** INFO: SCTP association connected! 0x7ff3080025c0 ** INFO: SCTP association state change! 0x7ff3080025c0 0:00:00.053971318 20594 0x1766cf0 DEBUG SCTP association 0 established 0:00:00.054005565 20594 0x174d300 DEBUG Tearing down connection 0:00:00.054167789 20594 0x174d300 WARN closing socket assoc 1: 0x177b330 0:00:00.054536272 20594 0x174d300 WARN closing socket assoc 0: 0x7ff3080025c0 Timer type 17 goes off Timer now complete (type = 17) Timer type 16 goes offAt his point, the program get stalled waiting for the thread 5 which is locked in usrsctp_conninput to finish. I noticed that it only gets blocked whenever I got the trace with the timer type 16 (SCTP_TIMER_TYPE_ASOCKILL). Other executions that does not print that trace finishes correctly.