search

catalinii / minisatip

minisatip is an SATIP server for linux using local DVB-S2, DVB-C, DVB-T or ATSC cards
https://minisatip.org
327 stars 81 forks source link

crash with latest git #743

Closed 9000h closed 4 years ago

9000h commented 4 years ago 
[24/04 10:57:00.223 main]: new filter 9 added for adapter 0, pid 17, flags 1, mask_len 1, master_filter 1
[24/04 10:57:00.223 main]: Dumping pids table for adapter 0, number of unknown pids: 19
[24/04 10:57:00.223 main]: pid 1920, fd 12, packets 33895, d/c errs 2727/1, flags 1, pmt 0, filter -1, sock -1, sids: 0 -1 -1 -1 -1 -1 -1 -1
[24/04 10:57:00.223 main]: pid 1925, fd 15, packets 1133, d/c errs 0/1, flags 1, pmt -1, filter -1, sock -1, sids: 0 -1 -1 -1 -1 -1 -1 -1
[24/04 10:57:00.223 main]: pid 1921, fd 13, packets 1498, d/c errs 115/7, flags 1, pmt 0, filter -1, sock -1, sids: 0 -1 -1 -1 -1 -1 -1 -1
[24/04 10:57:00.223 main]: pid 1922, fd 14, packets 1498, d/c errs 115/7, flags 1, pmt 0, filter -1, sock -1, sids: 0 -1 -1 -1 -1 -1 -1 -1
[24/04 10:57:00.223 main]: pid 120, fd 20, packets 29, d/c errs 0/0, flags 1, pmt -5, filter 7, sock -1, sids: -1 -1 -1 -1 -1 -1 -1 -1
[24/04 10:57:00.223 main]: pid 107, fd 11, packets 12, d/c errs 0/0, flags 1, pmt 0, filter 2, sock -1, sids: 0 -1 -1 -1 -1 -1 -1 -1
[24/04 10:57:00.223 main]: pid 0, fd 10, packets 12, d/c errs 0/0, flags 1, pmt -1, filter 0, sock -1, sids: 0 -1 -1 -1 -1 -1 -1 -1
[24/04 10:57:00.223 main]: pid 17, fd 0, packets 1, d/c errs 0/0, flags 2, pmt -1, filter 1, sock -1, sids: -1 -1 -1 -1 -1 -1 -1 -1
[24/04 10:57:00.223 main]: AD 0 [demux 0 0], setting filter on PID 17 for fd 16
[24/04 10:57:00.254 AD0]: Processing SDT for transponder 1007 (3ef) with length 173, sdt[5] D3
[24/04 10:57:00.254 AD0]: SDT PMT 0: name ORF1 HD provider ORF, sid: 4911 (132F)
[24/04 10:57:00.254 AD0]: SDT PMT 1: name ORF2W HD provider ORF, sid: 4912 (1330)
[24/04 10:57:00.254 AD0]: SDT PMT 2: name ServusTV HD Oesterreich provider ServusTV, sid: 4913 (1331)
[24/04 10:57:00.254 AD0]: SDT PMT 3: name ServusTV HD Deutschland provider ServusTV, sid: 4914 (1332)
[24/04 10:57:00.254 AD0]: SDT PMT 4: name ORF2N HD provider ORF, sid: 4916 (1334)
[24/04 10:57:00.254 AD0]: SDT PMT 5: name OE3. provider ORF, sid: 4920 (1338)
[24/04 10:57:00.255 AD0]: dvbapi: sending ECM key 0 for pid 0011 (17), current ecm_parity = 0, previous parity -1, demux = 0, filter = 1, len = 176 [42 F0 AD 03]
[24/04 10:57:00.255 main]: dvbapi read from socket 23 the following data (9 bytes), pos = 0, op 00006F2A, key 0
[24/04 10:57:00.255 main]: dvbapi: received DMX_STOP for key 0, index 1, adapter 0, demux 0, filter 1, pid 11 (17)
[24/04 10:57:00.255 main]: deleting filter 9
[24/04 10:57:00.255 main]: Destroying mutex 0x7fffe4013738
[24/04 10:57:00.255 main]: deleted filter 9, ad 0, pid 17, max filters 10
[24/04 10:57:00.260 AD0]: SOCK 8 it 1: queueing 70876 bytes at 2 (out of 100) send pos 0 [A:3, U:3]
[24/04 10:57:00.331 AD0]: SOCK 8 it 1: queueing 72192 bytes at 3 (out of 100) send pos 0 [A:4, U:4]
[24/04 10:57:00.340 main]: start flush sock id 8, send pos 0, write pos 4

Thread 1 "minisatip" received signal SIGPIPE, Broken pipe.
0x00007ffff67ae6e7 in __GI___writev (fd=9, iov=0x7fffffffcfc0, iovcnt=1) at ../sysdeps/unix/sysv/linux/writev.c:26
26  ../sysdeps/unix/sysv/linux/writev.c: No such file or directory.
(gdb) bt
#0  0x00007ffff67ae6e7 in __GI___writev (fd=9, iov=0x7fffffffcfc0, iovcnt=1) at ../sysdeps/unix/sysv/linux/writev.c:26
#1  0x0000555555566c7b in my_writev (s=0x55555593ebf0, iov=0x7fffffffcfc0, iiov=1) at socketworks.c:1361
#2  0x0000555555567b0a in flush_socket (s=0x55555593ebf0) at socketworks.c:1599
#3  0x0000555555564fb5 in select_and_execute (arg=0x0) at socketworks.c:805
#4  0x00005555555611f2 in main (argc=16, argv=0x7fffffffe358) at minisatip.c:1857
(gdb) up
#1  0x0000555555566c7b in my_writev (s=0x55555593ebf0, iov=0x7fffffffcfc0, iiov=1) at socketworks.c:1361
1361                rv = writev(s->sock, iov, iiov);
(gdb) up
#2  0x0000555555567b0a in flush_socket (s=0x55555593ebf0) at socketworks.c:1599
1599            rv = my_writev(s, iov, 1);
(gdb) up
#3  0x0000555555564fb5 in select_and_execute (arg=0x0) at socketworks.c:805
805                         while (!flush_socket(ss))
(gdb) up
#4  0x00005555555611f2 in main (argc=16, argv=0x7fffffffe358) at minisatip.c:1857
1857        select_and_execute(NULL);
(gdb) up
Initial frame selected; you cannot go up.
(gdb)
(gdb) print **s
$6 = {enabled = 1 '\001', mutex = {enabled = 1, mtx = pthread_mutex_t = {Type = Recursive, Status = Not acquired, Robust = No, Shared = No, Protocol = None}, state = 0, line = 515, tid = 140737353922048, 
    lock_time = 7365, create_time = 0, file = 0x5555555b3c72 "socketworks.c"}, is_enabled = 1 '\001', force_close = 0 '\000', sock = 5, nonblock = 0, sa = {sa = {sa_family = 2, 
      sa_data = "\344D\300\250\262\001\000\000\000\000\000\000\000"}, sin = {sin_family = 2, sin_port = 17636, sin_addr = {s_addr = 28485824}, sin_zero = "\000\000\000\000\000\000\000"}, sin6 = {
      sin6_family = 2, sin6_port = 17636, sin6_flowinfo = 28485824, sin6_addr = {__in6_u = {__u6_addr8 = '\000' <repeats 15 times>, __u6_addr16 = {0, 0, 0, 0, 0, 0, 0, 0}, __u6_addr32 = {0, 0, 0, 0}}}, 
      sin6_scope_id = 0}}, action = 0x55555555fd60 <ssdp_reply>, close = 0x55555555fd41 <ssdp_byebye>, timeout = 0x55555555fd22 <ssdp_discovery>, read = 0x555555563a49 <sockets_recv>, type = 0, sid = -1, 
  rtime = 194, wtime = 194, buf = 0x7fffffffda50 "", opaque = 0x0, opaque2 = 0x0, opaque3 = 0x0, lbuf = 2000, rlen = 123, timeout_ms = 60000, id = 0, iteration = 5, err = 0, flags = 0, events = 3, 
  last_poll = 40778, tid = 140737353922048, lock = 0x0, sock_err = 0, pack = 0x0, prio_pack = {len = 0, size = 0, buf = 0x0}, flush_enqued_data = 0, spos = 0, wmax = 100, wpos = 0, overflow = 0, buf_alloc = 0, 
  buf_used = 0, master = -1}
