souphttpsrc: source:src thread disappears even though handshake_thread task is running
Regarding this issue, an issue was created in glib-networking and discussion was ongoing.
https://gitlab.gnome.org/GNOME/glib-networking/-/issues/176
However, I still couldn't find a clue as to why the parent thread that created the task disappeared first, so I opened an issue to Gstreamer.
With the following relationship, handshake_thread starts with g_task_run_in_thread through source:src thread, Sometimes there is a problem in the process of stopping the pipeline when the network situation is terrible. If I check the crash dump, handshake_thread (pool-pipe-m) is a situation in which a crash occurred during the operation for error string handling, and strangely, at this time, source:src has already disappeared and is not visible. My guess is that the source:src that created the tls object is gone, which is the cause of the crash of handshake_thread that needs to use the tls object(err_string_lock).
As discussed in glib-networking, it is nonsense that source:src disappears before handshake_thread terminates.
In the normal case backtrace.
Thread 2.6 "source:src" hit Breakpoint 2, g_tls_connection_base_handshake (conn=0xf18121b8, cancellable=0x169a770, error=0xf21bc864)
at ../glib-networking-2.62.4/tls/base/gtlsconnection-base.c:1534
1534 ../glib-networking-2.62.4/tls/base/gtlsconnection-base.c: No such file or directory.
(gdb) bt
#0 g_tls_connection_base_handshake (conn=0xf18121b8, cancellable=0x169a770, error=0xf21bc864) at ../glib-networking-2.62.4/tls/base/gtlsconnection-base.c:1534
#1 0xf5d8ab0c in ?? () from /usr/lib/libsoup-2.4.so.1
#2 0xf5d6d646 in ?? () from /usr/lib/libsoup-2.4.so.1
#3 0xf5d87528 in ?? () from /usr/lib/libsoup-2.4.so.1
#4 0xf5d87f0e in soup_session_send () from /usr/lib/libsoup-2.4.so.1
#5 0xf21e6eb2 in gst_soup_http_src_send_message (src=0x16a81e0) at ../git/ext/soup/gstsouphttpsrc.c:1923
#6 gst_soup_http_src_do_request (src=src@entry=0x16a81e0, method=<optimized out>) at ../git/ext/soup/gstsouphttpsrc.c:1999
#7 0xf21e8532 in gst_soup_http_src_create (psrc=0x16a81e0, outbuf=0xf21bcb4c) at ../git/ext/soup/gstsouphttpsrc.c:2191
Thread 2.8 "pool-pipe-m" hit Breakpoint 4, handshake_thread (task=0x15c22e0, object=0xf18121b8, task_data=0xf1814ba0, cancellable=0x169a770)
at ../glib-networking-2.62.4/tls/base/gtlsconnection-base.c:1350
1350 in ../glib-networking-2.62.4/tls/base/gtlsconnection-base.c
(gdb) bt
#0 handshake_thread (task=0x15c22e0, object=0xf18121b8, task_data=0xf1814ba0, cancellable=0x169a770) at ../glib-networking-2.62.4/tls/base/gtlsconnection-base.c:1350
#1 0xf5e936a0 in ?? () from /usr/lib/libgio-2.0.so.0
#2 0xf78fbe48 in ?? () from /usr/lib/libglib-2.0.so.0
#3 0xf78fb8ee in ?? () from /usr/lib/libglib-2.0.so.0
#4 0xf7748898 in start_thread (arg=0x7ca98217) at pthread_create.c:477
When a crash occurs in handshake_thread as shown below, source:src has already disappeared.
Signal: 11
SignalCode: 1, SEGV_MAPERR
SignalSender: 28
FaultAddress: 0x0000001c
Register dump:
r0: 0x00000000 r1: 0xf6c69f6d r2: 0xf22fd140 r3: 0xf22fd600
r4: 0xf6d43f10 r5: 0xf22fc858 r6: 0xf22fc988 r7: 0xf22fc988
r8: 0xffffffff r9: 0x00000000 r10: 0xf3652ee0 fp: 0xf365352c
ip: 0xf6d4288c sp: 0xf22fc840 lr: 0xf6cb068b pc: 0xf79cb41c
cpsr: 0x00000030
Disassemble:
...
0xf79cb414: mrc p15, #0, r3, c13, c0, #3
0xf79cb418: sub.w r2, r3, #0x4c0
***** 0xf79cb41c: ldr r3, [r0, #0x1c]
PC: /lib/libpthread-2.31.so [0xf79cb41c]
LR: /usr/lib/libcrypto.so.1.1 [0xf6cb068b]
Backtrace: tid = 14905
/lib/libpthread-2.31.so (__pthread_rwlock_rdlock+0x7) [0xf79cb41c] // crash occurred here in pool-pipe-m. is err_string_lock contained in tls object invalid?
/usr/lib/libcrypto.so.1.1 (CRYPTO_THREAD_read_lock+0x6) [0xf6cb068b]
/usr/lib/libcrypto.so.1.1 (ENGINE_set_RSA+0xf6) [0xf6c6a00b]
/usr/lib/libcrypto.so.1.1 (ERR_lib_error_string+0x28) [0xf6c6a32d]
/usr/lib/libcrypto.so.1.1 (ERR_error_string_n+0x18) [0xf6c6a3e1]
/usr/lib/gio/modules/libgioopenssl.so (g_io_openssl_query+0x1a26) [0xf364c55b]
g_tls_connection_openssl_handshake_thread_handshake, gtlsconnection-openssl.c:318
/usr/lib/gio/modules/libgioopenssl.so (g_io_openssl_query+0x62ac) [0xf3650de1]
handshake_thread, gtlsconnection-base.c:1414
/usr/lib/libgio-2.0.so.0.6200.6 (g_task_attach_source+0x1b0) [0xf61166a1]
/usr/lib/libglib-2.0.so.0.6200.6 (g_get_num_processors+0x188) [0xf7b7ae49]
/usr/lib/libglib-2.0.so.0.6200.6 (g_test_get_filename+0xd6) [0xf7b7a8ef]
/lib/libpthread-2.31.so (start_thread+0x90) [0xf79c7899]
/lib/libc-2.31.so (clone+0x3c) [0xf6ec4aad]
Backtrace: tid = 8112
/lib/libpthread-2.31.so (__libc_do_syscall+0x5) [0xf79d1b26]
/lib/libpthread-2.31.so (__pthread_clockjoin_ex+0x176) [0xf79c8983]
/lib/libpthread-2.31.so (pthread_join+0x10) [0xf79c8799]
/usr/lib/libsystrim.so.3.0.0 (end_watch+0xd6) [0xf7d1623f]
/lib/ld-2.31.so (_dl_fini+0x160) [0xf7d35011]
/lib/libc-2.31.so (__run_exit_handlers+0x108) [0xf6e54c19]
/lib/libc-2.31.so (exit+0xe) [0xf6e54cdb]
/lib/libc-2.31.so (__libc_start_main+0x9c) [0xf6e44be9]
/usr/sbin/media-pipeline (_start+0x34) [0xa88351]
Backtrace: tid = 14903
/lib/libc-2.31.so (syscall+0xf) [0xf6ec2730]
/usr/lib/libglib-2.0.so.0.6200.6 (g_cond_wait_until+0x8e) [0xf7b922a7]
/usr/lib/libglib-2.0.so.0.6200.6 (g_byte_array_sort_with_data+0x9e) [0xf7b3e74b]
/usr/lib/libglib-2.0.so.0.6200.6 (g_get_num_processors+0x300) [0xf7b7afc1]
/usr/lib/libglib-2.0.so.0.6200.6 (g_test_get_filename+0xd6) [0xf7b7a8ef]
/lib/libpthread-2.31.so (start_thread+0x90) [0xf79c7899]
/lib/libc-2.31.so (clone+0x3c) [0xf6ec4aad]
Backtrace: tid = 14904
/lib/libc-2.31.so (__libc_do_syscall+0x3) [0xf6e44e24]
/lib/libc-2.31.so (__poll+0x3c) [0xf6ebe535]
/usr/lib/libglib-2.0.so.0.6200.6 (g_main_context_dispatch+0x2aa) [0xf7b5f39b]
/usr/lib/libglib-2.0.so.0.6200.6 (g_main_context_iteration+0x1c) [0xf7b5f449]
/usr/lib/libglib-2.0.so.0.6200.6 (g_main_context_iteration+0x48) [0xf7b5f475]
/usr/lib/libglib-2.0.so.0.6200.6 (g_test_get_filename+0xd6) [0xf7b7a8ef]
/lib/libpthread-2.31.so (start_thread+0x90) [0xf79c7899]
/lib/libc-2.31.so (clone+0x3c) [0xf6ec4aad]
Thread Info:
Tid: 14905
Comm: pool-pipe-m
It's not easy to reproduce the problem, so I haven't gotten GST_DEBUG yet, but if it does, I'll look at the gsttask log.
Can't we guess the cause of the parent thread disappearing even though the task is running in sync with only the small information above?
Additionally, got log as below.
Abnormal case, source:src task joined with souphttp's cancelled operation.
0:00:03.785770340 16045 0x1ae41a0 DEBUG task gsttask.c:431:gst_task_new: Created task 0x1afa828
0:00:03.785819520 16045 0x1ae41a0 INFO task gsttask.c:460:gst_task_set_lock: setting stream lock 0x1a2b610 on task 0x1afa828
0:00:03.790379100 16045 0x1ae41a0 DEBUG basesrc gstbasesrc.c:459:gst_base_src_init:<GstBaseSrc@0x1b0c1e0> creating src pad
0:00:03.790426860 16045 0x1ae41a0 DEBUG basesrc gstbasesrc.c:462:gst_base_src_init:<GstBaseSrc@0x1b0c1e0> setting functions on src pad
0:00:03.790437600 16045 0x1ae41a0 DEBUG basesrc gstbasesrc.c:470:gst_base_src_init:<GstBaseSrc@0x1b0c1e0> adding src pad
0:00:03.790446340 16045 0x1ae41a0 DEBUG basesrc gstbasesrc.c:486:gst_base_src_init:<GstBaseSrc@0x1b0c1e0> init done
0:00:03.790827760 16045 0x1ae41a0 INFO basesrc gstbasesrc.c:2309:gst_base_src_set_property:<source> passed structure is [smart-properties, real-time=(boolean)true, adaptive-mode=(boolean)true;], result structure is [smart-properties, push-mode=(boolean)true, real-time=(boolean)true, adaptive-mode=(boolean)true;]
0:00:03.790927460 16045 0x1ae41a0 INFO basesrc gstbasesrc.c:2309:gst_base_src_set_property:<source> passed structure is [smart-properties, interleaving-type=(int)0, drm-mediauri=(string)"https://live.sdn.wavve.com/hls/C4102/KR/1/2000/live.m3u8\?....", low-percent=(int)98, dolby-vision-support=(boolean)true;], result structure is [smart-properties, push-mode=(boolean)true, real-time=(boolean)true, adaptive-mode=(boolean)true, interleaving-type=(int)0, drm-mediauri=(string)"https://live.sdn.wavve.com/hls/C4102/KR/1/2000/live.m3u8\?....", low-percent=(int)98, dolby-vision-support=(boolean)true;]
0:00:03.790995060 16045 0x1ae41a0 DEBUG basesrc gstbasesrc.c:1446:gst_base_src_default_query:<source> query caps returns 1
0:00:03.791418620 16045 0x1ae41a0 DEBUG basesrc gstbasesrc.c:1446:gst_base_src_default_query:<source> query caps returns 1
0:00:03.791568720 16045 0x1ae41a0 DEBUG basesrc gstbasesrc.c:4091:gst_base_src_activate_mode:<source:src> activating in mode 1
0:00:03.791577420 16045 0x1ae41a0 DEBUG basesrc gstbasesrc.c:4017:gst_base_src_activate_push:<source> Activating in push mode
0:00:03.791587200 16045 0x1ae41a0 DEBUG souphttpsrc gstsouphttpsrc.c:2241:gst_soup_http_src_start:<source> start("https://live.sdn.wavve.com/hls/C4102/KR/1/2000/live.m3u8?....")
0:00:03.791606520 16045 0x1ae41a0 DEBUG souphttpsrc gstsouphttpsrc.c:1122:gst_soup_http_src_session_open:<source> dlna opval = 273, flagval=273, src->is_dtcp:0
0:00:03.791625640 16045 0x1ae41a0 DEBUG souphttpsrc gstsouphttpsrc.c:1132:gst_soup_http_src_session_open:<source> no dlna
0:00:03.791652660 16045 0x1ae41a0 DEBUG souphttpsrc gstsouphttpsrc.c:1186:gst_soup_http_src_session_open:<source> Creating session (can share 0)
0:00:03.801733600 16045 0x1ae41a0 DEBUG basesrc gstbasesrc.c:3714:gst_base_src_start_complete:<source> starting source
0:00:03.801758220 16045 0x1ae41a0 DEBUG souphttpsrc gstsouphttpsrc.c:2349:gst_soup_http_src_get_size:<source> get_size() = FALSE
0:00:03.801773380 16045 0x1ae41a0 DEBUG basesrc gstbasesrc.c:3727:gst_base_src_start_complete:<source> setting size 18446744073709551615
0:00:03.801797100 16045 0x1ae41a0 DEBUG basesrc gstbasesrc.c:3735:gst_base_src_start_complete:<source> format: bytes, have size: 0, size: 18446744073709551615, duration: -1
0:00:03.801814260 16045 0x1ae41a0 INFO souphttpsrc gstsouphttpsrc.c:2386:gst_soup_http_src_is_seekable:<source> seekable : 0
0:00:03.801820720 16045 0x1ae41a0 DEBUG basesrc gstbasesrc.c:3741:gst_base_src_start_complete:<source> is seekable: 0
0:00:03.801825520 16045 0x1ae41a0 DEBUG basesrc gstbasesrc.c:3746:gst_base_src_start_complete:<source> is random_access: 0
0:00:03.801843740 16045 0x1ae41a0 DEBUG basesrc gstbasesrc.c:1755:gst_base_src_perform_seek:<source> doing seek: (NULL)
0:00:03.801855300 16045 0x1ae41a0 DEBUG basesrc gstbasesrc.c:1822:gst_base_src_perform_seek:<source> seek with seqnum 22
0:00:03.801863280 16045 0x1ae41a0 DEBUG basesrc gstbasesrc.c:1857:gst_base_src_perform_seek:<source> segment configured from 0 to -1, position 0
0:00:03.801888880 16045 0x1ae41a0 INFO basesrc gstbasesrc.c:1495:gst_base_src_do_seek:<source> seeking: bytes segment start=0, offset=0, stop=-1, rate=1.000000, applied_rate=1.000000, flags=0x00, time=0, base=0, position 0, duration -1
0:00:03.801900400 16045 0x1ae41a0 DEBUG souphttpsrc gstsouphttpsrc.c:2396:gst_soup_http_src_do_seek:<source> do_seek(0-18446744073709551615)
0:00:03.801905500 16045 0x1ae41a0 DEBUG souphttpsrc gstsouphttpsrc.c:2415:gst_soup_http_src_do_seek:<source> Seek to current read/end position and no seek pending
0:00:03.801933020 16045 0x1ae41a0 DEBUG task gsttask.c:431:gst_task_new: Created task 0x1afa8d0
0:00:03.801942360 16045 0x1ae41a0 INFO task gsttask.c:460:gst_task_set_lock: setting stream lock 0x1af9294 on task 0x1afa8d0
0:00:03.802111720 16045 0x1ae41a0 DEBUG task gsttask.c:673:gst_task_set_state_unlocked:<task1> Changing task 0x1afa8d0 to state 0
0:00:03.802259380 16045 0x1ae41a0 DEBUG basesrc gstbasesrc.c:3851:gst_base_src_start_wait:<source> got ok
0:00:03.802821800 16045 0x19e7950 DEBUG task gsttask.c:283:gst_task_func: Entering task 0x1afa8d0, thread 0x19e7950
0:00:03.802934060 16045 0x19e7950 DEBUG task gsttask.c:245:gst_task_configure_name:<source:src> Setting thread name to 'source:src'
0:00:03.803022880 16045 0x19e7950 DEBUG basesrc gstbasesrc.c:1000:gst_base_src_send_stream_start:<source> Pushing STREAM_START
0:00:03.803059000 16045 0x19e7950 DEBUG basesrc gstbasesrc.c:3567:gst_base_src_negotiate_unlocked:<source> starting negotiation
0:00:03.803084520 16045 0x19e7950 DEBUG basesrc gstbasesrc.c:1446:gst_base_src_default_query:<source> query caps returns 1
0:00:03.803094520 16045 0x19e7950 DEBUG basesrc gstbasesrc.c:3496:gst_base_src_default_negotiate:<source> caps of src: ANY
0:00:03.803100540 16045 0x19e7950 DEBUG basesrc gstbasesrc.c:3542:gst_base_src_default_negotiate:<source> no negotiation needed
0:00:03.803121420 16045 0x19e7950 DEBUG basesrc gstbasesrc.c:3436:gst_base_src_prepare_allocation:<source> peer ALLOCATION query failed
0:00:03.803165680 16045 0x19e7950 DEBUG basesrc gstbasesrc.c:3442:gst_base_src_prepare_allocation:<source> ALLOCATION (1) params: allocation query: 0xf2105cc0, GstQueryAllocation, caps=(GstCaps)"NULL", need-pool=(boolean)true, allocator=(GArray)NULL, pool=(GArray)NULL;
0:00:03.803192600 16045 0x19e7950 LOG basesrc gstbasesrc.c:3026:gst_base_src_loop:<source> next_ts 0:00:00.000000000 size 24576
0:00:03.803241000 16045 0x19e7950 DEBUG basesrc gstbasesrc.c:2594:gst_base_src_update_length:<source> reading offset 0, length 24576, size -1, segment.stop -1, maxsize -1
0:00:03.803251620 16045 0x19e7950 DEBUG basesrc gstbasesrc.c:2702:gst_base_src_get_range:<source> calling create offset 0 length 24576, time 0
0:00:03.803269660 16045 0x19e7950 LOG souphttpsrc gstsouphttpsrc.c:1973:gst_soup_http_src_do_request:<source> Running request for method: GET
0:00:03.803834180 16045 0x19e7950 DEBUG souphttpsrc gstsouphttpsrc.c:989:gst_soup_http_src_add_range_header:<source> Appending byte range header bytes=0-
0:00:03.803849900 16045 0x19e7950 DEBUG souphttpsrc gstsouphttpsrc.c:1020:_append_extra_header:<source> Appending extra header: "Referer: http://lgchplus-test.wavve.com/?lg_server=qa2"
0:00:03.850823360 16045 0x1ae41a0 DEBUG task gsttask.c:673:gst_task_set_state_unlocked:<task0> Changing task 0x1afa828 to state 1
0:00:03.850850440 16045 0x1ae41a0 DEBUG task gsttask.c:853:gst_task_join:<task0> Joining task 0x1afa828, thread 0x1ae41a0
0:00:03.850857520 16045 0x1ae41a0 DEBUG task gsttask.c:883:gst_task_join:<task0> Joined task 0x1afa828
0:00:03.850869340 16045 0x1ae41a0 DEBUG task gsttask.c:210:gst_task_finalize: task 0x1afa828 finalize
0:00:03.851063320 16045 0x1ae41a0 DEBUG basesrc gstbasesrc.c:4091:gst_base_src_activate_mode:<source:src> activating in mode 1
0:00:03.851079920 16045 0x1ae41a0 DEBUG basesrc gstbasesrc.c:4025:gst_base_src_activate_push:<source> Deactivating in push mode
0:00:03.851085400 16045 0x1ae41a0 DEBUG basesrc gstbasesrc.c:3862:gst_base_src_stop:<source> stopping source
0:00:03.851091180 16045 0x1ae41a0 DEBUG basesrc gstbasesrc.c:3912:gst_base_src_set_flushing:<source> flushing 1
0:00:03.851097240 16045 0x1ae41a0 DEBUG souphttpsrc gstsouphttpsrc.c:2317:gst_soup_http_src_unlock:<source> unlock()
0:00:03.851147180 16045 0x1ae41a0 DEBUG task gsttask.c:673:gst_task_set_state_unlocked:<source:src> Changing task 0x1afa8d0 to state 1
0:00:03.852869420 16045 0x19e7950 DEBUG souphttpsrc gstsouphttpsrc.c:1927:gst_soup_http_src_send_message:<source> Sending message failed: Operation was cancelled(19)
0:00:03.852895540 16045 0x19e7950 DEBUG souphttpsrc gstsouphttpsrc.c:2210:gst_soup_http_src_create:<source> Returning -2 flushing
0:00:03.852907460 16045 0x19e7950 DEBUG basesrc gstbasesrc.c:2842:gst_base_src_get_range:<source> create returned -2 (flushing)
0:00:03.852915460 16045 0x19e7950 INFO basesrc gstbasesrc.c:3037:gst_base_src_loop:<source> pausing after gst_base_src_get_range() = flushing
0:00:03.852921980 16045 0x19e7950 DEBUG basesrc gstbasesrc.c:3207:gst_base_src_loop:<source> pausing task, reason flushing
0:00:03.852971900 16045 0x19e7950 DEBUG task gsttask.c:355:gst_task_func: Exit task 0x1afa8d0, thread 0x19e7950
0:00:03.852998900 16045 0x1ae41a0 DEBUG task gsttask.c:853:gst_task_join:<source:src> Joining task 0x1afa8d0, thread 0x1ae41a0
0:00:03.853006620 16045 0x1ae41a0 DEBUG task gsttask.c:883:gst_task_join:<source:src> Joined task 0x1afa8d0
0:00:03.853014400 16045 0x1ae41a0 DEBUG task gsttask.c:210:gst_task_finalize: task 0x1afa8d0 finalize
0:00:03.853024080 16045 0x1ae41a0 DEBUG basesrc gstbasesrc.c:3912:gst_base_src_set_flushing:<source> flushing 0
0:00:03.853031840 16045 0x1ae41a0 DEBUG souphttpsrc gstsouphttpsrc.c:2330:gst_soup_http_src_unlock_stop:<source> unlock_stop()
0:00:03.853067260 16045 0x1ae41a0 DEBUG souphttpsrc gstsouphttpsrc.c:2252:gst_soup_http_src_stop:<source> stop()
0:00:03.853074660 16045 0x1ae41a0 DEBUG souphttpsrc gstsouphttpsrc.c:1289:gst_soup_http_src_session_close:<source> Closing session
0:00:03.853199260 16045 0x1ae41a0 DEBUG souphttpsrc gstsouphttpsrc.c:1289:gst_soup_http_src_session_close:<source> Closing session
0:00:03.854018640 16045 0x1ae41a0 DEBUG souphttpsrc gstsouphttpsrc.c:618:gst_soup_http_src_dispose:<source> dispose
0:00:03.854034940 16045 0x1ae41a0 DEBUG souphttpsrc gstsouphttpsrc.c:1289:gst_soup_http_src_session_close:<source> Closing session
0:00:03.854051180 16045 0x1ae41a0 DEBUG souphttpsrc gstsouphttpsrc.c:635:gst_soup_http_src_finalize:<source> finalize