Bug #4333
Cannot connect to external SATIP server
100%
Description
I have a Windows PC running DVBViewer Recording Server which can act as a SATIP server. This has five tuners - two DVB-C and three DVB-T2. Many months ago when I last looked at this, I managed to get TVH to connect to DVBViewer RS and use it's tuners ok, but I haven't tried again recently until now, and I cannot get it to work now.
Basically, TVH sees all five tuners and for the sake of simplicity I only enable the first DVB-T2 tuner to test. Note, I have the TVH config set to "DVBC-2,DVBT2-3" on the tuner config page otherwise TVH detects the remote tuners in the wrong order and tries to use the wrong one (see bug #4016). With TVH idle, if I use VLC to try and play a channel, it fails to connect with "service instance is bad, reason: No input detected". It does this for whatever channel I choose. However...if I trigger an OTA EPG grab, this connects and works. If I then try and play a channel on the same mux as the grab is active on - it works!
It seems to be a problem with TVH doing the initial tune when trying to play a channel, but there is no problem when it tunes for the EPG grab. Also, trying to do a channel scan on a mux doesn't work either.
Attached is a trace log showing the RTSP comms, but everything looks ok to me. I am using build 4.1.2545
Files
History
Updated by Jaroslav Kysela over 7 years ago
Updated by Try increase the timeout in the used stream profile. It seems that your server is VERY slow (6 seconds for DVB-T? it's a joke).
Updated by Laurie Davis over 7 years ago
Updated by The Timeout setting for the "pass" stream says "Timeout (sec) (0=infinite):" and was set to 0, so that would imply there was no timeout. I tried setting it to 10 and 20 but no joy - I get the same problem (logs are the same ie TVH times out before the 6 seconds it takes for RS to reply).
I can't see why the RS server is so slow - in it's logs it sets up the connection in under a second. I know some changes were made in the last release but unfortunately, development has now stopped because the developer has created a new "media server" - which he now charges more money for 
Is it possible to increase the connection timeout in TVH?
Updated by Jaroslav Kysela over 7 years ago
Could you watch the network traffic ? There's 6 second delay between the request (SETUP) and answer from the SATIP server. There must be a culprit somewhere.
Request from TVH:
2017-04-25 14:14:16.874 [ TRACE]:httpc: 0002: sending RTSP/1.0 cmd 2017-04-25 14:14:16.874 [ TRACE]:httpc: 53 45 54 55 50 20 72 74 73 70 3A 2F 2F 31 39 32 SETUP rtsp://192 2017-04-25 14:14:16.874 [ TRACE]:httpc: 2E 31 36 38 2E 31 2E 32 30 31 2F 3F 66 65 3D 33 .168.1.201/?fe=3 2017-04-25 14:14:16.874 [ TRACE]:httpc: 26 66 72 65 71 3D 34 39 30 26 62 77 3D 38 26 6D &freq=490&bw=8&m 2017-04-25 14:14:16.874 [ TRACE]:httpc: 73 79 73 3D 64 76 62 74 26 6D 74 79 70 65 3D 36 sys=dvbt&mtype=6 2017-04-25 14:14:16.874 [ TRACE]:httpc: 34 71 61 6D 26 74 6D 6F 64 65 3D 38 6B 26 67 69 4qam&tmode=8k&gi 2017-04-25 14:14:16.874 [ TRACE]:httpc: 3D 31 33 32 20 52 54 53 50 2F 31 2E 30 0D 0A 54 =132 RTSP/1.0..T 2017-04-25 14:14:16.874 [ TRACE]:httpc: 72 61 6E 73 70 6F 72 74 3A 20 52 54 50 2F 41 56 ransport: RTP/AV 2017-04-25 14:14:16.874 [ TRACE]:httpc: 50 3B 75 6E 69 63 61 73 74 3B 63 6C 69 65 6E 74 P;unicast;client 2017-04-25 14:14:16.874 [ TRACE]:httpc: 5F 70 6F 72 74 3D 35 34 30 34 34 2D 35 34 30 34 _port=54044-5404 2017-04-25 14:14:16.874 [ TRACE]:httpc: 35 0D 0A 43 53 65 71 3A 20 31 0D 0A 0D 0A 5..CSeq: 1....
Late answer from the server:
2017-04-25 14:14:23.051 [ TRACE]:httpc: 0002: RTSP/1.0 answer 'RTSP/1.0 200 OK' (rcseq: 1) 2017-04-25 14:14:23.051 [ TRACE]:httpc: 52 54 53 50 2F 31 2E 30 20 32 30 30 20 4F 4B 00 RTSP/1.0 200 OK. 2017-04-25 14:14:23.051 [ TRACE]:httpc: 0A 43 53 65 71 3A 20 31 0D 0A 53 65 73 73 69 6F .CSeq: 1..Sessio 2017-04-25 14:14:23.051 [ TRACE]:httpc: 6E 3A 20 35 34 33 36 3B 74 69 6D 65 6F 75 74 3D n: 5436;timeout= 2017-04-25 14:14:23.051 [ TRACE]:httpc: 32 30 0D 0A 54 72 61 6E 73 70 6F 72 74 3A 20 52 20..Transport: R 2017-04-25 14:14:23.051 [ TRACE]:httpc: 54 50 2F 41 56 50 3B 75 6E 69 63 61 73 74 3B 64 TP/AVP;unicast;d 2017-04-25 14:14:23.051 [ TRACE]:httpc: 65 73 74 69 6E 61 74 69 6F 6E 3D 31 39 32 2E 31 estination=192.1 2017-04-25 14:14:23.051 [ TRACE]:httpc: 36 38 2E 31 2E 32 30 32 3B 73 6F 75 72 63 65 3D 68.1.202;source= 2017-04-25 14:14:23.051 [ TRACE]:httpc: 31 39 32 2E 31 36 38 2E 31 2E 32 30 31 3B 63 6C 192.168.1.201;cl 2017-04-25 14:14:23.051 [ TRACE]:httpc: 69 65 6E 74 5F 70 6F 72 74 3D 35 34 30 34 34 2D ient_port=54044- 2017-04-25 14:14:23.051 [ TRACE]:httpc: 35 34 30 34 35 3B 73 65 72 76 65 72 5F 70 6F 72 54045;server_por 2017-04-25 14:14:23.051 [ TRACE]:httpc: 74 3D 36 32 30 30 2D 36 32 30 31 0D 0A 63 6F 6D t=6200-6201..com 2017-04-25 14:14:23.051 [ TRACE]:httpc: 2E 73 65 73 2E 73 74 72 65 61 6D 49 44 3A 20 31 .ses.streamID: 1 2017-04-25 14:14:23.051 [ TRACE]:httpc: 37 35 0D 0A 53 65 72 76 65 72 3A 20 44 56 42 56 75..Server: DVBV 2017-04-25 14:14:23.051 [ TRACE]:httpc: 69 65 77 65 72 20 52 65 63 6F 72 64 69 6E 67 20 iewer Recording 2017-04-25 14:14:23.051 [ TRACE]:httpc: 53 65 72 76 69 63 65 0D 0A 44 61 74 65 3A 20 54 Service..Date: T 2017-04-25 14:14:23.051 [ TRACE]:httpc: 75 65 2C 20 32 35 20 41 70 72 20 32 30 31 37 20 ue, 25 Apr 2017 2017-04-25 14:14:23.051 [ TRACE]:httpc: 31 33 3A 31 34 3A 32 34 20 47 4D 54 00 0A 0D 0A 13:14:24 GMT....
Updated by Jaroslav Kysela over 7 years ago
The idea is to identify, if the problem is in the SAT>IP server (data are not send throught the network in time) or in TVH or somewhere else (system config). I've not seen this problem before.
Updated by Laurie Davis over 7 years ago
It looks to definitely be the server: Wireshark shows
No. Time Source Destination Protocol Length Info
8 17.861823 192.168.1.199 192.168.1.201 RTSP 224 SETUP rtsp://192.168.1.201/?fe=5&freq=514&bw=8&msys=dvbt&mtype=64qam&tmode=8k&gi=132 RTSP/1.0
11 18.063419 192.168.1.199 192.168.1.201 RTSP 224 [TCP Retransmission] SETUP rtsp://192.168.1.201/?fe=5&freq=514&bw=8&msys=dvbt&mtype=64qam&tmode=8k&gi=132 RTSP/1.0
15 23.333879 192.168.1.201 192.168.1.199 RTSP 336 Reply: RTSP/1.0 200 OK
17 23.334050 192.168.1.199 192.168.1.201 RTSP 183 PLAY rtsp://192.168.1.201/stream=6?addpids=0,1,16,17,18,1700,1701,1702,1703,1731 RTSP/1.0
18 23.334435 192.168.1.201 192.168.1.199 RTSP 264 Reply: RTSP/1.0 200 OK
129 23.861027 192.168.1.199 192.168.1.201 RTSP 141 TEARDOWN rtsp://192.168.1.201/stream=6 RTSP/1.0
135 24.064155 192.168.1.201 192.168.1.199 RTSP 194 Reply: RTSP/1.0 200 OK
144 25.863568 192.168.1.199 192.168.1.201 RTSP 224 SETUP rtsp://192.168.1.201/?fe=5&freq=514&bw=8&msys=dvbt&mtype=64qam&tmode=8k&gi=132 RTSP/1.0
152 31.058909 192.168.1.201 192.168.1.199 RTSP 336 Reply: RTSP/1.0 200 OK
154 31.059210 192.168.1.199 192.168.1.201 RTSP 183 PLAY rtsp://192.168.1.201/stream=7?addpids=0,1,16,17,18,1700,1701,1702,1703,1731 RTSP/1.0
155 31.059682 192.168.1.201 192.168.1.199 RTSP 262 Reply: RTSP/1.0 200 OK
307 31.862975 192.168.1.199 192.168.1.201 RTSP 141 TEARDOWN rtsp://192.168.1.201/stream=7 RTSP/1.0
313 32.066213 192.168.1.201 192.168.1.199 RTSP 194 Reply: RTSP/1.0 200 OK
322 33.866108 192.168.1.199 192.168.1.201 RTSP 224 SETUP rtsp://192.168.1.201/?fe=5&freq=514&bw=8&msys=dvbt&mtype=64qam&tmode=8k&gi=132 RTSP/1.0
328 39.343916 192.168.1.201 192.168.1.199 RTSP 336 Reply: RTSP/1.0 200 OK
330 39.344141 192.168.1.199 192.168.1.201 RTSP 183 PLAY rtsp://192.168.1.201/stream=8?addpids=0,1,16,17,18,1700,1701,1702,1703,1731 RTSP/1.0
331 39.344598 192.168.1.201 192.168.1.199 RTSP 264 Reply: RTSP/1.0 200 OK
462 39.865316 192.168.1.199 192.168.1.201 RTSP 141 TEARDOWN rtsp://192.168.1.201/stream=8 RTSP/1.0
1172 42.952291 192.168.1.201 192.168.1.199 RTSP 194 Reply: RTSP/1.0 200 OK
But the server log shows all is setup within a second:
26.04.17 16:56:43.166 SetStandbyBlock RTSP-Client 192.168.1.199 26.04.17 16:56:43.166 TRecordingEngine AddReference RTSP-Client 192.168.1.199: 1 26.04.17 16:56:43.166 TRTSPUDPClient SendBufSizeUDP 13280000 26.04.17 16:56:43.166 TRTSPUDPClient SetTuner TType: 2, Freq: 514000, Symrate: 0, LOF: 0, Tone: 0, Pol: 2, DiseqC: 0, FEC: 0, APID: 0, VPID: 0, PMT: 0, SID: 0, TID: 0, NID: 0, SatMod: 0, DiseqCVal: 0, Flags: 0 26.04.17 16:56:43.472 TBDATeVii OpenDevice bvTeVii 26.04.17 16:56:43.472 TRTSPUDPClient AllocateHardware Digital TV (5) 26.04.17 16:56:43.472 TRTSPUDPClient SetTuner Got new hardware 26.04.17 16:56:43.472 TBDATeVii SetTuner TType: 2, Freq: 514000, Symrate: 0, LOF: 0, Tone: 0, Pol: 2, DiseqC: 0, FEC: 0, APID: 0, VPID: 0, PMT: 0, SID: 0, TID: 0, NID: 0, SatMod: 0, DiseqCVal: 0, Flags: 0 26.04.17 16:56:44.122 TRTSPUDPClient SetTuner Tuner set 26.04.17 16:56:44.122 TRTSPUDPClient AddPids 0,1,16,17,18,1700,1701,1702,1703,1731 26.04.17 16:56:44.649 TRTSPUDPClient Release Digital TV (5) 26.04.17 16:56:44.649 TRTSPUDPClient Free Digital TV (5) 26.04.17 16:56:44.852 TRTSPUDPClient Freed Digital TV (5) 26.04.17 16:56:44.852 TRTSPUDPClient hamDeleted Digital TV (5) 26.04.17 16:56:44.852 TVCR No shutdown allowed next recording: 26/04/2017 16:57:00 26.04.17 16:56:44.852 TRecordingEngine ReleaseReference RTSP-Client 192.168.1.199: 0 26.04.17 16:56:51.167 SetStandbyBlock RTSP-Client 192.168.1.199 26.04.17 16:56:51.167 TRecordingEngine AddReference RTSP-Client 192.168.1.199: 1 26.04.17 16:56:51.167 TRTSPUDPClient SendBufSizeUDP 13280000 26.04.17 16:56:51.167 TRTSPUDPClient SetTuner TType: 2, Freq: 514000, Symrate: 0, LOF: 0, Tone: 0, Pol: 2, DiseqC: 0, FEC: 0, APID: 0, VPID: 0, PMT: 0, SID: 0, TID: 0, NID: 0, SatMod: 0, DiseqCVal: 0, Flags: 0 26.04.17 16:56:51.480 TBDATeVii OpenDevice bvTeVii 26.04.17 16:56:51.480 TRTSPUDPClient AllocateHardware Digital TV (5) 26.04.17 16:56:51.480 TRTSPUDPClient SetTuner Got new hardware 26.04.17 16:56:51.480 TBDATeVii SetTuner TType: 2, Freq: 514000, Symrate: 0, LOF: 0, Tone: 0, Pol: 2, DiseqC: 0, FEC: 0, APID: 0, VPID: 0, PMT: 0, SID: 0, TID: 0, NID: 0, SatMod: 0, DiseqCVal: 0, Flags: 0 26.04.17 16:56:51.847 TRTSPUDPClient SetTuner Tuner set 26.04.17 16:56:51.847 TRTSPUDPClient AddPids 0,1,16,17,18,1700,1701,1702,1703,1731 26.04.17 16:56:52.651 TRTSPUDPClient Release Digital TV (5) 26.04.17 16:56:52.651 TRTSPUDPClient Free Digital TV (5) 26.04.17 16:56:52.854 TRTSPUDPClient Freed Digital TV (5) 26.04.17 16:56:52.854 TRTSPUDPClient hamDeleted Digital TV (5) 26.04.17 16:56:52.854 TVCR No shutdown allowed next recording: 26/04/2017 16:57:00 26.04.17 16:56:52.854 TRecordingEngine ReleaseReference RTSP-Client 192.168.1.199: 0 26.04.17 16:56:59.164 SetStandbyBlock RTSP-Client 192.168.1.199 26.04.17 16:56:59.164 TRecordingEngine AddReference RTSP-Client 192.168.1.199: 1 26.04.17 16:56:59.164 TRTSPUDPClient SendBufSizeUDP 13280000 26.04.17 16:56:59.164 TRTSPUDPClient SetTuner TType: 2, Freq: 514000, Symrate: 0, LOF: 0, Tone: 0, Pol: 2, DiseqC: 0, FEC: 0, APID: 0, VPID: 0, PMT: 0, SID: 0, TID: 0, NID: 0, SatMod: 0, DiseqCVal: 0, Flags: 0 26.04.17 16:56:59.461 TBDATeVii OpenDevice bvTeVii 26.04.17 16:56:59.461 TRTSPUDPClient AllocateHardware Digital TV (5) 26.04.17 16:56:59.461 TRTSPUDPClient SetTuner Got new hardware 26.04.17 16:56:59.461 TBDATeVii SetTuner TType: 2, Freq: 514000, Symrate: 0, LOF: 0, Tone: 0, Pol: 2, DiseqC: 0, FEC: 0, APID: 0, VPID: 0, PMT: 0, SID: 0, TID: 0, NID: 0, SatMod: 0, DiseqCVal: 0, Flags: 0 26.04.17 16:57:00.132 TRTSPUDPClient SetTuner Tuner set 26.04.17 16:57:00.132 TRTSPUDPClient AddPids 0,1,16,17,18,1700,1701,1702,1703,1731 26.04.17 16:57:00.388 TBDA_TBS OpenDevice bvTurbosightNew 26.04.17 16:57:00.388 TRecording AllocateHardware TBS 6280 DVBT/T2 Tuner A (1) 26.04.17 16:57:00.388 TRecording StartRecording TBS 6280 DVBT/T2 Tuner A (1) 26.04.17 16:57:00.388 TBDA_TBS SetTuner TType: 2, Freq: 546000, Symrate: 0, LOF: 0, Tone: 0, Pol: 2, DiseqC: 0, FEC: 0, APID: 202, VPID: 201, PMT: 200, SID: 17604, TID: 16516, NID: 9018, SatMod: 4, DiseqCVal: 0, Flags: 24 26.04.17 16:57:03.533 TRecording StartRecording: ITV HD 26.04.17 16:57:03.536 TRecordingEngine AddReference TRecording: 2 26.04.17 16:57:03.537 TRTSPUDPClient Release Digital TV (5) 26.04.17 16:57:03.537 TRTSPUDPClient Free Digital TV (5) 26.04.17 16:57:03.740 TRTSPUDPClient Freed Digital TV (5) 26.04.17 16:57:03.740 TRTSPUDPClient hamDeleted Digital TV (5) 26.04.17 16:57:03.740 TRecordingEngine ReleaseReference RTSP-Client 192.168.1.199: 1
Not sure why I get a TCP Restransmission - this seems to happen on every first-connect attempt, but subsequent connections seem ok as you can see, but all have the six second delay.
Updated by Jaroslav Kysela over 7 years ago
It might be also a weird network issue. It seems that the packets are not delivered in time. Perhaps, you may run wireshark on both server / client and compare sent / received packets. But then - it's difficult to recommend something. It might be anything bad in any system or in the network which connects the server and client.
Updated by Joe User over 7 years ago
Updated by Is the channel you are trying to play available on different muxes? It appears that the server is trying to use different tuners. Have you tries playing the service directly (instead of the channel)? Not sure if you can play a whole mux over sat->ip, but you can give that a try also and see what you get. Did you try to use just one tuner from the server?
Updated by Laurie Davis over 7 years ago
No, the channel is only on one mux. I tried playing the service directly and still get the same issue. It's only using one tuner as I only have one of them enabled in TVH.
I've now installed the RS server on a different Windows PC and am not seeing this issue when TVH connects to it, so it must be something odd about my main PC that I'll need to investigate.
Updated by Joe User over 7 years ago
Only one enabled on Tvheadend, but how many on your server? Your log seems to show the first and last tuner are different...
26.04.17 16:56:43.166 TRTSPUDPClient SetTuner TType: 2, Freq: 514000, Symrate: 0, LOF: 0, Tone: 0, Pol: 2, DiseqC: 0, FEC: 0, APID: 0, VPID: 0, PMT: 0, SID: 0, TID: 0, NID: 0, SatMod: 0, DiseqCVal: 0, Flags: 0 26.04.17 16:56:43.472 TBDATeVii OpenDevice bvTeVii
26.04.17 16:57:00.388 TBDA_TBS OpenDevice bvTurbosightNew 26.04.17 16:57:00.388 TRecording AllocateHardware TBS 6280 DVBT/T2 Tuner A (1) 26.04.17 16:57:00.388 TRecording StartRecording TBS 6280 DVBT/T2 Tuner A (1) 26.04.17 16:57:00.388 TBDA_TBS SetTuner TType: 2, Freq: 546000, Symrate: 0, LOF: 0, Tone: 0, Pol: 2, DiseqC: 0, FEC: 0, APID: 202, VPID: 201, PMT: 200, SID: 17604, TID: 16516, NID: 9018, SatMod: 4, DiseqCVal: 0, Flags: 24 26.04.17 16:57:03.533 TRecording StartRecording: ITV HD
Updated by Laurie Davis over 7 years ago
Ignore that - at the time I was testing, RS started a scheduled recording on a different tuner.
Updated by Laurie Davis over 7 years ago
I'm really getting nowhere with this despite checking everything I can think of. I raised it with the DVBViewer devs, but they are being their usual less-than-helpful selves
I only need a few more seconds tolerance on the response to the SETUP command, so would it be possible to increase this in TVH to, say, 10 seconds? Or, better still, add an entry in the UI so users can set their own timeout if needed, but default it to 5 secs (which looks like it's the current timeout). This would be a big help 
I should just say again, the OTA EPG grabber connects fine to the DVBViewer RS using SATIP, so that must already have a longer timeout on the SETUP command.
Thanks, in advance.
Updated by Jaroslav Kysela over 7 years ago
- Status changed from New to Fixed
- % Done changed from 0 to 100
Applied in changeset commit:tvheadend|ee76167205559add012953bf2ff63d494114df4f.
Updated by Jaroslav Kysela over 7 years ago
Fixed in v4.3-76-gee76167 - added 'Grace period' option to the SAT>IP client.
Updated by Laurie Davis over 7 years ago
Success! Just tried it and it seems to work fine. Many thanks for the swift response