(gdb) print **a
$7 = {enabled = 1 '\001', mutex = {enabled = 1, mtx = pthread_mutex_t = {Type = Recursive, Status = Not acquired, Robust = No, Shared = No, Protocol = None}, state = 0, line = 1083, tid = 140737265985280, 
    lock_time = 40848, create_time = 18, file = 0x5555555b4f79 "stream.c"}, type = 1 '\001', fe = 7, dmx = -1, dvr = 8, pa = 0, fn = 0, slow_dev = 0 '\000', restart_when_tune = 0 '\000', 
  restart_needed = 0 '\000', err = 0 '\000', adapter_timeout = 30000, failed_adapter = 0 '\000', flush = 0 '\000', updating_pids = 0 '\000', sys = "\005\000\000\000\006\000\000\000\004", tp = {sys = 6, 
    freq = 11302000, inversion = 2, mtype = 6, fe = 0, hprate = 9, tmode = 2, gi = 4, bw = 8000000, sm = 0, t2id = 0, ro = 0, plts = 0, fec = 2, sr = 22000000, pol = 2, diseqc = 1, diseqc_param = {
      switch_type = 1, uslot = 4, ufreq = 984, pin = 48, only13v = 0, fast = 0, addr = 16, committed_no = 1, uncommitted_no = 0, before_cmd = 15, after_cmd = 54, after_repeated_cmd = 15, after_switch = 15, 
      after_burst = 15, after_tone = 0, lnb_low = 9750000, lnb_high = 10600000, lnb_circular = 10750000, lnb_switch = 11700000}, c2tft = 0, ds = -1, plp_isi = -1, pls_mode = -1, pls_code = -1, apids = 0x0, 
    pids = 0x5555559aa474 "0", dpids = 0x0, x_pmt = 0x0}, pids = {{pid = 1920, fd = 12, cc_err = 1, sid = "\000", '\377' <repeats 15 times>, flags = 1 '\001', packets = 34572, dec_err = 2727, pmt = 0, 
      filter = -1, cc = 10 '\n', cc1 = 0 '\000', sock = -1}, {pid = 1925, fd = 15, cc_err = 1, sid = "\000", '\377' <repeats 15 times>, flags = 1 '\001', packets = 1153, dec_err = 0, pmt = -1, filter = -1, 
      cc = 9 '\t', cc1 = 0 '\000', sock = -1}, {pid = 1921, fd = 13, cc_err = 7, sid = "\000", '\377' <repeats 15 times>, flags = 1 '\001', packets = 1530, dec_err = 115, pmt = 0, filter = -1, cc = 5 '\005', 
      cc1 = 0 '\000', sock = -1}, {pid = 1922, fd = 14, cc_err = 7, sid = "\000", '\377' <repeats 15 times>, flags = 1 '\001', packets = 1530, dec_err = 115, pmt = 0, filter = -1, cc = 13 '\r', cc1 = 0 '\000', 
      sock = -1}, {pid = 120, fd = 20, cc_err = 0, sid = '\377' <repeats 16 times>, flags = 1 '\001', packets = 29, dec_err = 0, pmt = -5, filter = 7, cc = 11 '\v', cc1 = 0 '\000', sock = -1}, {pid = 107, 
      fd = 11, cc_err = 0, sid = "\000", '\377' <repeats 15 times>, flags = 1 '\001', packets = 12, dec_err = 0, pmt = 0, filter = 2, cc = 4 '\004', cc1 = 0 '\000', sock = -1}, {pid = 0, fd = 10, cc_err = 0, 
      sid = "\000", '\377' <repeats 15 times>, flags = 1 '\001', packets = 12, dec_err = 0, pmt = -1, filter = 0, cc = 5 '\005', cc1 = 0 '\000', sock = -1}, {pid = 17, fd = 16, cc_err = 0, 
      sid = '\377' <repeats 16 times>, flags = 1 '\001', packets = 1, dec_err = 0, pmt = -1, filter = 1, cc = 11 '\v', cc1 = 0 '\000', sock = -1}, {pid = 109, fd = 0, cc_err = 0, 
      sid = '\377' <repeats 16 times>, flags = 0 '\000', packets = 1, dec_err = 0, pmt = -1, filter = -1, cc = 0 '\000', cc1 = 0 '\000', sock = -1}, {pid = 110, fd = 0, cc_err = 0, 
      sid = '\377' <repeats 16 times>, flags = 0 '\000', packets = 1, dec_err = 0, pmt = -1, filter = -1, cc = 11 '\v', cc1 = 0 '\000', sock = -1}, {pid = 116, fd = 0, cc_err = 0, 
      sid = '\377' <repeats 16 times>, flags = 0 '\000', packets = 1, dec_err = 0, pmt = -1, filter = -1, cc = 10 '\n', cc1 = 0 '\000', sock = -1}, {pid = 46, fd = 0, cc_err = 0, 
      sid = '\377' <repeats 16 times>, flags = 0 '\000', packets = 1, dec_err = 0, pmt = -1, filter = -1, cc = 12 '\f', cc1 = 0 '\000', sock = -1}, {pid = 58, fd = 0, cc_err = 0, 
      sid = '\377' <repeats 16 times>, flags = 0 '\000', packets = 1, dec_err = 0, pmt = -1, filter = -1, cc = 1 '\001', cc1 = 0 '\000', sock = -1}, {pid = 45, fd = 0, cc_err = 0, 
      sid = '\377' <repeats 16 times>, flags = 0 '\000', packets = 1, dec_err = 0, pmt = -1, filter = -1, cc = 12 '\f', cc1 = 0 '\000', sock = -1}, {pid = 47, fd = 0, cc_err = 0, 
      sid = '\377' <repeats 16 times>, flags = 0 '\000', packets = 1, dec_err = 0, pmt = -1, filter = -1, cc = 13 '\r', cc1 = 0 '\000', sock = -1}, {pid = 53, fd = 0, cc_err = 0, 
      sid = '\377' <repeats 16 times>, flags = 0 '\000', packets = 1, dec_err = 0, pmt = -1, filter = -1, cc = 12 '\f', cc1 = 0 '\000', sock = -1}, {pid = 41, fd = 0, cc_err = 0, 
      sid = '\377' <repeats 16 times>, flags = 0 '\000', packets = 1, dec_err = 0, pmt = -1, filter = -1, cc = 12 '\f', cc1 = 0 '\000', sock = -1}, {pid = 48, fd = 0, cc_err = 0, 
      sid = '\377' <repeats 16 times>, flags = 0 '\000', packets = 1, dec_err = 0, pmt = -1, filter = -1, cc = 13 '\r', cc1 = 0 '\000', sock = -1}, {pid = 0, fd = 0, cc_err = 0, 
      sid = '\377' <repeats 16 times>, flags = 0 '\000', packets = 0, dec_err = 0, pmt = 0, filter = 0, cc = 0 '\000', cc1 = 0 '\000', sock = 0} <repeats 110 times>}, ca_mask = 2, master_sid = 0, sid_cnt = 1, 
  sock = 7, fe_sock = -1, do_tune = 0, force_close = 0, 
  buf = 0x55555591b510 "G\a\200\233R\263\313\071\067\375\315\017V\253\203\275\376\375\232\177\364\\z\351\250+\277\367\021\025>\273,\240@>N\224\030\020\270-ɑ\032\351Z\356\300om\006\032\243)kT\002\362U\355\307\v,\325[\025\070Y\202\065S\235\370\205\255*\267Ga~\367p\272\275\311h'e\266\300\031j\317\350\221\060\245\231\060n%\245\260\321\307\356!Lڰ=Ө\r\212\071$\301\216\241\244\310\343\023\203\063[\265\033'z\276\370\223t\233Q\345)\231\344!*814\"\262\266\006/\364<\\\004\222\272\214\226f\241\360\223H\314`", rtime = 40848, last_sort = 96647, new_gs = 1, status = 31, status_cnt = 19, fast_status = 0, dmx_source = -1, 
  master_source = -1, is_fbc = 0, used = 0, strength = 254, ber = 0, snr = 38, strength_multiplier = 1, snr_multiplier = 1, pid_err = 19, dec_err = 7138, diseqc_param = {switch_type = 1, uslot = 4, 
    ufreq = 984, pin = 48, only13v = 0, fast = 0, addr = 16, committed_no = 1, uncommitted_no = 0, before_cmd = 15, after_cmd = 54, after_repeated_cmd = 15, after_switch = 15, after_burst = 15, after_tone = 0, 
    lnb_low = 9750000, lnb_high = 10600000, lnb_circular = 10750000, lnb_switch = 11700000}, diseqc_multi = -1, sources_pos = {0, 1 <repeats 64 times>}, debug_pos = 'X' <repeats 64 times>, 
  debug_src = 18446744073709551615, old_diseqc = 0, old_hiband = 0, old_pol = 0, id = 0, rlen = 72192, lbuf = 72192, pat_processed = 1, wait_new_stream = 0, wait_transponder_id = 0, threshold = 50, 
  active_pids = 8, max_active_pids = 18, max_pids = 0, active_demux_pids = 0, is_t2mi = 0, tune_time = 0, name = "AD0\000", null_packets = 0 '\000', drop_encrypted = 1 '\001', transponder_id = 1007, 
  pat_ver = 11, pat_filter = 0, sdt_filter = 1, set_pid = 0x5555555a76a4 <dvb_set_pid>, del_filters = 0x5555555a799a <dvb_del_filters>, commit = 0x5555555a9776 <dvb_commit>, 
  open = 0x5555555a4c55 <dvb_open_device>, tune = 0x5555555a6409 <dvb_tune>, delsys = 0x5555555a8937 <dvb_delsys>, get_signal = 0x5555555a9479 <dvb_get_signal>, wakeup = 0x0, standby = 0x0, post_init = 0x0, 
  close = 0x5555555a9781 <dvb_close>}
