Bug #2555
closed
Inverto "8 channel SAT>IP LNB" hanging frequently when accessed by tvheadend
Added by ullix tv over 10 years ago. Updated over 10 years ago.
0%
Description
First, it is still unclear whether the problem is caused by tvheadend, or by the LNB, or by something specific to this combination, but the problem is only observable when accessed by tvheadend!
This problem was not present about 8 weeks ago, but surfaced recently, some 2+ weeks back. Up to this time tvheadend has changed, the LNB has "aged", and it got much colder outside. Anything is possible, electronic, firmwaqre, software.
When tvheadend is started with the tuner online, it takes from 2 to 10 hours before the tuner hangs. Hanging means, I cannot watch live-TV nor record any shows via tvheadend, and trying to access the tuner via a browser results in permanent "Connecting..." message with no connection ever.
Previously this had also resulted in tvheadend itself hanging solidly, but this is no longer true with the recent change by perexg of moving sat>ip code into a separate thread.
This time the tuner hung after about 6h of runtime with tvheadend. the log with trace on satip and httpc is attached.
I am testing availabiliy of the tuner with a script every 1 min via cron by a ping and wget ("/usr/bin/wget --spider -nv -t 1 -T 3"). While the ping continues to work in a hang, the wget times out with a returncode of 4. Here is the relevant segment of the ping/wget log:
15.12.2014 16:13:01 ping_iplnb.py 20769 (tvheadend is running) returncode=0 ping
15.12.2014 16:13:01 ping_iplnb.py 20769 (tvheadend is running) returncode=0 wget
15.12.2014 16:14:01 ping_iplnb.py 20803 (tvheadend is running) returncode=0 ping
15.12.2014 16:14:04 ping_iplnb.py 20803 (tvheadend is running) returncode=4 wget
i.e., sometime between 16:13:01 and 16:14:04 the SAT>IP LNB failed.
At about 16:21 I stopped tvheanded (sudo stop tvheadend)
Files
Updated by Jaroslav Kysela over 10 years ago
2014-12-15 16:13:35.000 [ INFO]:mpegts: 12265.5H in SATIP - tuning on SAT>IP DVB-S Tuner #1 (10.0.0.71) 2014-12-15 16:13:35.000 [ DEBUG]:satip: SAT>IP DVB-S Tuner #1 (10.0.0.71) - starting 12265.5H in SATIP 2014-12-15 16:13:35.000 [ TRACE]:satip: SAT>IP DVB-S Tuner #1 (10.0.0.71) - start 2014-12-15 16:13:35.000 [ INFO]:subscription: 0142: "scan" subscribing to mux, weight: 1, adapter: "SAT>IP DVB-S Tuner #1 (10.0.0.71)", network: "SATIP", mux: "12265.5H", hostname: "<N/A>", username: "<N/A>", client: "<N/A>" 2014-12-15 16:13:35.000 [ TRACE]:satip: SAT>IP DVB-S Tuner #1 (10.0.0.71) - local RTP port 42424 RTCP port 42425 2014-12-15 16:13:35.000 [ TRACE]:httpc: Connected to 10.0.0.71:554 2014-12-15 16:13:35.000 [ TRACE]:satip: setup params - src=1&fe=1&freq=12265.5&sr=27500&msys=dvbs&mtype=qpsk&pol=h&fec=34&ro=0.35 2014-12-15 16:13:35.000 [ TRACE]:httpc: sending RTSP/1.0 cmd 2014-12-15 16:13:35.000 [ TRACE]:httpc: 53 45 54 55 50 20 72 74 73 70 3A 2F 2F 31 30 2E SETUP rtsp://10. 2014-12-15 16:13:35.000 [ TRACE]:httpc: 30 2E 30 2E 37 31 2F 3F 73 72 63 3D 31 26 66 65 0.0.71/?src=1&fe 2014-12-15 16:13:35.000 [ TRACE]:httpc: 3D 31 26 66 72 65 71 3D 31 32 32 36 35 2E 35 26 =1&freq=12265.5& 2014-12-15 16:13:35.000 [ TRACE]:httpc: 73 72 3D 32 37 35 30 30 26 6D 73 79 73 3D 64 76 sr=27500&msys=dv 2014-12-15 16:13:35.000 [ TRACE]:httpc: 62 73 26 6D 74 79 70 65 3D 71 70 73 6B 26 70 6F bs&mtype=qpsk&po 2014-12-15 16:13:35.000 [ TRACE]:httpc: 6C 3D 68 26 66 65 63 3D 33 34 26 72 6F 3D 30 2E l=h&fec=34&ro=0. 2014-12-15 16:13:35.000 [ TRACE]:httpc: 33 35 20 52 54 53 50 2F 31 2E 30 0D 0A 54 72 61 35 RTSP/1.0..Tra 2014-12-15 16:13:35.000 [ TRACE]:httpc: 6E 73 70 6F 72 74 3A 20 52 54 50 2F 41 56 50 3B nsport: RTP/AVP; 2014-12-15 16:13:35.000 [ TRACE]:httpc: 75 6E 69 63 61 73 74 3B 63 6C 69 65 6E 74 5F 70 unicast;client_p 2014-12-15 16:13:35.000 [ TRACE]:httpc: 6F 72 74 3D 34 32 34 32 34 2D 34 32 34 32 35 0D ort=42424-42425. 2014-12-15 16:13:35.000 [ TRACE]:httpc: 0A 43 53 65 71 3A 20 31 0D 0A 0D 0A .CSeq: 1.... 2014-12-15 16:13:35.003 [ TRACE]:httpc: received RTSP/1.0 answer 2014-12-15 16:13:35.003 [ TRACE]:httpc: 52 54 53 50 2F 31 2E 30 20 32 30 30 20 4F 4B 0D RTSP/1.0 200 OK. 2014-12-15 16:13:35.003 [ TRACE]:httpc: 0A 43 53 65 71 3A 20 31 0D 0A 44 61 74 65 3A 20 .CSeq: 1..Date: 2014-12-15 16:13:35.003 [ TRACE]:httpc: 4D 6F 6E 2C 20 31 35 20 44 65 63 20 32 30 31 34 Mon, 15 Dec 2014 2014-12-15 16:13:35.003 [ TRACE]:httpc: 20 31 35 3A 31 33 3A 32 31 20 47 4D 54 0D 0A 54 15:13:21 GMT..T 2014-12-15 16:13:35.003 [ TRACE]:httpc: 72 61 6E 73 70 6F 72 74 3A 20 52 54 50 2F 41 56 ransport: RTP/AV 2014-12-15 16:13:35.003 [ TRACE]:httpc: 50 3B 75 6E 69 63 61 73 74 3B 64 65 73 74 69 6E P;unicast;destin 2014-12-15 16:13:35.003 [ TRACE]:httpc: 61 74 69 6F 6E 3D 31 30 2E 30 2E 30 2E 32 30 3B ation=10.0.0.20; 2014-12-15 16:13:35.003 [ TRACE]:httpc: 73 6F 75 72 63 65 3D 31 30 2E 30 2E 30 2E 37 31 source=10.0.0.71 2014-12-15 16:13:35.003 [ TRACE]:httpc: 3B 63 6C 69 65 6E 74 5F 70 6F 72 74 3D 34 32 34 ;client_port=424 2014-12-15 16:13:35.003 [ TRACE]:httpc: 32 34 2D 34 32 34 32 35 3B 73 65 72 76 65 72 5F 24-42425;server_ 2014-12-15 16:13:35.003 [ TRACE]:httpc: 70 6F 72 74 3D 31 35 33 39 38 2D 31 35 33 39 39 port=15398-15399 2014-12-15 16:13:35.003 [ TRACE]:httpc: 0D 0A 53 65 73 73 69 6F 6E 3A 20 31 36 32 44 33 ..Session: 162D3 2014-12-15 16:13:35.003 [ TRACE]:httpc: 45 42 33 3B 74 69 6D 65 6F 75 74 3D 36 30 0D 0A EB3;timeout=60.. 2014-12-15 16:13:35.003 [ TRACE]:httpc: 63 6F 6D 2E 73 65 73 2E 73 74 72 65 61 6D 49 44 com.ses.streamID 2014-12-15 16:13:35.003 [ TRACE]:httpc: 3A 20 32 36 39 39 0D 0A 0D 0A : 2699.... 2014-12-15 16:13:35.003 [ TRACE]:httpc: RTSP/1.0 answer 'RTSP/1.0 200 OK' 2014-12-15 16:13:35.003 [ DEBUG]:satip: 10.0.0.71 #1 - new session 162D3EB3 stream id 2699 2014-12-15 16:13:35.003 [ TRACE]:httpc: sending RTSP/1.0 cmd 2014-12-15 16:13:35.003 [ TRACE]:httpc: 50 4C 41 59 20 72 74 73 70 3A 2F 2F 31 30 2E 30 PLAY rtsp://10.0 2014-12-15 16:13:35.003 [ TRACE]:httpc: 2E 30 2E 37 31 2F 73 74 72 65 61 6D 3D 32 36 39 .0.71/stream=269 2014-12-15 16:13:35.003 [ TRACE]:httpc: 39 3F 70 69 64 73 3D 31 38 20 52 54 53 50 2F 31 9?pids=18 RTSP/1 2014-12-15 16:13:35.003 [ TRACE]:httpc: 2E 30 0D 0A 53 65 73 73 69 6F 6E 3A 20 31 36 32 .0..Session: 162 2014-12-15 16:13:35.003 [ TRACE]:httpc: 44 33 45 42 33 0D 0A 43 53 65 71 3A 20 32 0D 0A D3EB3..CSeq: 2.. 2014-12-15 16:13:35.003 [ TRACE]:httpc: 0D 0A .. 2014-12-15 16:13:35.022 [ TRACE]:httpc: received RTSP/1.0 answer 2014-12-15 16:13:35.022 [ TRACE]:httpc: 52 54 53 50 2F 31 2E 30 20 32 30 30 20 4F 4B 0D RTSP/1.0 200 OK. 2014-12-15 16:13:35.022 [ TRACE]:httpc: 0A 43 53 65 71 3A 20 32 0D 0A 53 65 73 73 69 6F .CSeq: 2..Sessio 2014-12-15 16:13:35.022 [ TRACE]:httpc: 6E 3A 20 31 36 32 44 33 45 42 33 0D 0A 52 54 50 n: 162D3EB3..RTP 2014-12-15 16:13:35.022 [ TRACE]:httpc: 2D 49 6E 66 6F 3A 20 75 72 6C 3D 72 74 73 70 3A -Info: url=rtsp: 2014-12-15 16:13:35.022 [ TRACE]:httpc: 2F 2F 31 30 2E 30 2E 30 2E 37 31 2F 73 74 72 65 //10.0.0.71/stre 2014-12-15 16:13:35.022 [ TRACE]:httpc: 61 6D 3D 32 36 39 39 3B 73 65 71 3D 31 38 33 37 am=2699;seq=1837 2014-12-15 16:13:35.022 [ TRACE]:httpc: 32 3B 72 74 70 74 69 6D 65 3D 31 34 31 38 36 35 2;rtptime=141865 2014-12-15 16:13:35.022 [ TRACE]:httpc: 36 34 30 31 0D 0A 44 61 74 65 3A 20 4D 6F 6E 2C 6401..Date: Mon, 2014-12-15 16:13:35.022 [ TRACE]:httpc: 20 31 35 20 44 65 63 20 32 30 31 34 20 31 35 3A 15 Dec 2014 15: 2014-12-15 16:13:35.022 [ TRACE]:httpc: 31 33 3A 32 31 20 47 4D 54 0D 0A 52 61 6E 67 65 13:21 GMT..Range 2014-12-15 16:13:35.022 [ TRACE]:httpc: 3A 20 6E 70 74 3D 30 2E 30 30 30 2D 0D 0A 0D 0A : npt=0.000-.... 2014-12-15 16:13:35.022 [ TRACE]:httpc: RTSP/1.0 answer 'RTSP/1.0 200 OK' 2014-12-15 16:13:35.061 [ TRACE]:httpc: sending RTSP/1.0 cmd 2014-12-15 16:13:35.061 [ TRACE]:httpc: 50 4C 41 59 20 72 74 73 70 3A 2F 2F 31 30 2E 30 PLAY rtsp://10.0 2014-12-15 16:13:35.061 [ TRACE]:httpc: 2E 30 2E 37 31 2F 73 74 72 65 61 6D 3D 32 36 39 .0.71/stream=269 2014-12-15 16:13:35.061 [ TRACE]:httpc: 39 3F 61 64 64 70 69 64 73 3D 30 2C 31 2C 31 36 9?addpids=0,1,16 2014-12-15 16:13:35.061 [ TRACE]:httpc: 2C 31 37 20 52 54 53 50 2F 31 2E 30 0D 0A 53 65 ,17 RTSP/1.0..Se 2014-12-15 16:13:35.061 [ TRACE]:httpc: 73 73 69 6F 6E 3A 20 31 36 32 44 33 45 42 33 0D ssion: 162D3EB3. 2014-12-15 16:13:35.061 [ TRACE]:httpc: 0A 43 53 65 71 3A 20 33 0D 0A 0D 0A .CSeq: 3.... 2014-12-15 16:13:35.061 [ TRACE]:satip: Status string: 'ver=1.0;src=1;tuner=1,0,0,0,12265,h,dvbs,,,,27500,34;pids=18' 2014-12-15 16:13:35.233 [ TRACE]:httpc: received RTSP/1.0 answer 2014-12-15 16:13:35.233 [ TRACE]:httpc: 52 54 53 50 2F 31 2E 30 20 32 30 30 20 4F 4B 0D RTSP/1.0 200 OK. 2014-12-15 16:13:35.233 [ TRACE]:httpc: 0A 43 53 65 71 3A 20 33 0D 0A 53 65 73 73 69 6F .CSeq: 3..Sessio 2014-12-15 16:13:35.233 [ TRACE]:httpc: 6E 3A 20 31 36 32 44 33 45 42 33 0D 0A 52 54 50 n: 162D3EB3..RTP 2014-12-15 16:13:35.233 [ TRACE]:httpc: 2D 49 6E 66 6F 3A 20 75 72 6C 3D 72 74 73 70 3A -Info: url=rtsp: 2014-12-15 16:13:35.233 [ TRACE]:httpc: 2F 2F 31 30 2E 30 2E 30 2E 37 31 2F 73 74 72 65 //10.0.0.71/stre 2014-12-15 16:13:35.233 [ TRACE]:httpc: 61 6D 3D 32 36 39 39 3B 73 65 71 3D 31 38 33 37 am=2699;seq=1837 2014-12-15 16:13:35.233 [ TRACE]:httpc: 32 3B 72 74 70 74 69 6D 65 3D 31 34 31 38 36 35 2;rtptime=141865 2014-12-15 16:13:35.233 [ TRACE]:httpc: 36 34 30 31 0D 0A 44 61 74 65 3A 20 4D 6F 6E 2C 6401..Date: Mon, 2014-12-15 16:13:35.233 [ TRACE]:httpc: 20 31 35 20 44 65 63 20 32 30 31 34 20 31 35 3A 15 Dec 2014 15: 2014-12-15 16:13:35.233 [ TRACE]:httpc: 31 33 3A 32 31 20 47 4D 54 0D 0A 52 61 6E 67 65 13:21 GMT..Range 2014-12-15 16:13:35.233 [ TRACE]:httpc: 3A 20 6E 70 74 3D 30 2E 30 30 30 2D 0D 0A 0D 0A : npt=0.000-.... 2014-12-15 16:13:35.233 [ TRACE]:httpc: RTSP/1.0 answer 'RTSP/1.0 200 OK' 2014-12-15 16:13:35.267 [ TRACE]:satip: Status string: 'ver=1.0;src=1;tuner=1,0,0,0,12265,h,dvbs,qpsk,,,27500,34;pids=0,1,16,17,18' 2014-12-15 16:13:35.469 [ TRACE]:satip: Status string: 'ver=1.0;src=1;tuner=1,0,0,0,12265,h,dvbs,qpsk,,,27500,34;pids=0,1,16,17,18' 2014-12-15 16:13:35.671 [ TRACE]:httpc: sending RTSP/1.0 cmd 2014-12-15 16:13:35.671 [ TRACE]:httpc: 50 4C 41 59 20 72 74 73 70 3A 2F 2F 31 30 2E 30 PLAY rtsp://10.0 2014-12-15 16:13:35.671 [ TRACE]:httpc: 2E 30 2E 37 31 2F 73 74 72 65 61 6D 3D 32 36 39 .0.71/stream=269 2014-12-15 16:13:35.671 [ TRACE]:httpc: 39 3F 70 69 64 73 3D 61 6C 6C 20 52 54 53 50 2F 9?pids=all RTSP/ 2014-12-15 16:13:35.671 [ TRACE]:httpc: 31 2E 30 0D 0A 53 65 73 73 69 6F 6E 3A 20 31 36 1.0..Session: 16 2014-12-15 16:13:35.671 [ TRACE]:httpc: 32 44 33 45 42 33 0D 0A 43 53 65 71 3A 20 34 0D 2D3EB3..CSeq: 4. 2014-12-15 16:13:35.671 [ TRACE]:httpc: 0A 0D 0A ... 2014-12-15 16:13:35.671 [ TRACE]:satip: Status string: 'ver=1.0;src=1;tuner=1,0,0,0,12265,h,dvbs,qpsk,,,27500,34;pids=0,1,16,17,18' 2014-12-15 16:13:35.684 [ TRACE]:httpc: received RTSP/1.0 answer 2014-12-15 16:13:35.684 [ TRACE]:httpc: 52 54 53 50 2F 31 2E 30 20 32 30 30 20 4F 4B 0D RTSP/1.0 200 OK. 2014-12-15 16:13:35.684 [ TRACE]:httpc: 0A 43 53 65 71 3A 20 34 0D 0A 53 65 73 73 69 6F .CSeq: 4..Sessio 2014-12-15 16:13:35.684 [ TRACE]:httpc: 6E 3A 20 31 36 32 44 33 45 42 33 0D 0A 52 54 50 n: 162D3EB3..RTP 2014-12-15 16:13:35.684 [ TRACE]:httpc: 2D 49 6E 66 6F 3A 20 75 72 6C 3D 72 74 73 70 3A -Info: url=rtsp: 2014-12-15 16:13:35.684 [ TRACE]:httpc: 2F 2F 31 30 2E 30 2E 30 2E 37 31 2F 73 74 72 65 //10.0.0.71/stre 2014-12-15 16:13:35.684 [ TRACE]:httpc: 61 6D 3D 32 36 39 39 3B 73 65 71 3D 31 38 33 37 am=2699;seq=1837 2014-12-15 16:13:35.684 [ TRACE]:httpc: 32 3B 72 74 70 74 69 6D 65 3D 31 34 31 38 36 35 2;rtptime=141865 2014-12-15 16:13:35.684 [ TRACE]:httpc: 36 34 30 31 0D 0A 44 61 74 65 3A 20 4D 6F 6E 2C 6401..Date: Mon, 2014-12-15 16:13:35.684 [ TRACE]:httpc: 20 31 35 20 44 65 63 20 32 30 31 34 20 31 35 3A 15 Dec 2014 15: 2014-12-15 16:13:35.684 [ TRACE]:httpc: 31 33 3A 32 31 20 47 4D 54 0D 0A 52 61 6E 67 65 13:21 GMT..Range 2014-12-15 16:13:35.684 [ TRACE]:httpc: 3A 20 6E 70 74 3D 30 2E 30 30 30 2D 0D 0A 0D 0A : npt=0.000-.... 2014-12-15 16:13:35.684 [ TRACE]:httpc: RTSP/1.0 answer 'RTSP/1.0 200 OK' 2014-12-15 16:13:35.872 [ TRACE]:satip: Status string: 'ver=1.0;src=1;tuner=1,0,0,0,12265,h,dvbs,qpsk,,,27500,34;pids=all' 2014-12-15 16:13:36.072 [ TRACE]:satip: Status string: 'ver=1.0;src=1;tuner=1,0,0,0,12265,h,dvbs,qpsk,,,27500,34;pids=all' 2014-12-15 16:13:36.272 [ TRACE]:satip: Status string: 'ver=1.0;src=1;tuner=1,0,0,0,12265,h,dvbs,qpsk,,,27500,34;pids=all' 2014-12-15 16:13:36.473 [ TRACE]:satip: Status string: 'ver=1.0;src=1;tuner=1,161,1,14,12265,h,dvbs,qpsk,,,27500,34;pids=all' 2014-12-15 16:13:36.673 [ TRACE]:satip: Status string: 'ver=1.0;src=1;tuner=1,161,1,14,12265,h,dvbs,qpsk,,,27500,34;pids=all' 2014-12-15 16:13:36.873 [ TRACE]:satip: Status string: 'ver=1.0;src=1;tuner=1,161,1,14,12265,h,dvbs,qpsk,,,27500,34;pids=all' 2014-12-15 16:13:37.073 [ TRACE]:satip: Status string: 'ver=1.0;src=1;tuner=1,161,1,14,12265,h,dvbs,qpsk,,,27500,34;pids=all' 2014-12-15 16:13:45.000 [ INFO]:mpegts: 12265.5H in SATIP - scan needs more time 2014-12-15 16:14:05.000 [ INFO]:mpegts: 12265.5H in SATIP - scan timed out 2014-12-15 16:14:05.000 [ INFO]:subscription: 0142: "scan" unsubscribing 2014-12-15 16:14:05.000 [ DEBUG]:satip: SAT>IP DVB-S Tuner #1 (10.0.0.71) - stopping 12265.5H in SATIP 2014-12-15 16:14:05.000 [ TRACE]:satip: SAT>IP DVB-S Tuner #1 (10.0.0.71) - input thread received mux close 2014-12-15 16:14:05.000 [ TRACE]:httpc: sending RTSP/1.0 cmd 2014-12-15 16:14:05.000 [ TRACE]:httpc: 54 45 41 52 44 4F 57 4E 20 72 74 73 70 3A 2F 2F TEARDOWN rtsp:// 2014-12-15 16:14:05.000 [ TRACE]:httpc: 31 30 2E 30 2E 30 2E 37 31 2F 73 74 72 65 61 6D 10.0.0.71/stream 2014-12-15 16:14:05.000 [ TRACE]:httpc: 3D 32 36 39 39 20 52 54 53 50 2F 31 2E 30 0D 0A =2699 RTSP/1.0.. 2014-12-15 16:14:05.000 [ TRACE]:httpc: 53 65 73 73 69 6F 6E 3A 20 31 36 32 44 33 45 42 Session: 162D3EB 2014-12-15 16:14:05.000 [ TRACE]:httpc: 33 0D 0A 43 53 65 71 3A 20 35 0D 0A 0D 0A 3..CSeq: 5....
Some analysis: Up to time 2014-12-15 16:13:37.073 is everything good. After this time the box is dead (the satip: Status string messages should be logged each 200ms - these UDP status packets are required from the SAT>IP specification). Note that tvheadend doesn't do any action at this time - just waits for data next 28 seconds. At 2014-12-15 16:14:05.000, the shutdown attempt was made, but unsuccessful (box is dead). After this time no replies are received from the box. The box == your LNB.
As you can see, the session was setup correctly, PIDs were set and added and then changed to all PIDs (because the limit was reached). Note that there was a signal lock before box was unresponsible.
Unfortunately, I think that it's an issue with the firmware or hardware.
Could you write an e-mail to inverto (send me CC: to e-mail perex at perex dot cz) and even send me their replies (if they are relavant to tvheadend)?
The support e-mail for inverto is stb.support at inverto dot tv .. (There is dot between stb and support.)
Updated by Marc Postema over 10 years ago
Hello,
I have a question about what:
Jaroslav Kysela wrote:
[...]
As you can see, the session was setup correctly, PIDs were set and added and then changed to all PIDs (because the limit was reached). Note that there was a signal lock before box was unresponsible.
What does limit reached mean? What limit is this?
Thanks for any answers and Regards,
Marc
Updated by Jaroslav Kysela over 10 years ago
Marc Postema wrote:
Hello,
I have a question about what:
Jaroslav Kysela wrote:
[...]
As you can see, the session was setup correctly, PIDs were set and added and then changed to all PIDs (because the limit was reached). Note that there was a signal lock before box was unresponsible.
What does limit reached mean? What limit is this?
It's maximum count (limit) of PID filters supported by SAT>IP server. Usually (at least for Inverto IDL400s, GSS.BOX and compatible) it's 32 (this number can be changed in the frontend config for tvheadend).
Updated by ullix tv over 10 years ago
I have run this again up to the next hang, this time with the "Double RTSP Shutdown" in the IPLNB settings enabled (had been disabled so far). If I am not mistaken, the result is the very same - the IPLNB suddenly stops working between 22:37:51 and 22:38:14 with tvh doing nothing but reading status strings?
What does the INFO at 22:38:14.000 "scan timed out" mean? Had a scan been attempted, or is it just the report of a timeout with perhaps a not quite correct description?
2014-12-15 22:37:50.108 [ TRACE]:satip: Status string: 'ver=1.0;src=1;tuner=1,142,1,12,11361,h,dvbs2,8psk,on,0.35,22000,23;pids=0,1,16,17,18,6100,6300,6400' 2014-12-15 22:37:50.316 [ TRACE]:satip: Status string: 'ver=1.0;src=1;tuner=1,142,1,12,11361,h,dvbs2,8psk,on,0.35,22000,23;pids=0,1,16,17,18,6100,6300,6400' 2014-12-15 22:37:50.516 [ TRACE]:satip: Status string: 'ver=1.0;src=1;tuner=1,142,1,12,11361,h,dvbs2,8psk,on,0.35,22000,23;pids=0,1,16,17,18,6100,6300,6400' 2014-12-15 22:37:50.720 [ TRACE]:satip: Status string: 'ver=1.0;src=1;tuner=1,142,1,12,11361,h,dvbs2,8psk,on,0.35,22000,23;pids=0,1,16,17,18,6100,6300,6400' 2014-12-15 22:37:50.924 [ TRACE]:satip: Status string: 'ver=1.0;src=1;tuner=1,142,1,12,11361,h,dvbs2,8psk,on,0.35,22000,23;pids=0,1,16,17,18,6100,6300,6400' 2014-12-15 22:37:51.128 [ TRACE]:satip: Status string: 'ver=1.0;src=1;tuner=1,142,1,12,11361,h,dvbs2,8psk,on,0.35,22000,23;pids=0,1,16,17,18,6100,6300,6400' 2014-12-15 22:38:14.000 [ INFO]:mpegts: 11361.75H in SATIP - scan timed out 2014-12-15 22:38:14.000 [ INFO]:subscription: 0285: "scan" unsubscribing 2014-12-15 22:38:14.000 [ DEBUG]:satip: SAT>IP DVB-S Tuner #1 (10.0.0.71) - stopping 11361.75H in SATIP 2014-12-15 22:38:14.000 [ TRACE]:satip: SAT>IP DVB-S Tuner #1 (10.0.0.71) - input thread received mux close 2014-12-15 22:38:14.000 [ TRACE]:httpc: sending RTSP/1.0 cmd 2014-12-15 22:38:14.000 [ TRACE]:httpc: 54 45 41 52 44 4F 57 4E 20 72 74 73 70 3A 2F 2F TEARDOWN rtsp:// 2014-12-15 22:38:14.000 [ TRACE]:httpc: 31 30 2E 30 2E 30 2E 37 31 2F 73 74 72 65 61 6D 10.0.0.71/stream 2014-12-15 22:38:14.000 [ TRACE]:httpc: 3D 36 34 35 20 52 54 53 50 2F 31 2E 30 0D 0A 53 =645 RTSP/1.0..S 2014-12-15 22:38:14.000 [ TRACE]:httpc: 65 73 73 69 6F 6E 3A 20 31 43 37 35 42 41 44 35 ession: 1C75BAD5 2014-12-15 22:38:14.000 [ TRACE]:httpc: 0D 0A 43 53 65 71 3A 20 35 0D 0A 0D 0A ..CSeq: 5.... 2014-12-15 22:38:14.250 [ TRACE]:httpc: sending RTSP/1.0 cmd 2014-12-15 22:38:14.250 [ TRACE]:httpc: 54 45 41 52 44 4F 57 4E 20 72 74 73 70 3A 2F 2F TEARDOWN rtsp:// 2014-12-15 22:38:14.250 [ TRACE]:httpc: 31 30 2E 30 2E 30 2E 37 31 2F 73 74 72 65 61 6D 10.0.0.71/stream 2014-12-15 22:38:14.250 [ TRACE]:httpc: 3D 36 34 35 20 52 54 53 50 2F 31 2E 30 0D 0A 53 =645 RTSP/1.0..S 2014-12-15 22:38:14.250 [ TRACE]:httpc: 65 73 73 69 6F 6E 3A 20 31 43 37 35 42 41 44 35 ession: 1C75BAD5 2014-12-15 22:38:14.250 [ TRACE]:httpc: 0D 0A 43 53 65 71 3A 20 36 0D 0A 0D 0A ..CSeq: 6.... 2014-12-15 22:38:24.000 [ INFO]:mpegts: 11493.75H in SATIP - tuning on SAT>IP DVB-S Tuner #1 (10.0.0.71) 2014-12-15 22:38:24.000 [ DEBUG]:satip: SAT>IP DVB-S Tuner #1 (10.0.0.71) - starting 11493.75H in SATIP 2014-12-15 22:38:24.000 [ INFO]:subscription: 0286: "scan" subscribing to mux, weight: 1, adapter: "SAT>IP DVB-S Tuner #1 (10.0.0.71)", network: "SATIP", mux: "11493.75H", hostname: "<N/A>", username: "<N/A>", client: "<N/A>" 2014-12-15 22:38:24.000 [ TRACE]:satip: SAT>IP DVB-S Tuner #1 (10.0.0.71) - start 2014-12-15 22:38:24.000 [ TRACE]:satip: SAT>IP DVB-S Tuner #1 (10.0.0.71) - local RTP port 54136 RTCP port 54137 2014-12-15 22:38:24.000 [ TRACE]:httpc: Connected to 10.0.0.71:554 2014-12-15 22:38:24.000 [ TRACE]:satip: setup params - src=1&fe=1&freq=11493.75&sr=22000&msys=dvbs2&mtype=8psk&pol=h&fec=23&ro=0.35&plts=on 2014-12-15 22:38:24.000 [ TRACE]:httpc: sending RTSP/1.0 cmd 2014-12-15 22:38:24.000 [ TRACE]:httpc: 53 45 54 55 50 20 72 74 73 70 3A 2F 2F 31 30 2E SETUP rtsp://10. 2014-12-15 22:38:24.000 [ TRACE]:httpc: 30 2E 30 2E 37 31 2F 3F 73 72 63 3D 31 26 66 65 0.0.71/?src=1&fe 2014-12-15 22:38:24.000 [ TRACE]:httpc: 3D 31 26 66 72 65 71 3D 31 31 34 39 33 2E 37 35 =1&freq=11493.75 2014-12-15 22:38:24.000 [ TRACE]:httpc: 26 73 72 3D 32 32 30 30 30 26 6D 73 79 73 3D 64 &sr=22000&msys=d 2014-12-15 22:38:24.000 [ TRACE]:httpc: 76 62 73 32 26 6D 74 79 70 65 3D 38 70 73 6B 26 vbs2&mtype=8psk& 2014-12-15 22:38:24.000 [ TRACE]:httpc: 70 6F 6C 3D 68 26 66 65 63 3D 32 33 26 72 6F 3D pol=h&fec=23&ro= 2014-12-15 22:38:24.000 [ TRACE]:httpc: 30 2E 33 35 26 70 6C 74 73 3D 6F 6E 20 52 54 53 0.35&plts=on RTS 2014-12-15 22:38:24.000 [ TRACE]:httpc: 50 2F 31 2E 30 0D 0A 54 72 61 6E 73 70 6F 72 74 P/1.0..Transport 2014-12-15 22:38:24.000 [ TRACE]:httpc: 3A 20 52 54 50 2F 41 56 50 3B 75 6E 69 63 61 73 : RTP/AVP;unicas 2014-12-15 22:38:24.000 [ TRACE]:httpc: 74 3B 63 6C 69 65 6E 74 5F 70 6F 72 74 3D 35 34 t;client_port=54 2014-12-15 22:38:24.000 [ TRACE]:httpc: 31 33 36 2D 35 34 31 33 37 0D 0A 43 53 65 71 3A 136-54137..CSeq: 2014-12-15 22:38:24.000 [ TRACE]:httpc: 20 31 0D 0A 0D 0A 1.... 2014-12-15 22:38:34.000 [ INFO]:mpegts: 11493.75H in SATIP - scan no data, failed 2014-12-15 22:38:34.000 [ INFO]:subscription: 0286: "scan" unsubscribing 2014-12-15 22:38:34.000 [ DEBUG]:satip: SAT>IP DVB-S Tuner #1 (10.0.0.71) - stopping 11493.75H in SATIP 2014-12-15 22:38:34.000 [ TRACE]:satip: SAT>IP DVB-S Tuner #1 (10.0.0.71) - input thread received mux close 2014-12-15 22:38:35.000 [WARNING]:mpegts: 10920.75H in SATIP - not enabled 2014-12-15 22:38:35.000 [WARNING]:mpegts: 12460.5H in SATIP - not enabled 2014-12-15 22:38:35.000 [WARNING]:mpegts: 12148.5H in SATIP - not enabled 2014-12-15 22:38:44.000 [ INFO]:mpegts: 12265.5H in SATIP - tuning on SAT>IP DVB-S Tuner #1 (10.0.0.71) 2014-12-15 22:38:44.000 [ DEBUG]:satip: SAT>IP DVB-S Tuner #1 (10.0.0.71) - starting 12265.5H in SATIP 2014-12-15 22:38:44.000 [ INFO]:subscription: 0287: "scan" subscribing to mux, weight: 1, adapter: "SAT>IP DVB-S Tuner #1 (10.0.0.71)", network: "SATIP", mux: "12265.5H", hostname: "<N/A>", username: "<N/A>", client: "<N/A>" 2014-12-15 22:38:44.000 [ TRACE]:satip: SAT>IP DVB-S Tuner #1 (10.0.0.71) - local RTP port 42254 RTCP port 42255 2014-12-15 22:38:44.000 [ TRACE]:satip: SAT>IP DVB-S Tuner #1 (10.0.0.71) - last tune diff = 0 (delay = 2000) 2014-12-15 22:38:46.004 [ TRACE]:httpc: Connected to 10.0.0.71:554 2014-12-15 22:38:46.004 [ TRACE]:satip: setup params - src=1&fe=1&freq=12265.5&sr=27500&msys=dvbs&mtype=qpsk&pol=h&fec=34&ro=0.35 2014-12-15 22:38:46.004 [ TRACE]:httpc: sending RTSP/1.0 cmd 2014-12-15 22:38:46.004 [ TRACE]:httpc: 53 45 54 55 50 20 72 74 73 70 3A 2F 2F 31 30 2E SETUP rtsp://10. 2014-12-15 22:38:46.004 [ TRACE]:httpc: 30 2E 30 2E 37 31 2F 3F 73 72 63 3D 31 26 66 65 0.0.71/?src=1&fe 2014-12-15 22:38:46.004 [ TRACE]:httpc: 3D 31 26 66 72 65 71 3D 31 32 32 36 35 2E 35 26 =1&freq=12265.5& 2014-12-15 22:38:46.004 [ TRACE]:httpc: 73 72 3D 32 37 35 30 30 26 6D 73 79 73 3D 64 76 sr=27500&msys=dv 2014-12-15 22:38:46.004 [ TRACE]:httpc: 62 73 26 6D 74 79 70 65 3D 71 70 73 6B 26 70 6F bs&mtype=qpsk&po 2014-12-15 22:38:46.004 [ TRACE]:httpc: 6C 3D 68 26 66 65 63 3D 33 34 26 72 6F 3D 30 2E l=h&fec=34&ro=0. 2014-12-15 22:38:46.004 [ TRACE]:httpc: 33 35 20 52 54 53 50 2F 31 2E 30 0D 0A 54 72 61 35 RTSP/1.0..Tra 2014-12-15 22:38:46.004 [ TRACE]:httpc: 6E 73 70 6F 72 74 3A 20 52 54 50 2F 41 56 50 3B nsport: RTP/AVP; 2014-12-15 22:38:46.004 [ TRACE]:httpc: 75 6E 69 63 61 73 74 3B 63 6C 69 65 6E 74 5F 70 unicast;client_p 2014-12-15 22:38:46.004 [ TRACE]:httpc: 6F 72 74 3D 34 32 32 35 34 2D 34 32 32 35 35 0D ort=42254-42255. 2014-12-15 22:38:46.004 [ TRACE]:httpc: 0A 43 53 65 71 3A 20 31 0D 0A 0D 0A .CSeq: 1.... 2014-12-15 22:38:54.000 [ INFO]:mpegts: 12265.5H in SATIP - scan no data, failed
Updated by Jaroslav Kysela over 10 years ago
ullix tv wrote:
I have run this again up to the next hang, this time with the "Double RTSP Shutdown" in the IPLNB settings enabled (had been disabled so far).
I don't think that Double RTSP Shutdown is required...
If I am not mistaken, the result is the very same - the IPLNB suddenly stops working between 22:37:51 and 22:38:14 with tvh doing nothing but reading status strings?
Correct.
What does the INFO at 22:38:14.000 "scan timed out" mean? Had a scan been attempted, or is it just the report of a timeout with perhaps a not quite correct description?
"scan timed out" means that no sufficient data were received to complete the mux scan in the defined time window (approx 30 seconds). The description is correct.
Updated by ullix tv over 10 years ago
- File tuner-failure tuner-failure added
This thing is really odd. About 10 days ago I noticed that way too many services were associated with just one single mux, and actually belonged to different muxes. The configuration seemed to be messed up, and I deleted every mux, service and channel and reconfigured.
After that, instead of the IP-LNB freezing every couple of hours, it lasted 3-5 days. Which may suggest that some wrong config of tvheadend is resulting in commands to the IP-LNB, which confuses the IP-LNB into a hang. Still shouldn't happen on the IP-LNB side, that a wrong command hangs it, but what is it?
I have now again experienced another hang. The log file now grows into the gigabytes, so I am attaching an excerpt. My ping/wget probe said it was working at 4:14:01 and failing at 4:15:04
29.12.2014 04:14:01 ping_iplnb.py 17635 (tvheadend is running) returncode=0 wget 29.12.2014 04:15:04 ping_iplnb.py 17650 (tvheadend is running) returncode=4 wget
Judging from the tvh.log I think the failure occured after 04:15:01.036 and 04:15:58.000 as after the later time only Warnings were logged for the next 5 hours (when I rebooted the IP-LNB), and no more traces? But shouldn't there be any more httpc or satip traces? So while now tvheadend is continuing, is it possible that the SAT-IP module is now hanging, which it also should not do (I suppose)?
2014-12-29 04:15:01.036 [ TRACE]:satip: Status string: 'ver=1.0;src=1;tuner=3,152,1,13,11347,v,dvbs2,8psk,on,0.35,22000,23;pids=0,1,16,17,18,6500,6510,6520,6521,6522,6523,6530,6531' 2014-12-29 04:15:58.000 [WARNING]:mpegts: 12551.5V in SATIP - not enabled
What more info can be gathered to figure out where/what the bug is?
Updated by Marc Postema over 10 years ago
Hello,
Why are there allways 2 teardown message send? (Can this be switched off?)
And in this trace from above it appears not to wait on a reply (is this way it breaks?):
2014-12-15 22:38:14.000 [ DEBUG]:satip: SAT>IP DVB-S Tuner #1 (10.0.0.71) - stopping 11361.75H in SATIP
2014-12-15 22:38:14.000 [ TRACE]:satip: SAT>IP DVB-S Tuner #1 (10.0.0.71) - input thread received mux close
2014-12-15 22:38:14.000 [ TRACE]:httpc: sending RTSP/1.0 cmd
2014-12-15 22:38:14.000 [ TRACE]:httpc: 54 45 41 52 44 4F 57 4E 20 72 74 73 70 3A 2F 2F TEARDOWN rtsp://
2014-12-15 22:38:14.000 [ TRACE]:httpc: 31 30 2E 30 2E 30 2E 37 31 2F 73 74 72 65 61 6D 10.0.0.71/stream
2014-12-15 22:38:14.000 [ TRACE]:httpc: 3D 36 34 35 20 52 54 53 50 2F 31 2E 30 0D 0A 53 =645 RTSP/1.0..S
2014-12-15 22:38:14.000 [ TRACE]:httpc: 65 73 73 69 6F 6E 3A 20 31 43 37 35 42 41 44 35 ession: 1C75BAD5
2014-12-15 22:38:14.000 [ TRACE]:httpc: 0D 0A 43 53 65 71 3A 20 35 0D 0A 0D 0A ..CSeq: 5....
2014-12-15 22:38:14.250 [ TRACE]:httpc: sending RTSP/1.0 cmd
2014-12-15 22:38:14.250 [ TRACE]:httpc: 54 45 41 52 44 4F 57 4E 20 72 74 73 70 3A 2F 2F TEARDOWN rtsp://
2014-12-15 22:38:14.250 [ TRACE]:httpc: 31 30 2E 30 2E 30 2E 37 31 2F 73 74 72 65 61 6D 10.0.0.71/stream
2014-12-15 22:38:14.250 [ TRACE]:httpc: 3D 36 34 35 20 52 54 53 50 2F 31 2E 30 0D 0A 53 =645 RTSP/1.0..S
2014-12-15 22:38:14.250 [ TRACE]:httpc: 65 73 73 69 6F 6E 3A 20 31 43 37 35 42 41 44 35 ession: 1C75BAD5
2014-12-15 22:38:14.250 [ TRACE]:httpc: 0D 0A 43 53 65 71 3A 20 36 0D 0A 0D 0A ..CSeq: 6....
2014-12-15 22:38:24.000 [ INFO]:mpegts: 11493.75H in SATIP - tuning on SAT>IP DVB-S Tuner #1 (10.0.0.71)
2014-12-15 22:38:24.000 [ DEBUG]:satip: SAT>IP DVB-S Tuner #1 (10.0.0.71) - starting 11493.75H in SATIP
I see this behavior also with my written SAT>IP server for rpi, it does not hang but shows no picture and after this
there is no input detected message in Kodi.
Updated by Jaroslav Kysela over 10 years ago
Marc Postema wrote:
Hello,
Why are there allways 2 teardown message send? (Can this be switched off?)
There is "Double RTSP Shutdown" checkbox in the tuner settings in recent code now..
Updated by Jaroslav Kysela over 10 years ago
ullix tv wrote:
This thing is really odd. About 10 days ago I noticed that way too many services were associated with just one single mux, and actually belonged to different muxes. The configuration seemed to be messed up, and I deleted every mux, service and channel and reconfigured.
After that, instead of the IP-LNB freezing every couple of hours, it lasted 3-5 days. Which may suggest that some wrong config of tvheadend is resulting in commands to the IP-LNB, which confuses the IP-LNB into a hang. Still shouldn't happen on the IP-LNB side, that a wrong command hangs it, but what is it?
Bad firmware.
I have now again experienced another hang. The log file now grows into the gigabytes, so I am attaching an excerpt. My ping/wget probe said it was working at 4:14:01 and failing at 4:15:04
[...]Judging from the tvh.log I think the failure occured after 04:15:01.036 and 04:15:58.000 as after the later time only Warnings were logged for the next 5 hours (when I rebooted the IP-LNB), and no more traces? But shouldn't there be any more httpc or satip traces? So while now tvheadend is continuing, is it possible that the SAT-IP module is now hanging, which it also should not do (I suppose)?
[...]
What more info can be gathered to figure out where/what the bug is?
Upload the log between 04:15:00 and 04:20:00 ..
Updated by Marc Postema over 10 years ago
Jaroslav Kysela wrote:
Marc Postema wrote:
Hello,
Why are there allways 2 teardown message send? (Can this be switched off?)
There is "Double RTSP Shutdown" checkbox in the tuner settings in recent code now..
Thanks for your answer... I thought that I had 'some' recent code... probably not.
Will check it.
Marc
Updated by ullix tv over 10 years ago
- File tvh (Kopie).log tvh (Kopie).log added
- File tvh-screenshot-2014-12-31.png tvh-screenshot-2014-12-31.png added
Jaroslav Kysela wrote:
Upload the log between 04:15:00 and 04:20:00 ..
If you are asking for the log as attached in my post #6, this is deleted. However, as I said in the log excerpt, from 04:15:58.000 onwards it had only the warnings repeated for 5 hours:
2014-12-29 04:15:58.000 [WARNING]:mpegts: 12551.5V in SATIP - not enabled 2014-12-29 04:15:58.000 [WARNING]:mpegts: 12148.5H in SATIP - not enabled 2014-12-29 04:15:58.000 [WARNING]:mpegts: 11111.75H in SATIP - not enabled 2014-12-29 04:15:58.000 [WARNING]:mpegts: 12460.5H in SATIP - not enabled ---after that warning bursts about every minute for next 5 hours
Absolutely nothing else!
Just in case that my daily (at least once) DSL disconnection/reconnection, usually occuring between 4 and 5 am, has anything to do with it, I checked. On the 2014-12-29 the failure occured at 04:15, but the reconnect was 05:49. So had nothing to do with it. Also on other days, DSL reconnections were well separated timewise from IP-LNB failures.
In case you are wondering about anything repeating daily, I am attaching the log for one day (>130MB).
I am now running: HTS Tvheadend 3.9.2275~g066b273~precise (I have frozen the version to avoid uncertainties from changed code)
started with: TVH_ARGS="-d -l /home/ullix/tvh_logs/tvh.log --trace satip,httpc --debug satip,httpc"
and in settings the "double RTSP shutdown" is now disabled
the tuner had been dispowered and reset to factory conditions before starting tvheadend
Since a few days - that is with the "double RTSP shutdown" being either enabled or disabled - I am observing that tuners are left addressed by tvh. Attached screenshot shows it in Stream ( but nothing in Subscription or Connection). It does not seem to do anything. Log file is full of Status strings.
At present system is running for 24 hours.
Updated by Jaroslav Kysela over 10 years ago
Add more log lines '--trace satip,httpc,mpegts,subscription' --debug 'satip,httpc,mpegts,subscription' and try to describe when you think that tvh should stop the streaming (in log), but you see it in the status grid.
Updated by ullix tv over 10 years ago
- File screenshot-inactive streams.png screenshot-inactive streams.png added
- File screenshot-festatus.png screenshot-festatus.png added
- File tvh(idlestreams).log tvh(idlestreams).log added
Jaroslav Kysela wrote:
Add more log lines '--trace satip,httpc,mpegts,subscription' --debug 'satip,httpc,mpegts,subscription' and try to describe when you think that tvh should stop the streaming (in log), but you see it in the status grid.
Done. And I also upgraded tvh to "HTS Tvheadend 3.9.2304~gc1ed929~precise" (which may have been a bad idea)
The "allocation" of tuners, as it seems to be called, while the streams were idle, happened right after restart. I then stopped tvheadend right-away. It actually happened twice in a row! Here are details from the second one:
Log file is attached (1.5MB)
A sreenshot from tvh shows5 tuners doing nothing. A screenshot from ipLNB/festatus is also attached, showing those tuners being "allocated" bot not locked.
Still, this is a bit more serious, as it blocks all 5 tuners from being used for watching/recording! However,tvh can free these tuners, because after stopping tvh, all tuners in festatus became "green, free, not locked".
Updated by Jaroslav Kysela over 10 years ago
I added some more logs to v3.9-2308-g2635a3d . Could you get the latest sources and provide above logs (including status status picture from tvh) ?
The problem is that the epggrab subscriptions override other active epggrab subscriptions which should have same weight (thus the new subscription should fail). But in your situation, the overriden subscription is moved back to the tail of the epggrab queue.
Updated by Marc Postema over 10 years ago
Hello,
I see sometimes that the teardown msg is followed directly by
an setup msg, while the teardown msg is not finished (freeing the fronted that was in use
and requested by the new setup msg)
This will result in my situation in an 503 error which tvh does not like (it maybe could do
a retry, I think).
And a "no input detected" error in Kodi as result.
My question is why is the teardown msg not waiting on the teardown reply?
before requesting the previous used frontend.
Greetings,
Marc
Updated by ullix tv over 10 years ago
Jaroslav Kysela wrote:
I added some more logs to v3.9-2308-g2635a3d . Could you get the latest sources and provide above logs (including status status picture from tvh) ?
The problem is that the epggrab subscriptions override other active epggrab subscriptions which should have same weight (thus the new subscription should fail). But in your situation, the overriden subscription is moved back to the tail of the epggrab queue.
Huh?
I need more guidance, do you mean?
TVH_ARGS="-d -l /home/ullix/tvh_logs/tvh.log --trace satip,httpc,mpegts,subscription,status, picture --debug satip,httpc,mpegts,subscription,status,picture"
Updated by Marc Postema over 10 years ago
Hello ullix tv
I think the status page of tvh (like you had before) not adding to trace list.
Updated by ullix tv over 10 years ago
Marc Postema wrote:
I think the status page of tvh (like you had before) not adding to trace list.
Now that I finally learned how to set these options, all you want is a screenshot ;-)
In trying to keep track on all the changes I am wondering whether it is possible to add a config option to the DEBUG options, which prints the current configuration of the respective system - like configTV - in the log?
And not to forget the tvh version!
Updated by ullix tv over 10 years ago
- File iplnb-festatus.png iplnb-festatus.png added
- File tvh-status-2015-01-02.png tvh-status-2015-01-02.png added
- File tvh.log tvh.log added
Tuner #3 and #6 are stuck in allocation.
Hope that Marc correctly translated your wishlist for me :-)
Attached is tvh.log, screenshot tvh-Status , screenshot iplnb-festatus
Updated by Jaroslav Kysela over 10 years ago
Added even more logs to v3.9-2309-g4dcdbef, repeat, please . I'm sorry, but it seems like a complicated issue and you can trigger it easily.
Updated by ullix tv over 10 years ago
- File tvh-2015-01-03-1200.log.zip tvh-2015-01-03-1200.log.zip added
- File tvh-status-2015-01-03.png tvh-status-2015-01-03.png added
Jaroslav Kysela wrote:
... and you can trigger it easily.
yes, it did happen after less than 2 minutes. I let it run for >2h, but no changes which I could see, except that both "SNR" and "Signal Strength" in the Status change do change.
tvh is HTS Tvheadend 3.9.2310~gcb5aed8~precise
I think it would be great if version and some config options were auto-included in the log files?
Updated by ullix tv over 10 years ago
- File tvh-2015-01-03-1234.log tvh-2015-01-03-1234.log added
- File tvh-status-2015-01-03-1234.png tvh-status-2015-01-03-1234.png added
Well, here is some additional oddity:
In the last days, in order to have reproducible conditions, I always stopped tvheadedn, depowered the IP-LNB, and then did a factory reset of it via the IP-LNB's web interfase, then restarted tvheadend. It almost immediately triggered the allocated-but-not-used tuner effect.
Today I forgot to depower/reset and the allocation issue did NOT happen! Curious, I repeated this 6 times, and always smooth scanning/epggrabbing and clear status, no allocation issue. I then did the depowering and resetting and restarted, and promptly the allocation issue happened again, plus a hang of the tuner.
Is there perhaps something that tvh, before exiting, sends to the IP-LNB, which puts the IP-LNB in a better start condition than the depowering/resetting might do?
Updated by Jaroslav Kysela over 10 years ago
Could you try v3.9-2316-gc051d0b ? I fixed a little SAT>IP issue which may explain the stalled mux subscriptions.
Updated by ullix tv over 10 years ago
- File iplnb-festatus-2015-01-04-after-system_restart.png iplnb-festatus-2015-01-04-after-system_restart.png added
- File iplnb-festatus-2015-01-04-after-system_restart-and-tvh-run.png iplnb-festatus-2015-01-04-after-system_restart-and-tvh-run.png added
Jaroslav Kysela wrote:
Could you try v3.9-2316-gc051d0b ? I fixed a little SAT>IP issue which may explain the stalled mux subscriptions.
I think the good news is that I can clearly reproduce this one bug, but after that it becomes murky.
With that new version:
When tvheadend had been run and is stopped, and then I do either of these:
- a) depower the iplnb and then do a Factory Reset (via its web interface)
- b) or do a Factory Reset only, WITHOUT a previous depowering
- c) or only do a System Restart (via its web interface)
and then start tvheadend, the results are the same: tvh scans, epggrabs, and then 1 to 3 tuners remain "allocated" (iplnb terminology) but do nothing.
Then I stop tvh and start it, and the results are this: tvh scans, epgrabs and once finished all tuners are "free" (iplnb terminology)!
@Marc: can you reproduce this?
Updated by ullix tv over 10 years ago
- File iplnb-festatus-2015-01-04-after-system_restart-and-tvh-exited.png iplnb-festatus-2015-01-04-after-system_restart-and-tvh-exited.png added
- File tvh-status-2015-01-04-after-iplnb-system_restart.png tvh-status-2015-01-04-after-iplnb-system_restart.png added
- File tvh-2015-01-04.log tvh-2015-01-04.log added
(oops, accidentally hit return, don't know how o continue with post)
the attached screenshots show the sequence for a run after a System Restart (option c) had been done.
My conclusion is that the iplnb is after the tvh exit in a "cleaner" state than after either option of the a,b,c.
Hence, wouldn't it be prudent to try to send whatever command(s) tvh is sending to the iplnb before exiting - as this may be doing the cleaning job - also when tvh first starts?
It shouldn't harm anything and should be worth a try after all these struggles.
Updated by Jaroslav Kysela over 10 years ago
My concern is now only about the stalled muxes in the status tab. Do you have any stalled muxes now ?
BTW: The tvheadend does not do any special shutdown sequence (except that it closes all opened streams). Anyway, I would enable the OTA EPG scan only for one tuner for the standard environment.
Updated by Marc Postema over 10 years ago
Hello ullix tv and Jaroslav Kysela,
I can not reproduce this, but I have that now and the channel switch produces no picture in kodi.
When this happens I see in tvh logs that the TEARDOWN msg does not seem to wait on the reply (or does not receive it?).
But immediately sends an SETUP msg (see above message 15)
Regards,
Marc
Updated by ullix tv over 10 years ago
Jaroslav Kysela wrote:
Do you have any stalled muxes now ?
To be clear: what you call "stalled-muxes" is seen as an active stream with zero subscriptions in tvh, and on the IPLNB festatus shown as "allocated" (and not "free") for the respective tuner?
Yes, my previous post has the screenshots and the matching tvh.log. What happened was three stalled muxes followed by a frozen iplnb. Should all be in the log
My system is now running fine for 1 day, nothing stalled, nothing frozen. Of course, an iplnb System Restart was NOT done immediately before this run. Instead, tvh had been started and stopped, and started again for the current run.
As before, running tvh seems to be doing something good for the iplnb, which its System Restart routine does not seem to be able to accomplish.
Updated by Jaroslav Kysela over 10 years ago
Marc Postema wrote:
Hello ullix tv and Jaroslav Kysela,
I can not reproduce this, but I have that now and the channel switch produces no picture in kodi.
When this happens I see in tvh logs that the TEARDOWN msg does not seem to wait on the reply (or does not receive it?).
But immediately sends an SETUP msg (see above message 15)
The new SETUP message should be sent in a new session (new TCP connection). There is 250ms timeout for the TEARDOWN (not sure if it's enough). Now, when I moved the whole SAT>IP control loop to another thread, we may increase this timeout, because it won't hurt the whole tvheadend, but only one tuner. Could you try to change value 250 on line 1476 in src/input/mpegts/satip/satip_frontend.c to 1000 ? It's line:
nfds = tvhpoll_wait(efd, ev, 1, 250);
Updated by Jaroslav Kysela over 10 years ago
ullix tv wrote:
Jaroslav Kysela wrote:
Do you have any stalled muxes now ?
To be clear: what you call "stalled-muxes" is seen as an active stream with zero subscriptions in tvh, and on the IPLNB festatus shown as "allocated" (and not "free") for the respective tuner?
Yes, I meant the subscribed muxes with zero subscriptions (stalled muxes).
Yes, my previous post has the screenshots and the matching tvh.log. What happened was three stalled muxes followed by a frozen iplnb. Should all be in the log
My system is now running fine for 1 day, nothing stalled, nothing frozen. Of course, an iplnb System Restart was NOT done immediately before this run. Instead, tvh had been started and stopped, and started again for the current run.
OK, so no more subscribed muxes with zero subscriptions.
As before, running tvh seems to be doing something good for the iplnb, which its System Restart routine does not seem to be able to accomplish.
No idea.
Updated by Marc Postema over 10 years ago
Jaroslav Kysela wrote:
The new SETUP message should be sent in a new session (new TCP connection). There is 250ms timeout for the TEARDOWN (not sure if it's enough). Now, when I moved the whole SAT>IP control loop to another thread, we may increase this timeout, because it won't hurt the whole tvheadend, but only one tuner. Could you try to change value 250 on line 1476 in src/input/mpegts/satip/satip_frontend.c to 1000 ? It's line:
But it is not realy requered to teardown the session when changing channels.. A play or setup within the session is acceptible.
I will try to change it.. But I have changed it also in my software that it will retry to requested
to be teardowned frontend. So I hope this will fix it also.
I don't realy like to increase timeouts (At some point something will change and it does not work anymore).
But thanks for the reply and regards,
Marc
Updated by ullix tv over 10 years ago
After about 5 days of successfully running tvh and iplnb - no adverse effects of any kind, in particular no stalled muxes - the iplnb froze again. A stalled mux was not involved, at least none was shown in the tvh status page.
Restart required depwoering.
11.01.2015 04:21:01 ping_iplnb.py 4217 (tvheadend is running) returncode=0 wget 11.01.2015 04:22:04 ping_iplnb.py 4240 (tvheadend is running) returncode=4 wget
As seen from wget test, iplnb failed between 04:21:01 and 04:22:04. I am attaching an excerpt of the tvh.log from around this period.
I have then upgraded tvheadend to version 3.9.2345~gf5c8e4c~precise. Same things happened as before: tvh did scan, then epggrab, ending with 2 stalled muxes. I restart tvh WITHOUT depowering or resetting the iplnb, and scan+epggrab go through without stalled muxes.
What to do? Is there anything you can read out of the log?
Updated by Jaroslav Kysela over 10 years ago
2 stalled muxes - provide the whole trace again..
Updated by ullix tv over 10 years ago
- File tvh-2015-01-11.log.zip tvh-2015-01-11.log.zip added
Jaroslav Kysela wrote:
2 stalled muxes - provide the whole trace again..
How do you see that? can you point to the time? As I said, the tvh status page had no stalled muxes.
Attached is the whole 5 day log
Updated by Jaroslav Kysela over 10 years ago
I just saw your words: "ending with 2 stalled muxes". Did you mean stalled muxes in IPLNB (not in tvh) ?
Updated by ullix tv over 10 years ago
- File Bildschirmfoto vom 2015-01-12 12_11_55.png Bildschirmfoto vom 2015-01-12 12_11_55.png added
- File tvh-2015-01-12_4-stalled-muxes.log tvh-2015-01-12_4-stalled-muxes.log added
Jaroslav Kysela wrote:
I just saw your words: "ending with 2 stalled muxes". Did you mean stalled muxes in IPLNB (not in tvh) ?
I guess you misread my post #32.
That post was about the freezing of the IPLNB, which means that you can still ping the iplnb, but have no access to anything else, not even the iplnb's web interface. The only escape is by pulling the power plug (i.e. the ethernet plug, as it is PoE). The log in that post #32 has the situation of the freeze captured (and in #34 the whole log up to this event and beyond is added)
The "stalled muxes" issue does exist, but there is a workaround. After depowering and the repowering the iplnb (or doing a factory reset, or doing a system restart) and starting tvh, there have ALWAYS been 1-3 stalled muxes, after tvh went through the initial scan+epggrab. However, when you then stop and restart tvh, there were NEVER (so far) any stalled muxes after the scan+epggrab.
My hypothesis is that tvh does something to reset the iplnb to a default state better than the iplnb's firmware resetting routine. Whatever it is. But the workaround avoids stalled muxes.
Therefore I am more concerned about the freezes every few days, as this seems to happen only whenever I am watching or recording something. I think it is still unclear whether the fault is at tvh or the firmware (or both).
But if you want stalled muxes, here is a clean log, given you 4 of them! What I did:
- upgrade tvh to version 3.9.2347~gbfa463d~precise
- stop tvh
- leaving the iplnb at the power, I do a "System Restart" via its web intercase
- start tvh
- after the scan+epggrab is over, I see 4 stalled muxes
- stop tvh
- post log files, post screenshot from tvh status
As you see, very reproducible and took only 2 1/2 minutes
Updated by Marc Postema over 10 years ago
Hello ullix tv,
What would happen if you tune to a frequency, let it play for some time.
then disconnect the tvh server from the network. does the IPLNB hang then?
Regards,
Marc
Updated by Jaroslav Kysela over 10 years ago
@ullix tv: from latest log:
Good:
015-01-12 12:10:29.000 [ INFO]:subscription: 0010: "epggrab" subscribing to mux, weight: 3, adapter: "SAT>IP DVB-S Tuner #8 (10.0.0.71)", network: "SATIP", mux: "11052.75H", hostname: "<N/A>", username: "<N/A>", client: "<N/A>" 2015-01-12 12:11:00.444 [ INFO]:subscription: 0010: "epggrab" unsubscribing 2015-01-12 12:11:00.444 [ TRACE]:mpegts: 11052.75H in SATIP - remove subscriber 2015-01-12 12:11:00.444 [ DEBUG]:mpegts: 11052.75H in SATIP - stopping mux 2015-01-12 12:11:00.444 [ DEBUG]:satip: SAT>IP DVB-S Tuner #8 (10.0.0.71) - stopping 11052.75H in SATIP 2015-01-12 12:11:00.444 [ TRACE]:mpegts: SAT>IP DVB-S Tuner #8 (10.0.0.71) - flush subscribers 2015-01-12 12:11:00.444 [ TRACE]:mpegts: 11052.75H in SATIP - flush tables 2015-01-12 12:11:00.444 [ TRACE]:satip: SAT>IP DVB-S Tuner #8 (10.0.0.71) - input thread received mux close
Wrong:
015-01-12 12:10:35.000 [ INFO]:subscription: 0015: "epggrab" subscribing to mux, weight: 3, adapter: "SAT>IP DVB-S Tuner #7 (10.0.0.71)", network: "SATIP", mux: "12421.5H", hostname: "<N/A>", username: "<N/A>", client: "<N/A>" 015-01-12 12:11:05.000 [ INFO]:subscription: 0015: "epggrab" unsubscribing ... no other related lines here ...
Basically, tvh won't do the mux close, but the EPG code asked to close the mux. From the code:
src/subscription.c: fcn subscription_unsubscribe() line 551, it seems that s->ths_mmi is NULL here..
Analyzing further, in the mux_data_timeout callback should be called mpegts_mux_remove_subscriber instead subscription_unlink_mux .
Could you retest with v3.9-2352-g0a7ce2c ?
Updated by ullix tv over 10 years ago
- File Bildschirmfoto vom 2015-01-12 15_03_45.png Bildschirmfoto vom 2015-01-12 15_03_45.png added
- File Bildschirmfoto vom 2015-01-12 15_04_20.png Bildschirmfoto vom 2015-01-12 15_04_20.png added
- File tvh-2015-01-12_tvh-disconnect.log tvh-2015-01-12_tvh-disconnect.log added
Marc Postema wrote:
Hello ullix tv,
What would happen if you tune to a frequency, let it play for some time.
then disconnect the tvh server from the network. does the IPLNB hang then?Regards,
Marc
Not easy to disconnect tvh. While playing live tv with Kodi: If you "sudo stop tvheadend" then tvh puts iplnb in good, clean state and exits. Everything fine. If you kill tvh, then tvh restarts automatically and kodi starts playing after the little break as if nothing has haapened. iplnb still in good state; no stalled muxes.
So then I pulled the ethernet plug from the tvh computer. The iplnb remained fully accessible!
But when reconnecting the ethernet cable to my tvh server, then a record of 7 (!) out of 8 stalled muxes resulted. Strangely though, they were stalled only in tvh; on the iplnb, all were presented as "free" on the iplnb's festatus page. See screenshots.
tvh.log also included; maybe this special situation is helpful for something
(Just seeing Jaroslav's new comment; will try tomorrow)
Updated by ullix tv over 10 years ago
Upgraded to: tvheadend: version 3.9.2354~g940ab26~precise
Using all my torture tools I tried hard and repeatedly to create any stalled muxes, but failed miserably every time!
Looks like you 've nailed this one, Jaroslav. Congrats!
Makes me wonder, where the problem originated: was it Inverto not following the specs, or tvh, or was there an incomplete definition of a situation and Inverto using some solution and tvh another one?
In the latter case, the problem might come back with a different system?
Updated by ullix tv over 10 years ago
I tried to enable the Idle scan for my sat>ip network for maximum load on the iplnb, but the column with the check box in Configuration->DVB Inputs->Networks is missing?
However, when I select my network and click the Edit button, the choice of idle-scan is still there. See screenshot.
Mistakenly removed?
Updated by Jaroslav Kysela over 10 years ago
ullix tv wrote:
I tried to enable the Idle scan for my sat>ip network for maximum load on the iplnb, but the column with the check box in Configuration->DVB Inputs->Networks is missing?
However, when I select my network and click the Edit button, the choice of idle-scan is still there. See screenshot.
Mistakenly removed?
No, this change is intentional. Most users enable this without exact knowledge (omit help). So I moved it to be a little more hidden than standard options. Again, this option is not for normal usage.
Updated by Jaroslav Kysela over 10 years ago
ullix tv wrote:
Makes me wonder, where the problem originated: was it Inverto not following the specs, or tvh, or was there an incomplete definition of a situation and Inverto using some solution and tvh another one?
I think that 8 tuners is the culprit. It makes this problem more "visible".
EDIT: Sorry, the above reply is for the stalled muxes issue. For (network) dead IPLNB, it's really firmware (or maybe hardware) issue. I would contact Inverto to help with it, because SAT>IP server should not be dead even if the client is broken.
Updated by ullix tv over 10 years ago
Jaroslav Kysela wrote:
EDIT: Sorry, the above reply is for the stalled muxes issue. For (network) dead IPLNB, it's really firmware (or maybe hardware) issue. I would contact Inverto to help with it, because SAT>IP server should not be dead even if the client is broken.
Yes, but... I'll contact you by email.
Updated by ullix tv over 10 years ago
Jaroslav Kysela wrote:
No, this change is intentional. Most users enable this without exact knowledge (omit help). So I moved it to be a little more hidden than standard options. Again, this option is not for normal usage.
Well, a user interface by obscurity does not look like being the best approach, or not?
The current idle scan is surely wayyyy beyond agressive. In my system it starts a cycle every 30sec (!), with the scan taking from 60 to 100% of that cycle, and thus it does generate 100MBit/s pulses every 30 sec.
In addition to the checkboxes for the network there are also checkboxes for both "Initial Scan" and "Idle Scan" for each of the 8 tuners. I don't see a good reason for these additional separate options. With the inverto lnb you are pointing to one and only one satellite; each tuner can only do the same thing as each other tuner. So, not even an indiviidual scan and epggrab on each tuner is necessary; one for the iplnb would suffice
What I really would like to see is:
- For each network a "Scan Now" button (helpful during configurations)
- An Idle Scan option per network allowing once every N hours idle scans, with N being integer and >0 (default perhaps=8?)
(My system is now running for 24h with the heavy idle scan load; log file is 1 GB per day. otherwise smooth running)
Updated by Jaroslav Kysela over 10 years ago
ullix tv wrote:
Jaroslav Kysela wrote:
No, this change is intentional. Most users enable this without exact knowledge (omit help). So I moved it to be a little more hidden than standard options. Again, this option is not for normal usage.
Well, a user interface by obscurity does not look like being the best approach, or not?
The point is that this option should not be in the first-look grid..
The current idle scan is surely wayyyy beyond agressive. In my system it starts a cycle every 30sec (!), with the scan taking from 60 to 100% of that cycle, and thus it does generate 100MBit/s pulses every 30 sec.
In addition to the checkboxes for the network there are also checkboxes for both "Initial Scan" and "Idle Scan" for each of the 8 tuners. I don't see a good reason for these additional separate options. With the inverto lnb you are pointing to one and only one satellite; each tuner can only do the same thing as each other tuner. So, not even an indiviidual scan and epggrab on each tuner is necessary; one for the iplnb would suffice
What I really would like to see is:
- For each network a "Scan Now" button (helpful during configurations)
I added this to v3.9-2375-gf48e390 (Force Scan). You may select one or multiple networks.
- An Idle Scan option per network allowing once every N hours idle scans, with N being integer and >0 (default perhaps=8?)
I don't think that we need another scheduler. We have already the EPG scheduler which does exactly similar thing (although it scans only the muxes with mapped services).
Updated by ullix tv over 10 years ago
- File Idle_scan_on_off effect on traffic and cpu.png Idle_scan_on_off effect on traffic and cpu.png added
- File epg_grabber_effect on traffic and cpu.png epg_grabber_effect on traffic and cpu.png added
Jaroslav Kysela wrote:
I added this to v3.9-2375-gf48e390 (Force Scan). You may select one or multiple networks.
We have already the EPG scheduler which does exactly similar thing (although it scans only the muxes with mapped services).
Very nice!
I am adding a System Monitor screenshot showing on the left half idlescan=on, and on the right idlescan=off. Network traffic is quite signifcant and even cpu very noticeable. On a less powerful system, this might be a real burden.
For the second screenshot I had triggered the Over-the-Air Grabbers 3 min apart. Traffic is only a tenth, and cpu much less too. And why would I scan anything but mapped services unless I changed some configuration, for which I now have the Force Scan button?
I think the initial scan and idle scan options can go altogether, both in the network and in the tuners settings.
My guess is that tvh with Kodi will get much broader audiences, and while the cron like settings of the EPG grabbers do work, I guess those kinds of settings may not be liked by everyone. It takes too much explaining.
Updated by Jaroslav Kysela over 10 years ago
ullix tv wrote:
Jaroslav Kysela wrote:
I added this to v3.9-2375-gf48e390 (Force Scan). You may select one or multiple networks.
We have already the EPG scheduler which does exactly similar thing (although it scans only the muxes with mapped services).
Very nice!
I am adding a System Monitor screenshot showing on the left half idlescan=on, and on the right idlescan=off. Network traffic is quite signifcant and even cpu very noticeable. On a less powerful system, this might be a real burden.
It's limitation of the firmware. I don't know exactly IPLNB, but the standard 4-tuner boxes (IDL 400s, GSS.BOX) can have only 32 PID filter installed or they can receive only the whole mux. You may check the settings in the tuner configuration and increase this value, but the problem is, that you need to check for the 'Status' strings in the satip traces if all requested PIDs are active, becuase newest requests might override others.
In other words - it's not necessary to receive the whole mux for the discovery, but some muxes have too many services, and tvheadend tries to scan them at once so the PID filter limit is crossed.
For the second screenshot I had triggered the Over-the-Air Grabbers 3 min apart. Traffic is only a tenth, and cpu much less too. And why would I scan anything but mapped services unless I changed some configuration, for which I now have the Force Scan button?
The scan is triggered when the mux is tuned to check for the new services, but in case of normal streaming and epggrab, only PMT tables for active services are subscribed, but during the full scan, all PMT tables are subscribed (which may cross the PID firmware limit).
I think the initial scan and idle scan options can go altogether, both in the network and in the tuners settings.
No, these are two different things.
My guess is that tvh with Kodi will get much broader audiences, and while the cron like settings of the EPG grabbers do work, I guess those kinds of settings may not be liked by everyone. It takes too much explaining.
Keep defaults. They're reasonable for standard users. EPG-grab is triggered twice in a day and when the mux with EPG is tuned (for streaming).
Updated by ullix tv over 10 years ago
The IPLNB is now running over a week with no stalled muxes and, most importantly, no freezing of the IPLNB, just smooth operation!
Looks like problems are corrected or at least a workaround was implemented. My understanding of the issues are:- There is a bug in the firmware of the iplnb, which allows that the iplnb can be frozen by some incorrect command from the client. However, a client corrupting the server by a command sent to the server - and the iplnb is a server - should never happen.
- The bad commands from tvh, which killed the server were modified (https://github.com/tvheadend/tvheadend/pull/369#issuecomment-69767082). Apparently, they no longer result in stalled muxes nor do they kill the server
So, while this looks really good again for the iplnb, it does have bug in its firmware!
I am using tvh with various PC, laptop and tablet clients, but most importantly with the Amazon FireTV. Kodi 14 (stable release) is run on all of them. All work well, and I am most pleased with the FireTV. Although some crashes occur on FireTV, they are rare, and recently have never been on playback, only navigation and/or control.
If the freezing comes back, I'll report here again, but for the time being it is done!
Updated by Jaroslav Kysela over 10 years ago
- Status changed from New to Fixed
OK. closing as fixed. Re-open new issue (in case of another tvh bug)..
Only a little note: TVH didn't send wrong commands. It seems that the IPLNB firmware problem is joined to the stalled muxes - the tuners were running for long times. And maybe the idle scan (fast tuner switching). The firmware does not like some command sequences (or timing of the commands).