(gdb)
lars18th commented 4 years ago

Hi @9000h ,

Perhaps it's my fault. Please, can you apply my last PR, recompile, and retry to execute? My last patch increases the funcionality of the LOG, so it will be more easy to debug.

In any case, the problem seems to be related to a write in a unkown socket. We need to found the root cause, but a simple check in the function writev() can overcome the crash.

9000h commented 4 years ago

it did not help

[25/04 15:51:06.660 ADPT   main]: pid 106, fd 15, packets 0, d/c errs 0/0, flags 3, pmt -1, filter -1, sock -1, sids: -1 -1 -1 -1 -1 -1 -1 -1
[25/04 15:51:06.660 ADPT   main]: pid 96, fd 16, packets 4, d/c errs 0/0, flags 3, pmt -1, filter 2, sock -1, sids: -1 -1 -1 -1 -1 -1 -1 -1
[25/04 15:51:06.660 DVB    main]: clearing filter on PID 96 FD 16
[25/04 15:51:06.660 DVB    main]: clearing filter on PID 106 FD 15
[25/04 15:51:06.660 DVB    main]: clearing filter on PID 2816 FD 14
[25/04 15:51:06.660 DVB    main]: clearing filter on PID 2815 FD 13
[25/04 15:51:06.660 DVB    main]: clearing filter on PID 0 FD 12
[25/04 15:51:06.660 STRM   main]: closed stream sid 0
[25/04 15:51:06.660 STRM   main]: minisatip.c:1990 get_sid returns NULL for s_id = -1
[25/04 15:51:06.660 RTSP   main]: Reply RTSP (sid -1) [192.168.178.151:36446] content_len:0, sock 8 (handle 9)
[25/04 15:51:06.660 LOCK   main]: socketworks.c:544 Unlock disabled mutex 0x5555559a7dd8
[25/04 15:51:06.660 WORK   main]: sockets_unlock: Changing socket 8 lock 0x5555559a7dd8 to NULL error -1 Success
[25/04 15:51:06.660 LOCK   main]: socketworks.c:550 Unlock disabled mutex 0x555555972238

Thread 1 "minisatip" received signal SIGSEGV, Segmentation fault.
__strlen_sse2 () at ../sysdeps/x86_64/multiarch/../strlen.S:120
120 ../sysdeps/x86_64/multiarch/../strlen.S: No such file or directory.
(gdb) bt full
#0  __strlen_sse2 () at ../sysdeps/x86_64/multiarch/../strlen.S:120
No locals.
#1  0x00007ffff66f54d3 in _IO_vfprintf_internal (s=s@entry=0x7fffffffccd0, format=format@entry=0x5555555b30f0 "select_and_execute[%d]: %s on socket sock %d (sid %d) from %s:%d - type %s errno %d", 
    ap=ap@entry=0x7fffffffce78) at vfprintf.c:1643
        len = <optimized out>
        string_malloced = 0
        string = 0x300000005 <error: Cannot access memory at address 0x300000005>
        width = <optimized out>
        signed_number = <optimized out>
        is_short = 0
        spec = 115 's'
        ptr = <optimized out>
        ptr = <optimized out>
        outc = <optimized out>
        step0_jumps = {0, 160, 64, 1664, 1576, 1464, 1360, 2216, 2912, 208, 2032, 1848, 1760, -768, -760, 3024, 3000, 3104, 2128, 3120, -304, -704, 384, 312, -80, -1256, 2624, -1344, -1344, 2536}
        base = <optimized out>
        pad = <optimized out>
        offset = <optimized out>
        offset = <optimized out>
        step1_jumps = {0, 0, 0, 0, 0, 0, 0, 0, 0, 208, 2032, 1848, 1760, -768, -760, 3024, 3000, 3104, 2128, 3120, -304, -704, 384, 312, -80, -1256, 2624, -1344, -1344, 0}
        args_value = <optimized out>
        is_negative = <optimized out>
        number = <optimized out>
        use_outdigits = <optimized out>
        step2_jumps = {0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 2032, 1848, 1760, -768, -760, 3024, 3000, 3104, 2128, 3120, -304, -704, 384, 312, -80, -1256, 2624, -1344, -1344, 0}
        alt = 0
        left = 0
        showsign = <optimized out>
        group = 0
        is_char = 0
        step3a_jumps = {0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 1936, 0, 0, 0, -760, 3024, 3000, 3104, 2128, 0, 0, 0, 0, 312, 0, 0, 0, 0, 0, 0}
        the_arg = {pa_wchar = -12496 L'\xffffcf30', pa_int = -12496, pa_long_int = 140737488342832, pa_long_long_int = 140737488342832, pa_u_int = 4294954800, pa_u_long_int = 140737488342832, 
          pa_u_long_long_int = 140737488342832, pa_double = 6.9533558072176199e-310, pa_long_double = <invalid float value>, pa_string = 0x7fffffffcf30 "", pa_wstring = 0x7fffffffcf30 L"", 
          pa_pointer = 0x7fffffffcf30, pa_user = 0x7fffffffcf30}
        space = <optimized out>
        is_long_double = <optimized out>
        is_long = <optimized out>
        step3b_jumps = {0 <repeats 11 times>, 1760, 0, 0, -760, 3024, 3000, 3104, 2128, 3120, -304, -704, 384, 312, -80, -1256, 2624, 0, 0, 0}
        step4_jumps = {0 <repeats 14 times>, -760, 3024, 3000, 3104, 2128, 3120, -304, -704, 384, 312, -80, -1256, 2624, 0, 0, 0}
        prec = <optimized out>
        _buffer = {__routine = 0x5555555b4f00, __arg = 0x3000000020, __canceltype = -12432, __prev = 0x7fffffffceb0}
        _avail = <optimized out>
        thousands_sep = 0x0
        grouping = 0xffffffffffffffff <error: Cannot access memory at address 0xffffffffffffffff>
        done = 105
        f = <optimized out>
        lead_str_end = 0x5555555b3103 "%d]: %s on socket sock %d (sid %d) from %s:%d - type %s errno %d"
        end_of_spec = <optimized out>
        work_buffer = "\340\310\377\377\377\177\000\000 \000\000\000\060\000\000\000\300\317\377\377\377\177\000\000\000\317\377\377\377\177\000\000P\312\377\377\377\177\000\000\377\377\377\377\000\000\000\000 }|UUU\000\000\020\tr\366\377\177\000\000\001\200\255\373\000\000\000\000 }|UUU\000\000 }|UUU\000\000\000\000\361T/Q1\230@\311\377\377\377\177\000\000@\311\377\377\377\177\000\000\317\a\000\000\000\000\000\000\bb[UUU\000\000\260\312\377\377\377\177\000\000\377\377\377\377\000\000\000\000\000~|UUU\000\000\020\tr\366\377\177\000\000\001\200\255\373\000\063\062\070\000\000\361T/Q1\230\220\311\377\377\377\177\000\000\220\311\377\377\377\177\000\000\307\000\000\000\000\000\000\000"...
        workstart = <optimized out>
---Type <return> to continue, or q <return> to quit---    
        workend = <optimized out>
        ap_save = {{gp_offset = 32, fp_offset = 48, overflow_arg_area = 0x7fffffffcf90, reg_save_area = 0x7fffffffced0}}
        nspecs_done = 6
        save_errno = 9
        readonly_format = 0
        __PRETTY_FUNCTION__ = "_IO_vfprintf_internal"
        __result = <optimized out>
#2  0x00007ffff6720910 in _IO_vsnprintf (string=0x5555557c7e22 <output+34> "select_and_execute[11]: Bad file descriptor on socket sock -1 (sid -1) from 192.168.178.151:48697 - type ", maxlen=<optimized out>, 
    format=0x5555555b30f0 "select_and_execute[%d]: %s on socket sock %d (sid %d) from %s:%d - type %s errno %d", args=0x7fffffffce78) at vsnprintf.c:114
        sf = {f = {_sbf = {_f = {_flags = -72515583, _IO_read_ptr = 0x5555557c7e22 <output+34> "select_and_execute[11]: Bad file descriptor on socket sock -1 (sid -1) from 192.168.178.151:48697 - type ", 
                _IO_read_end = 0x5555557c7e22 <output+34> "select_and_execute[11]: Bad file descriptor on socket sock -1 (sid -1) from 192.168.178.151:48697 - type ", 
                _IO_read_base = 0x5555557c7e22 <output+34> "select_and_execute[11]: Bad file descriptor on socket sock -1 (sid -1) from 192.168.178.151:48697 - type ", 
                _IO_write_base = 0x5555557c7e22 <output+34> "select_and_execute[11]: Bad file descriptor on socket sock -1 (sid -1) from 192.168.178.151:48697 - type ", 
                _IO_write_ptr = 0x5555557c7e8b <output+139> "", _IO_write_end = 0x5555557c85cf <output+1999> "", 
                _IO_buf_base = 0x5555557c7e22 <output+34> "select_and_execute[11]: Bad file descriptor on socket sock -1 (sid -1) from 192.168.178.151:48697 - type ", 
                _IO_buf_end = 0x5555557c85cf <output+1999> "", _IO_save_base = 0x0, _IO_backup_base = 0x0, _IO_save_end = 0x0, _markers = 0x0, _chain = 0x0, _fileno = 48697, _flags2 = 128, 
                _old_offset = 140737488347984, _cur_column = 0, _vtable_offset = 0 '\000', _shortbuf = "", _lock = 0x0, _offset = 206158430256, _codecvt = 0x7fffffffce40, _wide_data = 0xffffffffffffffff, 
                _freeres_list = 0x0, _freeres_buf = 0x7ffff6a886a0 <_tmbuf>, __pad5 = 140737488342544, _mode = -1, _unused2 = "UU\000\000 }|UUU\000\000\267a[UUU\000"}, 
              vtable = 0x7ffff6a7ffa0 <_IO_strn_jumps>}, _s = {_allocate_buffer = 0x0, _free_buffer = 0xf7ffb8c8}}, 
          overflow_buf = "\000\000\000\000\000\000\000\000\000\000\361T/Q1\230\005\000\000\000\003\000\000\000P\232WUUU\000\000\063\000\000\000\000\000\000\000\006\000\000\000\000\000\000\000\224\002\000\000\000\000\000\000\277\231WUUU\000"}
        ret = <optimized out>
#3  0x000055555557a08b in _log (file=0x5555555b24e2 "socketworks.c", line=929, level=8192, fmt=0x5555555b30f0 "select_and_execute[%d]: %s on socket sock %d (sid %d) from %s:%d - type %s errno %d")
    at utils.c:751
        arg = {{gp_offset = 48, fp_offset = 48, overflow_arg_area = 0x7fffffffcfb8, reg_save_area = 0x7fffffffced0}}
        len = 34
        len1 = 34
        both = 0
        idx = 0
        times = 0
        stid = "  main\000\000T\254}\366\377\177\000\000\000\000\000\000\062\000\000\000\320\331\377\377\377\177\000\000\024\275\204\366\377\177\000\000\005\000\000\000\377\177\000\000n"
        lname = 0x5555555b61b7 "SOCK"
        output = {
          "[25/04 15:51:06.660 SOCK   main]: select_and_execute[11]: Bad file descriptor on socket sock -1 (sid -1) from 192.168.178.151:48697 - type \000-1\000,2816,106\000=NULL, apids=NULL, dpids=NULL x_pmt=NULL\000L, dpi"..., 
          "[25/04 15:51:06.660 LOCK   main]: socketworks.c:550 Unlock disabled mutex 0x555555972238\000\061, filter -1, sock -1, sids: -1 -1 -1 -1 -1 -1 -1 -1\000\000ackets 0\000, unsend packets 0\000\065,2816,106, apids=NULL, dpids"...}
#4  0x0000555555565bb2 in select_and_execute (arg=0x0) at socketworks.c:925
        err_str = 0x7ffff684c18a "Bad file descriptor"
        types = {0x5555555b3073 "udp", 0x5555555b3077 "tcp", 0x5555555b307b "server", 0x5555555b3082 "http", 0x5555555b3087 "rtsp", 0x5555555b308c "dvr"}
        ss = 0x555555972230
        master = 0x555555972230
        i = 11
        rv = 2
        rlen = -1
        les = 9
        es = 9
        pos_len = 2000
        buf = "\000EARDOWN\000rtsp://192.168.178.129/stream=1\000RTSP/1.0\000\000CSeq:\000\066\000\000User-Agent:\000LibVLC/3.0.9.2\000(LIVE555\000Streaming\000Media\000v2020.01.19)\000\000Session:\000\061\063\065\060\064\071\060\060\062\067\000\000\000\n\000npt=0.000-\000\000\000\n\000\071\066-48697\000\000\000\n\000\065\065\065\000Streaming\000Media\000v2"...
        pos = 0x7fffffffda10 ""
        err = 9
        pf = {{fd = 5, events = 3, revents = 0}, {fd = 6, events = 3, revents = 0}, {fd = 3, events = 3, revents = 0}, {fd = 4, events = 3, revents = 0}, {fd = -1, events = 0, revents = 0}, {fd = -1, 
---Type <return> to continue, or q <return> to quit---
            events = 0, revents = 0}, {fd = -2, events = 3, revents = 0}, {fd = -1, events = 0, revents = 0}, {fd = 9, events = 3, revents = 1}, {fd = -1, events = 0, revents = 0}, {fd = 10, events = 3, 
            revents = 0}, {fd = 11, events = 3, revents = 1}, {fd = -1, events = 0, revents = 0}, {fd = -1, events = 0, revents = 0}, {fd = -1, events = 0, revents = 0}, {fd = 23, events = 3, revents = 0}, {
            fd = -1, events = 0, revents = 0}, {fd = -1, events = 0, revents = 0}, {fd = 25, events = 3, revents = 0}, {fd = 26, events = 3, revents = 1}, {fd = -1, events = -1, 
            revents = -1} <repeats 280 times>}
        lt = 62502
        c_time = 62512
        read_ok = 0
        ra = "192.168.178.151", '\000' <repeats 34 times>
#5  0x00005555555614d6 in main (argc=16, argv=0x7fffffffe358) at minisatip.c:1890
        sock_bw = 5
        rv = 0
        devices = 8
        i = 19
        log_it = 262144
        sv = {sa = {sa_family = 2, sa_data = "\037\220", '\000' <repeats 11 times>}, sin = {sin_family = 2, sin_port = 36895, sin_addr = {s_addr = 0}, sin_zero = "\000\000\000\000\000\000\000"}, sin6 = {
            sin6_family = 2, sin6_port = 36895, sin6_flowinfo = 0, sin6_addr = {__in6_u = {__u6_addr8 = '\000' <repeats 15 times>, __u6_addr16 = {0, 0, 0, 0, 0, 0, 0, 0}, __u6_addr32 = {0, 0, 0, 0}}}, 
            sin6_scope_id = 0}}
(gdb)
lars18th commented 4 years ago

Hi @9000h ,

More clear debug now... so please enable now the full log of modules socketworks and socket (-v socketworks,socket). And if you don't see the cause, try adding "stream", "dvbapi" and "utils". What I see is that the RESPONSE that the server wants to send to the SAT>IP client (192.168.178.151:36446) fails... perhaps because the socket is closed, or by another cause. We need to identify this.

9000h commented 4 years ago

I had to revert back to "git reset --hard 107c400f1b6981b151cb4d05dfb268adfaa5f982"

lars18th commented 4 years ago

I had to revert back to "git reset --hard 107c400"

Then it's my fault! This patch is from me. I'll take a look... however, it will be interesting if you can pass to me a full log. In the meeantime I suspect that the problem can be the check of the b[0]. However, I can't imagine how this can create a crash, as the read implies the existence of the buffer. And I want to say that I'm using this patch for around three weeks without any crash.

In any case, I'll fix it. But please, share the full log. Regards.

9000h commented 4 years ago

this look suspicions to me as this could be out of bounds -1 https://github.com/catalinii/minisatip/blob/a69d763ddf599e27423366c5d4b1b2bd6890bc1b/src/adapter.c#L517

9000h commented 4 years ago

if I revert this commit only it did not crash https://github.com/catalinii/minisatip/commit/0a1910b59f1d6465aac850ad1770d6320e3e2c0a still testing

9000h commented 4 years ago

the issue seem to be

-                       if (ss->type == TYPE_RTCP || ss->sock == SOCK_TIMEOUT)
+                       if (ss->sock == SOCK_TIMEOUT)
ghost commented 4 years ago

Can you try to reproduce with -v socket and upload the log?

ghost commented 4 years ago

You can also do in gdb:

catch syscall close when you see fd 5 or 6 do a bt And paste the stack trace here

lars18th commented 4 years ago

Hi @catalinii ,

Only to have a more robust code I created this PR: #745 . In any case, now it's clear that the crash from @9000h is not related with this commit: https://github.com/catalinii/minisatip/commit/107c400f1b6981b151cb4d05dfb268adfaa5f982

lars18th commented 4 years ago

Hi @9000h ,

this look suspicions to me as this could be out of bounds -1 https://github.com/catalinii/minisatip/blob/a69d763ddf599e27423366c5d4b1b2bd6890bc1b/src/adapter.c#L517

Even this is not related with your crash, thank you for pointing it! The code has an error. I'm fixed it in PR #746 .

9000h commented 4 years ago

not sure if this helps

TEARDOWN rtsp://192.168.178.129/stream=1 RTSP/1.0
CSeq: 6
User-Agent: LibVLC/3.0.9.2 (LIVE555 Streaming Media v2020.01.19)
Session: 1804289383

[27/04 15:04:27.066 main]: Updating sid 0 time to 110727, current time 110734
[27/04 15:04:27.067 main]: closing stream sid 0
[27/04 15:04:27.067 main]: Closing RTP sock 9 handle 8
[27/04 15:04:27.068 main]: stream.c:333 get_sid returns NULL for s_id = 0
[27/04 15:04:27.068 main]: close_stream_for_socket: start close_stream_for_socket for id 0 (nil)
[27/04 15:04:27.069 main]: sockets_del: sock 9 -> handle 8, sid 0, overflow bytes 0, allocated 0, used 0, unsend packets 0
[Switching to Thread 0x7ffff7fcb600 (LWP 11469)]

Thread 1 "minisatip" hit Catchpoint 1 (call to syscall close), 0x00007ffff7bc7447 in __close (fd=8) at ../sysdeps/unix/sysv/linux/close.c:27
27  in ../sysdeps/unix/sysv/linux/close.c
(gdb) c
Continuing.

Thread 1 "minisatip" hit Catchpoint 1 (returned from syscall close), 0x00007ffff7bc7447 in __close (fd=8) at ../sysdeps/unix/sysv/linux/close.c:27
27  in ../sysdeps/unix/sysv/linux/close.c
(gdb) c
Continuing.
[27/04 15:04:30.526 signal]: get_signal_new took 3482 ms for adapter 0 handle 10 (status: 31, ber: 0, strength:254, snr: 40, force scan 0)
[27/04 15:04:31.081 main]: sockets_del: sock 9 Last open socket is at index 12 current_handle 8
[27/04 15:04:31.082 main]: Destroying mutex 0x5555559508b8
[27/04 15:04:31.083 signal]: BW 803KB/s, Total BW: 5 MB, ns/read 1824, r: 41, w: 46 fw: 0, tt: 74 ms
[27/04 15:04:31.084 AD0]: Mutex 0x5555559a9c78 destroyed meanwhile
[27/04 15:04:31.085 main]: Destroying mutex 0x5555559a9c78
[27/04 15:04:31.085 main]: Closing RTCP sock 10 handle 9
[27/04 15:04:31.086 main]: sockets_del: sock 10 -> handle 9, sid 0, overflow bytes 0, allocated 0, used 0, unsend packets 0

Thread 1 "minisatip" hit Catchpoint 1 (call to syscall close), 0x00007ffff7bc7447 in __close (fd=9) at ../sysdeps/unix/sysv/linux/close.c:27
27  in ../sysdeps/unix/sysv/linux/close.c
(gdb) c
Continuing.
[27/04 15:04:31.087 AD0]: leak detected 1 0!!! 

Thread 1 "minisatip" hit Catchpoint 1 (returned from syscall close), 0x00007ffff7bc7447 in __close (fd=9) at ../sysdeps/unix/sysv/linux/close.c:27
27  in ../sysdeps/unix/sysv/linux/close.c
(gdb) c
Continuing.
[27/04 15:04:32.248 main]: sockets_del: sock 10 Last open socket is at index 12 current_handle 9
[27/04 15:04:32.248 main]: Destroying mutex 0x555555962578
[27/04 15:04:32.249 AD0]: sockets_lock: Changing socket 8 lock 0x5555559a9c78 to NULL error 1 Operation not permitted
[27/04 15:04:32.251 main]: sockets_del: sock 8 -> handle -2, sid 0, overflow bytes 0, allocated 0, used 0, unsend packets 0
[27/04 15:04:32.251 main]: sockets_del: sock 8 Last open socket is at index 12 current_handle -2
[27/04 15:04:32.252 AD0]: event on socket index 11 handle 11 type 5 spos 0 wpos 0 (poll fd: 11, events: 3, revents: 3)
[27/04 15:04:32.253 main]: Destroying mutex 0x55555593ebf8
[27/04 15:04:32.253 main]: adapter.c:840 get_sid returns NULL for s_id = 0
[27/04 15:04:32.254 main]: closed adapter 0 for sid 0 m:-1 sid_cnt:0, restart_needed 0
[27/04 15:04:32.255 main]: deleting pids on adapter 0, sid -1, pids=NULL
[27/04 15:04:32.255 main]: Dumping pids table for adapter 0, number of unknown pids: 15
[27/04 15:04:32.256 main]: pid 163, fd 16, packets 22208, d/c errs 0/2, flags 3, pmt 0, filter -1, sock -1, sids: -1 -1 -1 -1 -1 -1 -1 -1
[27/04 15:04:32.256 main]: pid 18, fd 14, packets 3934, d/c errs 0/1, flags 3, pmt -1, filter -1, sock -1, sids: -1 -1 -1 -1 -1 -1 -1 -1
[27/04 15:04:32.256 main]: pid 106, fd 18, packets 2418, d/c errs 0/1, flags 3, pmt 0, filter -1, sock -1, sids: -1 -1 -1 -1 -1 -1 -1 -1
[27/04 15:04:32.256 main]: pid 105, fd 17, packets 1820, d/c errs 0/2, flags 3, pmt -1, filter -1, sock -1, sids: -1 -1 -1 -1 -1 -1 -1 -1
[27/04 15:04:32.257 main]: pid 0, fd 12, packets 20, d/c errs 0/1, flags 3, pmt -1, filter 0, sock -1, sids: -1 -1 -1 -1 -1 -1 -1 -1
[27/04 15:04:32.257 main]: pid 17, fd 13, packets 10, d/c errs 0/1, flags 3, pmt -1, filter 1, sock -1, sids: -1 -1 -1 -1 -1 -1 -1 -1
[27/04 15:04:32.257 main]: pid 44, fd 15, packets 19, d/c errs 0/1, flags 3, pmt 0, filter 2, sock -1, sids: -1 -1 -1 -1 -1 -1 -1 -1
[27/04 15:04:32.257 main]: pid 54, fd 20, packets 19, d/c errs 0/1, flags 3, pmt -1, filter 3, sock -1, sids: -1 -1 -1 -1 -1 -1 -1 -1
[27/04 15:04:32.258 main]: pid 55, fd 21, packets 19, d/c errs 0/1, flags 3, pmt -2, filter 4, sock -1, sids: -1 -1 -1 -1 -1 -1 -1 -1
[27/04 15:04:32.258 main]: pid 57, fd 30, packets 19, d/c errs 0/1, flags 3, pmt -11, filter 13, sock -1, sids: -1 -1 -1 -1 -1 -1 -1 -1
[27/04 15:04:32.258 main]: pid 56, fd 22, packets 19, d/c errs 0/1, flags 3, pmt -3, filter 5, sock -1, sids: -1 -1 -1 -1 -1 -1 -1 -1
[27/04 15:04:32.258 main]: Dumping pids table for adapter 0, number of unknown pids: 15
[27/04 15:04:32.259 main]: pid 163, fd 16, packets 22208, d/c errs 0/2, flags 3, pmt 0, filter -1, sock -1, sids: -1 -1 -1 -1 -1 -1 -1 -1
[27/04 15:04:32.259 main]: pid 18, fd 14, packets 3934, d/c errs 0/1, flags 3, pmt -1, filter -1, sock -1, sids: -1 -1 -1 -1 -1 -1 -1 -1
[27/04 15:04:32.259 main]: pid 106, fd 18, packets 2418, d/c errs 0/1, flags 3, pmt 0, filter -1, sock -1, sids: -1 -1 -1 -1 -1 -1 -1 -1
[27/04 15:04:32.259 main]: pid 105, fd 17, packets 1820, d/c errs 0/2, flags 3, pmt -1, filter -1, sock -1, sids: -1 -1 -1 -1 -1 -1 -1 -1
[27/04 15:04:32.260 main]: pid 0, fd 12, packets 20, d/c errs 0/1, flags 3, pmt -1, filter 0, sock -1, sids: -1 -1 -1 -1 -1 -1 -1 -1
[27/04 15:04:32.260 main]: pid 17, fd 13, packets 10, d/c errs 0/1, flags 3, pmt -1, filter 1, sock -1, sids: -1 -1 -1 -1 -1 -1 -1 -1
[27/04 15:04:32.260 main]: pid 44, fd 15, packets 19, d/c errs 0/1, flags 3, pmt 0, filter 2, sock -1, sids: -1 -1 -1 -1 -1 -1 -1 -1
[27/04 15:04:32.260 main]: pid 54, fd 20, packets 19, d/c errs 0/1, flags 3, pmt -1, filter 3, sock -1, sids: -1 -1 -1 -1 -1 -1 -1 -1
[27/04 15:04:32.260 main]: pid 55, fd 21, packets 19, d/c errs 0/1, flags 3, pmt -2, filter 4, sock -1, sids: -1 -1 -1 -1 -1 -1 -1 -1
[27/04 15:04:32.261 main]: pid 57, fd 30, packets 19, d/c errs 0/1, flags 3, pmt -11, filter 13, sock -1, sids: -1 -1 -1 -1 -1 -1 -1 -1
[27/04 15:04:32.261 main]: pid 56, fd 22, packets 19, d/c errs 0/1, flags 3, pmt -3, filter 5, sock -1, sids: -1 -1 -1 -1 -1 -1 -1 -1
[27/04 15:04:32.261 AD0]: Read OK 72192 (rlen:72192/total:72192) bytes from 11 [s: 11 m: 11] -> 0x55555591b510 (buf: 0x55555591b510) - iteration 215 action 0x55555556c5bb
[27/04 15:04:32.262 main]: clearing filter on PID 56 FD 22

Thread 1 "minisatip" hit Catchpoint 1 (call to syscall close), 0x00007ffff7bc7447 in __close (fd=22) at ../sysdeps/unix/sysv/linux/close.c:27
27  in ../sysdeps/unix/sysv/linux/close.c
(gdb) c
Continuing.

Thread 1 "minisatip" hit Catchpoint 1 (returned from syscall close), 0x00007ffff7bc7447 in __close (fd=22) at ../sysdeps/unix/sysv/linux/close.c:27
27  in ../sysdeps/unix/sysv/linux/close.c
(gdb) c
Continuing.
[27/04 15:04:33.424 signal]: get_signal_new took 1177 ms for adapter 0 handle 10 (status: 31, ber: 0, strength:254, snr: 39, force scan 0)
[27/04 15:04:34.189 main]: clearing filter on PID 57 FD 30

Thread 1 "minisatip" hit Catchpoint 1 (call to syscall close), 0x00007ffff7bc7447 in __close (fd=30) at ../sysdeps/unix/sysv/linux/close.c:27
27  in ../sysdeps/unix/sysv/linux/close.c
(gdb) c
Continuing.

Thread 1 "minisatip" hit Catchpoint 1 (returned from syscall close), 0x00007ffff7bc7447 in __close (fd=30) at ../sysdeps/unix/sysv/linux/close.c:27
27  in ../sysdeps/unix/sysv/linux/close.c
(gdb) c
Continuing.
[27/04 15:04:35.484 main]: clearing filter on PID 55 FD 21

Thread 1 "minisatip" hit Catchpoint 1 (call to syscall close), 0x00007ffff7bc7447 in __close (fd=21) at ../sysdeps/unix/sysv/linux/close.c:27
27  in ../sysdeps/unix/sysv/linux/close.c
(gdb) c
Continuing.

Thread 1 "minisatip" hit Catchpoint 1 (returned from syscall close), 0x00007ffff7bc7447 in __close (fd=21) at ../sysdeps/unix/sysv/linux/close.c:27
27  in ../sysdeps/unix/sysv/linux/close.c
(gdb) c
Continuing.
[27/04 15:04:36.657 main]: clearing filter on PID 54 FD 20

Thread 1 "minisatip" hit Catchpoint 1 (call to syscall close), 0x00007ffff7bc7447 in __close (fd=20) at ../sysdeps/unix/sysv/linux/close.c:27
27  in ../sysdeps/unix/sysv/linux/close.c
(gdb) c
Continuing.

Thread 1 "minisatip" hit Catchpoint 1 (returned from syscall close), 0x00007ffff7bc7447 in __close (fd=20) at ../sysdeps/unix/sysv/linux/close.c:27
27  in ../sysdeps/unix/sysv/linux/close.c
(gdb) c
Continuing.
[27/04 15:04:37.847 main]: clearing filter on PID 44 FD 15

Thread 1 "minisatip" hit Catchpoint 1 (call to syscall close), 0x00007ffff7bc7447 in __close (fd=15) at ../sysdeps/unix/sysv/linux/close.c:27
27  in ../sysdeps/unix/sysv/linux/close.c
(gdb) c
Continuing.

Thread 1 "minisatip" hit Catchpoint 1 (returned from syscall close), 0x00007ffff7bc7447 in __close (fd=15) at ../sysdeps/unix/sysv/linux/close.c:27
27  in ../sysdeps/unix/sysv/linux/close.c
(gdb) c
Continuing.
[27/04 15:04:39.357 main]: clearing filter on PID 17 FD 13

Thread 1 "minisatip" hit Catchpoint 1 (call to syscall close), 0x00007ffff7bc7447 in __close (fd=13) at ../sysdeps/unix/sysv/linux/close.c:27
27  in ../sysdeps/unix/sysv/linux/close.c
(gdb) c
Continuing.

Thread 1 "minisatip" hit Catchpoint 1 (returned from syscall close), 0x00007ffff7bc7447 in __close (fd=13) at ../sysdeps/unix/sysv/linux/close.c:27
27  in ../sysdeps/unix/sysv/linux/close.c
(gdb) c
Continuing.
[27/04 15:04:40.715 main]: clearing filter on PID 0 FD 12

Thread 1 "minisatip" hit Catchpoint 1 (call to syscall close), 0x00007ffff7bc7447 in __close (fd=12) at ../sysdeps/unix/sysv/linux/close.c:27
27  in ../sysdeps/unix/sysv/linux/close.c
(gdb) c
Continuing.

Thread 1 "minisatip" hit Catchpoint 1 (returned from syscall close), 0x00007ffff7bc7447 in __close (fd=12) at ../sysdeps/unix/sysv/linux/close.c:27
27  in ../sysdeps/unix/sysv/linux/close.c
(gdb) c
Continuing.
[27/04 15:04:42.006 main]: clearing filter on PID 105 FD 17

Thread 1 "minisatip" hit Catchpoint 1 (call to syscall close), 0x00007ffff7bc7447 in __close (fd=17) at ../sysdeps/unix/sysv/linux/close.c:27
27  in ../sysdeps/unix/sysv/linux/close.c
(gdb) c
Continuing.

Thread 1 "minisatip" hit Catchpoint 1 (returned from syscall close), 0x00007ffff7bc7447 in __close (fd=17) at ../sysdeps/unix/sysv/linux/close.c:27
27  in ../sysdeps/unix/sysv/linux/close.c
(gdb) c
Continuing.
[27/04 15:04:43.266 main]: clearing filter on PID 106 FD 18

Thread 1 "minisatip" hit Catchpoint 1 (call to syscall close), 0x00007ffff7bc7447 in __close (fd=18) at ../sysdeps/unix/sysv/linux/close.c:27
27  in ../sysdeps/unix/sysv/linux/close.c
(gdb) c
Continuing.

Thread 1 "minisatip" hit Catchpoint 1 (returned from syscall close), 0x00007ffff7bc7447 in __close (fd=18) at ../sysdeps/unix/sysv/linux/close.c:27
27  in ../sysdeps/unix/sysv/linux/close.c
(gdb) c
Continuing.
[27/04 15:04:44.375 main]: clearing filter on PID 18 FD 14

Thread 1 "minisatip" hit Catchpoint 1 (call to syscall close), 0x00007ffff7bc7447 in __close (fd=14) at ../sysdeps/unix/sysv/linux/close.c:27
27  in ../sysdeps/unix/sysv/linux/close.c
(gdb) c
Continuing.

Thread 1 "minisatip" hit Catchpoint 1 (returned from syscall close), 0x00007ffff7bc7447 in __close (fd=14) at ../sysdeps/unix/sysv/linux/close.c:27
27  in ../sysdeps/unix/sysv/linux/close.c
(gdb) c
Continuing.
[27/04 15:04:45.429 main]: clearing filter on PID 163 FD 16

Thread 1 "minisatip" hit Catchpoint 1 (call to syscall close), 0x00007ffff7bc7447 in __close (fd=16) at ../sysdeps/unix/sysv/linux/close.c:27
27  in ../sysdeps/unix/sysv/linux/close.c
(gdb) c
Continuing.

Thread 1 "minisatip" hit Catchpoint 1 (returned from syscall close), 0x00007ffff7bc7447 in __close (fd=16) at ../sysdeps/unix/sysv/linux/close.c:27
27  in ../sysdeps/unix/sysv/linux/close.c
(gdb) c
Continuing.
[27/04 15:04:46.567 AD0]: stream.c:1083 Locked 0x555555910fd8 after 14305 ms, previously locked at: adapter.c, line 845
[27/04 15:04:46.568 main]: closed stream sid 0
[27/04 15:04:46.568 main]: minisatip.c:1950 get_sid returns NULL for s_id = -1
[27/04 15:04:46.569 main]: Reply (handle 7) [192.168.178.151:46460] content_len:0, sock 7
[27/04 15:04:46.570 main]: MSG client << process :
RTSP/1.0 200 OK
Date: Mon, Apr 27 13:04:46 2020 GMT
CSeq: 6
Server: minisatip/1.0.3-a69d763
Session: 1804289383

[27/04 15:04:46.571 AD0]: event on socket index 11 handle 11 type 5 spos 0 wpos 0 (poll fd: 11, events: 3, revents: 11)
[27/04 15:04:46.571 main]: start writev handle 7, iiov 1, len 119
[27/04 15:04:46.572 AD0]: Read NOK -1 (rlen:0/total:72192) bytes from 11 [s: 11 m: 11] -> 0x55555591b510 (buf: 0x55555591b510) - iteration 216 action 0x55555556c5bb
[27/04 15:04:46.573 main]: writev returned 119 handle 7, iiov 1, len 119 (took 0 ms)
[27/04 15:04:46.573 main]: socketworks.c:544 Unlock disabled mutex 0x5555559a9c78
[27/04 15:04:46.574 main]: sockets_unlock: Changing socket 7 lock 0x5555559a9c78 to NULL error -1 Success
[27/04 15:04:46.574 main]: event on socket index 10 handle -1 type 6 spos 0 wpos 0 (poll fd: 9, events: 3, revents: 1)
[27/04 15:04:46.575 main]: Read NOK -1 (rlen:0/total:2000) bytes from -1 [s: 10 m: 10] -> 0x7fffffffda50 (buf: 0x7fffffffda50) - iteration 7 action 0x55555556d7de
[27/04 15:04:46.575 main]: socketworks.c:550 Unlock disabled mutex 0x555555962578

Thread 1 "minisatip" received signal SIGSEGV, Segmentation fault.
__strlen_sse2 () at ../sysdeps/x86_64/multiarch/../strlen.S:120
120 ../sysdeps/x86_64/multiarch/../strlen.S: No such file or directory.
(gdb) c
Continuing.
RECEIVED SIGNAL 11 - SP=0 IP=0
Obtained 10 stack frames.
?? ??:0
?? ??:0
?? ??:0
?? ??:0
?? ??:0
?? ??:0
?? ??:0
?? ??:0
?? ??:0
?? ??:0
0x55555557930b : 0x555555579400 : 0x7ffff7bc8890 : 0x7ffff6749646 : 0x7ffff66f54d3 : 0x7ffff6720910 : 0x55555557a0d2 : 0x5555555658ae : 0x5555555611f2 : 0x7ffff66b9b97 : [Thread 0x7ffff1bec700 (LWP 13463) exited]
[Thread 0x7ffff7fcb600 (LWP 11469) exited]
[Inferior 1 (process 11469) exited with code 01]
(gdb)
lars18th commented 4 years ago

Hi @9000h ,

Please, which SAT>IP client are you using? VLC? And minisatip is using the satipc module?

9000h commented 4 years ago

yes for the test it's VLC but also with VDR the crash will happen

lars18th commented 4 years ago

yes for the test it's VLC but also with VDR the crash will happen

And the tuner? A local tuner or a SAT>IP server? Please, share the VLC URL too.

9000h commented 4 years ago

only local tuners in a mix gdb --args ./minisatip -H5:50 -D5 -o 192.168.178.129:2000 -Y 4:dvbt2,5:dvbt2,6:dvbc2,7:dvbc2 -u 0:4-984[-48],1:5-1020[-23],2:6-1056[-88],3:7-1092[-204] -m 0040caa2c79d -l general,http,adapter,stream,socketworks -v socket -f

why not revert the change particular in the first step

-                       if (ss->type == TYPE_RTCP || ss->sock == SOCK_TIMEOUT)
+                       if (ss->sock == SOCK_TIMEOUT)
lars18th commented 4 years ago

Hi @9000h ,

only local tuners in a mix

Then my patches aren't related to this crash, as they target mainly the satipc module.

why not revert the change particular in the first step

-                     if (ss->type == TYPE_RTCP || ss->sock == SOCK_TIMEOUT)
+                     if (ss->sock == SOCK_TIMEOUT)

Perhaps you're rigth and this is the cause of the crash, but we need to found the root cause. Personally I suggest to undo the other part of the patch...

-   return (*rv > 0);
+   // 0 is totally acceptable for UDP
+   return (*rv >= 0);
}

and test it.

lars18th commented 4 years ago

Hi @9000h ,

Any news about this crash?

9000h commented 4 years ago

it's defiantly this one

-                       if (ss->type == TYPE_RTCP || ss->sock == SOCK_TIMEOUT)
+                       if (ss->sock == SOCK_TIMEOUT)
lars18th commented 4 years ago

Hi @9000h ,

it's defiantly this one

-                     if (ss->type == TYPE_RTCP || ss->sock == SOCK_TIMEOUT)
+                     if (ss->sock == SOCK_TIMEOUT)

Then, as I'm not sure if the assumption of @catalinii is true or not, try now this change:

In your crash log I see some errors related to strings. So, if the crash is inside this line, then the problem is with the printed parameters.

Please, try it!

9000h commented 4 years ago

I did try it already with latest git, still the same the RTCP socket got closed and the write to the closed socket triggers the crash.

lars18th commented 4 years ago

Hi @9000h ,

Then that's my conclusion:

So, almost two different ways to solve this crash are possible:

I suspect that the initial idea from @catalinii is to not close the RTCP when read 0. However, then this specific case is required to be handle, as the current code closes it. However, I feel that is a good practice too to add the check for not writing in the RTCP socket if it's closed.

I hope @catalinii will fix this soon. Regards.

catalinii commented 4 years ago

There are multiple problems here: 1) Why the rtcp socket is closed 2) Why a disabled socket is being processed (easy fixable) 3) Why it crashes in LOG

catalinii commented 4 years ago

Can you try the latest commit ?

9000h commented 4 years ago

I did a quick test and it did not crash.

ghost commented 4 years ago

I think we still need to see why rtcp socket is closed

9000h commented 4 years ago

any idea how to track this down

ghost commented 4 years ago

break socketworks.c:650 if ss->type==6 print *ss

If ss->read is sockets_recv you can add break sockets_recv if ss->type==6 See when this method returns 0

9000h commented 4 years ago

hmm, the channels below have some broken ones after RTL If you zap with VLC it will happen (but with the latest git no crash)

#EXTINF:-1,Astra 19.2E RTL
rtsp://192.168.178.129:554/?src=1&freq=12188&sr=27500&pol=h&msys=dvbs&pids=0,17,18,44,163,105,106
#EXTINF:-1,Astra 19.2E Fashion 4K
rtsp://192.168.178.129/?src=1&freq=11111&sr=22000&fec=23&pol=h&msys=dvbs&pids=0,2815,2816,106
#EXTINF:-1,Astra 19.2E HGL teststream
http://192.168.178.129:8080/?src=1&freq=10714.00&pol=h&ro=0.35&msys=dvbs2&mtype=8psk&plts=off&sr=23500&fec=89&pids=0,17,18,20,32,33,36
#EXTINF:-1,Astra 19.2E Puls24 HD http
http://192.168.178.129:8080/?src=1&freq=11670.75&pol=h&msys=dvbs2&sr=22000&fec=23&pids=0,17,18,1279,1283,100
#EXTINF:-1,Astra 19.2E ORF1 HD http
http://192.168.178.129:8080/?src=1&freq=11302&pol=h&msys=dvbs2&sr=22000&fec=23&plts=on&ro=35&pids=0,107,1920,1921,1922,1925
#EXTINF:-1,Astra 19.2E ORF1 HD http satip
http://192.168.178.129:8080/?src=1&freq=11302&pol=h&msys=dvbs2&sr=22000&fec=23&plts=on&ro=35&pids=0,107,1920,1921,1922,1925
#EXTINF:-1,Astra 19.2E ORF1 HD rtsp
rtsp://192.168.178.129:554/?src=1&freq=11302&pol=h&msys=dvbs2&sr=22000&fec=23&plts=on&ro=35&pids=0,107,1920,1921,1922,1925
#EXTINF:-1,ServusTV_HD_Deutschland rtsp satip
[03/05 20:57:08.980 main]: MSG client >> process :
TEARDOWN rtsp://192.168.178.129/stream=1 RTSP/1.0
CSeq: 6
User-Agent: LibVLC/3.0.9.2 (LIVE555 Streaming Media v2020.01.19)
Session: 1804289383

[03/05 20:57:08.980 main]: Updating sid 0 time to 54546, current time 54546
[03/05 20:57:08.980 main]: closing stream sid 0
[03/05 20:57:08.980 main]: Closing RTP sock 9 handle 8
[03/05 20:57:08.987 main]: stream.c:333 get_sid returns NULL for s_id = 0
[03/05 20:57:08.987 main]: close_stream_for_socket: start close_stream_for_socket for id 0 (nil)
[03/05 20:57:08.987 main]: sockets_del: sock 9 -> handle 8, sid 0, overflow bytes 0, allocated 0, used 0, unsend packets 0
[03/05 20:57:08.987 main]: sockets_del: sock 9 Last open socket is at index 12 current_handle 8
[03/05 20:57:08.987 main]: Destroying mutex 0x5555559508b8
[03/05 20:57:08.987 main]: Destroying mutex 0x5555559a9dd8
[03/05 20:57:08.987 main]: Closing RTCP sock 10 handle 9

Thread 1 "minisatip" hit Breakpoint 1, sockets_del (sock=10)
    at socketworks.c:650
650     if (ss->close)
(gdb) print *ss
$1 = {enabled = 1 '\001', mutex = {enabled = 1, mtx = pthread_mutex_t = {
      Type = Recursive, Status = Acquired, possibly with no waiters, 
      Owner ID = 31694, Robust = No, Shared = No, Protocol = None}, 
    state = 1, line = 644, tid = 140737353922048, lock_time = 54553, 
    create_time = 47906, file = 0x5555555b3cd1 "socketworks.c"}, 
  is_enabled = 1 '\001', force_close = 0 '\000', sock = 9, nonblock = 0, 
  sa = {sa = {sa_family = 2, 
      sa_data = "\247=\300\250\262\227\000\000\000\000\000\000\000"}, sin = {
      sin_family = 2, sin_port = 15783, sin_addr = {s_addr = 2545068224}, 
      sin_zero = "\000\000\000\000\000\000\000"}, sin6 = {sin6_family = 2, 
      sin6_port = 15783, sin6_flowinfo = 2545068224, sin6_addr = {__in6_u = {
          __u6_addr8 = '\000' <repeats 15 times>, __u6_addr16 = {0, 0, 0, 0, 
            0, 0, 0, 0}, __u6_addr32 = {0, 0, 0, 0}}}, sin6_scope_id = 0}}, 
  action = 0x55555556d818 <rtcp_confirm>, close = 0x0, timeout = 0x0, 
  read = 0x555555563a5a <sockets_recv>, type = 6, sid = 0, rtime = 49906, 
  wtime = 0, buf = 0x7fffffffda40 "TEARDOWN", opaque = 0x0, opaque2 = 0x0, 
  opaque3 = 0x0, lbuf = 2000, rlen = 48, timeout_ms = 0, id = 10, 
  iteration = 3, err = 0, flags = 0, events = 3, last_poll = 54516, 
  tid = 140737353922048, lock = 0x0, sock_err = 0, pack = 0x0, prio_pack = {
    len = 0, size = 0, buf = 0x0}, flush_enqued_data = 0, spos = 0, 
  wmax = 100, wpos = 0, overflow = 0, buf_alloc = 0, buf_used = 0, 
  master = -1}
(gdb)
ghost commented 4 years ago

This is an occurrence part of stream close. In the logs you've attached initially there is 'close on socket..'

Looking more to know why reading 0 closes the socket

9000h commented 4 years ago

read 0 is also happen on a normal close without any error.

catalinii commented 4 years ago

For tcp yes. Udp does not have the concept of a connection. So writing 0 byteswill make the peerread 0 bytes

lars18th commented 4 years ago

Hi @catalinii and @9000h ,

Please take note of this:

Why the rtcp socket is closed

The RTCP can be closed by some different reasons. For example, because the client doesn't use it. Because some firewall is blocking it. And for other different reasons. In any case, the streaming should continue without RTCP packets. So my suggestion is very simple: if the RTCP socket is closed, then the processing can continue without any modification... but no new RTCP sockets will be sended to the network. This will simplifies the code and make it easy to maintain it. A simple flag can be used for this objective. You agree with that?

Why a disabled socket is being processed (easy fixable)

That's an internal behaviour of the minisatip. Personally, it's quite complex to understand how it works. Perhaps @catalinii can provide a diagram or model about the organization of the threads/modules.

Why it crashes in LOG

I feel they are more bugs related to the LOG functionality. I detected some of them, and I'm fixed them (see my PR #744). But in this particular case I suspect that the problem is not in the log but in the stream threading management. When the RTCP socket is closed, something is changed but the loop over the socket activity doesn't perceive this change. Please @catalinii can you explain how you debug minisatip?

I hope it helps. Regards.

9000h commented 4 years ago

is this still work in progress or can we close here?