search

FernetMenta / vdr-plugin-vnsiserver

VDR plugin to handle XBMC clients.
GNU General Public License v2.0
16 stars 33 forks source link

Switching issue #99

Open Karl-opec opened 7 years ago

Karl-opec commented 7 years ago

I ran a vdr-2.3.8 server with vnsiserver newest Git. Clients are libreelec newest git. Both software is self compiled. The channels are supplied by DVB-C devices and Sat channels by an satip server via VDR-PLUGIN-SATIP. Everythings works generally.

But i have the following issue: start streaming a satip supplied channel works. Switching from a streaming channel to an other satip supplied channel does not work, see attached log:

Aug 24 11:08:53 vnas1 vdr[6706]: [8278] VNSI: Welcome client 'XBMC Media Center' with protocol version '11'
Aug 24 11:08:53 vnas1 vdr[6706]: [8278] VNSI: LiveStreamer::Close - close
Aug 24 11:08:53 vnas1 vdr[6706]: [8278] VNSI: close video input ...
Aug 24 11:08:53 vnas1 vdr[6706]: [8278] VNSI: Successfully found following device: 0x13f9ea0 (3) for receiving, priority=0
Aug 24 11:08:53 vnas1 vdr[6706]: [8278] VNSI: Dummy receiver (0x7ff59c0a6290) activated
Aug 24 11:08:53 vnas1 vdr[6706]: [8278] VNSI: activate live receiver: 1
Aug 24 11:08:53 vnas1 vdr[6706]: [8278] VNSI: Successfully switched to channel 1 - Das Erste HD
Aug 24 11:08:53 vnas1 vdr[6706]: [8278] VNSI: Started streaming of channel Das Erste HD (timeout 14 seconds)
Aug 24 11:08:53 vnas1 vdr[6706]: [6715] SATIP: Detected 4 RTP packet errors [device 0]
Aug 24 11:08:53 vnas1 vdr[6706]: [8280] VNSI: Created stream for pid=5101 and type=8
Aug 24 11:08:53 vnas1 vdr[6706]: [8280] VNSI: Created stream for pid=5106 and type=1
Aug 24 11:08:53 vnas1 vdr[6706]: [8280] VNSI: Created stream for pid=5102 and type=2
Aug 24 11:08:53 vnas1 vdr[6706]: [8280] VNSI: Created stream for pid=5103 and type=2
Aug 24 11:08:53 vnas1 vdr[6706]: [8280] VNSI: Created stream for pid=5105 and type=10
Aug 24 11:08:53 vnas1 vdr[6706]: [8280] VNSI: Created stream for pid=5104 and type=12
Aug 24 11:08:53 vnas1 vdr[6706]: [8280] VNSI: Audio stream change, pid: 5106, channels: 2, samplerate: 48000
Aug 24 11:08:53 vnas1 vdr[6706]: [8280] VNSI: Audio stream change, pid: 5102, channels: 2, samplerate: 48000
Aug 24 11:08:53 vnas1 vdr[6706]: [8280] VNSI: Audio stream change, pid: 5103, channels: 2, samplerate: 48000
Aug 24 11:08:54 vnas1 vdr[6706]: [6706] ERROR: no OSD provider available - using dummy OSD!
Aug 24 11:08:54 vnas1 vdr[6706]: [8280] VNSI: Video stream change, pid: 5101, width: 1280, height: 720, aspect: 1,777778
Aug 24 11:09:12 vnas1 vdr[6706]: [6723] SATIP: Idle timeout - releasing [device 2]
Aug 24 11:09:19 vnas1 vdr[6706]: [8280] VNSI: exit streamer thread
Aug 24 11:09:19 vnas1 vdr[6706]: [8278] VNSI: LiveStreamer::Close - close
Aug 24 11:09:19 vnas1 vdr[6706]: [8278] VNSI: close video input ...
Aug 24 11:09:19 vnas1 vdr[6706]: [8278] VNSI: activate live receiver: 0
Aug 24 11:09:19 vnas1 vdr[6706]: [8278] VNSI: Dummy receiver (0x7ff59c0a6290) deactivated
Aug 24 11:09:19 vnas1 vdr[6706]: [8278] VNSI: close video input ...
Aug 24 11:09:19 vnas1 vdr[6706]: [8278] VNSI: LiveStreamer::Close - close
Aug 24 11:09:19 vnas1 vdr[6706]: [8278] VNSI: close video input ...
Aug 24 11:09:19 vnas1 vdr[6706]: [8278] VNSI: Successfully found following device: 0x13f9ea0 (3) for receiving, priority=0
Aug 24 11:09:19 vnas1 vdr[6706]: [8278] VNSI: Dummy receiver (0x7ff59c0a6290) activated
Aug 24 11:09:19 vnas1 vdr[6706]: [8278] VNSI: activate live receiver: 1
Aug 24 11:09:19 vnas1 vdr[6706]: [8278] VNSI: Successfully switched to channel 2 - ZDF HD
Aug 24 11:09:19 vnas1 vdr[6706]: [8278] VNSI: Started streaming of channel ZDF HD (timeout 14 seconds)
Aug 24 11:09:20 vnas1 vdr[6706]: [6706] ERROR: no OSD provider available - using dummy OSD!
Aug 24 11:09:33 vnas1 vdr[6706]: [8285] VNSI: Channel: no data 16
Aug 24 11:09:47 vnas1 vdr[6706]: [8285] VNSI: Channel: no data 16
Aug 24 11:10:01 vnas1 vdr[6706]: [8285] VNSI: Channel: no data 16
Aug 24 11:10:15 vnas1 vdr[6706]: [8285] VNSI: Channel: no data 16
Aug 24 11:10:15 vnas1 vdr[6706]: [8285] VNSI: exit streamer thread
Aug 24 11:10:15 vnas1 vdr[6706]: [8278] VNSI: LiveStreamer::Close - close
Aug 24 11:10:15 vnas1 vdr[6706]: [8278] VNSI: close video input ...
Aug 24 11:10:15 vnas1 vdr[6706]: [8278] VNSI: activate live receiver: 0
Aug 24 11:10:15 vnas1 vdr[6706]: [8278] VNSI: Dummy receiver (0x7ff59c0a6290) deactivated
Aug 24 11:10:15 vnas1 vdr[6706]: [8278] VNSI: close video input ...
Aug 24 11:10:15 vnas1 vdr[6706]: [8278] VNSI: cxSocket::read(fd=58): eof, connection closed
Aug 24 11:10:15 vnas1 vdr[6706]: [6737] VNSI: Client with ID 24 seems to be disconnected, removing from client list

Switching streaming channels from DVB-C devices does Work with no Problems. in the following Log start satip Channel (ARD) then switch to DVB-C (TNT-Comedy) and then to DVB-C /Syfy) works as it should:

Aug 24 11:48:06 vnas1 vdr[6706]: [8426] VNSI: Successfully found following device: 0x13f9ea0 (3) for receiving, priority=0
Aug 24 11:48:06 vnas1 vdr[6706]: [8426] VNSI: Dummy receiver (0x7ff530004e70) activated
Aug 24 11:48:06 vnas1 vdr[6706]: [8426] VNSI: activate live receiver: 1
Aug 24 11:48:06 vnas1 vdr[6706]: [8426] VNSI: Successfully switched to channel 1 - Das Erste HD
Aug 24 11:48:06 vnas1 vdr[6706]: [8426] VNSI: Started streaming of channel Das Erste HD (timeout 14 seconds)
Aug 24 11:48:06 vnas1 vdr[6706]: [8428] VNSI: Created stream for pid=5101 and type=8
Aug 24 11:48:06 vnas1 vdr[6706]: [8428] VNSI: Created stream for pid=5106 and type=1
Aug 24 11:48:06 vnas1 vdr[6706]: [8428] VNSI: Created stream for pid=5102 and type=2
Aug 24 11:48:06 vnas1 vdr[6706]: [8428] VNSI: Created stream for pid=5103 and type=2
Aug 24 11:48:06 vnas1 vdr[6706]: [8428] VNSI: Created stream for pid=5105 and type=10
Aug 24 11:48:06 vnas1 vdr[6706]: [8428] VNSI: Created stream for pid=5104 and type=12
Aug 24 11:48:06 vnas1 vdr[6706]: [8428] VNSI: Audio stream change, pid: 5102, channels: 2, samplerate: 48000
Aug 24 11:48:06 vnas1 vdr[6706]: [8428] VNSI: Audio stream change, pid: 5103, channels: 2, samplerate: 48000
Aug 24 11:48:06 vnas1 vdr[6706]: [8428] VNSI: Audio stream change, pid: 5106, channels: 2, samplerate: 48000
Aug 24 11:48:07 vnas1 vdr[6706]: [8428] VNSI: Video stream change, pid: 5101, width: 1280, height: 720, aspect: 1,777778
Aug 24 11:48:14 vnas1 vdr[6706]: [8428] VNSI: exit streamer thread
Aug 24 11:48:14 vnas1 vdr[6706]: [8426] VNSI: LiveStreamer::Close - close
Aug 24 11:48:14 vnas1 vdr[6706]: [8426] VNSI: close video input ...
Aug 24 11:48:14 vnas1 vdr[6706]: [8426] VNSI: activate live receiver: 0
Aug 24 11:48:14 vnas1 vdr[6706]: [8426] VNSI: Dummy receiver (0x7ff530004e70) deactivated
Aug 24 11:48:14 vnas1 vdr[6706]: [8426] VNSI: close video input ...
Aug 24 11:48:14 vnas1 vdr[6706]: [8426] VNSI: LiveStreamer::Close - close
Aug 24 11:48:14 vnas1 vdr[6706]: [8426] VNSI: close video input ...
Aug 24 11:48:14 vnas1 vdr[6706]: [8426] VNSI: Successfully found following device: 0x13cb4b0 (1) for receiving, priority=0
Aug 24 11:48:14 vnas1 vdr[6706]: [8426] dvb tuner: power-up - opening frontend 0/0
Aug 24 11:48:14 vnas1 vdr[6706]: [8426] VNSI: Dummy receiver (0x7ff5300a31c0) activated
Aug 24 11:48:14 vnas1 vdr[6706]: [8426] VNSI: activate live receiver: 1
Aug 24 11:48:14 vnas1 vdr[6706]: [8426] DVBAPI: 0.0 set CAM decrypt (SID 38102 (0x94D6), caLm 4, HasCaDescriptors 0)
Aug 24 11:48:14 vnas1 vdr[6706]: [8426] VNSI: Successfully switched to channel 27 - TNT Comedy HD
Aug 24 11:48:14 vnas1 vdr[6706]: [8426] VNSI: Started streaming of channel TNT Comedy HD (timeout 14 seconds)
Aug 24 11:48:15 vnas1 vdr[6706]: [8432] VNSI: Created stream for pid=523 and type=8
Aug 24 11:48:15 vnas1 vdr[6706]: [8432] VNSI: Created stream for pid=524 and type=1
Aug 24 11:48:15 vnas1 vdr[6706]: [8432] VNSI: Created stream for pid=525 and type=2
Aug 24 11:48:15 vnas1 vdr[6706]: [8432] VNSI: Created stream for pid=526 and type=2
Aug 24 11:48:15 vnas1 vdr[6706]: [6706] ERROR: no OSD provider available - using dummy OSD!
Aug 24 11:48:16 vnas1 vdr[6706]: [6737] VNSI: Requesting clients to reload channel list
Aug 24 11:48:16 vnas1 vdr[6706]: [6706] VNSI: re-tune to channel TNT Comedy HD
Aug 24 11:48:16 vnas1 vdr[6706]: [8432] VNSI: re-tuning...
Aug 24 11:48:16 vnas1 vdr[6706]: [8432] VNSI: close video input ...
Aug 24 11:48:16 vnas1 vdr[6706]: [8432] VNSI: activate live receiver: 0
Aug 24 11:48:16 vnas1 vdr[6706]: [8432] VNSI: Dummy receiver (0x7ff5300a31c0) deactivated
Aug 24 11:48:16 vnas1 vdr[6706]: [8432] VNSI: Successfully found following device: 0x13cb4b0 (1) for receiving, priority=0
Aug 24 11:48:16 vnas1 vdr[6706]: [8432] VNSI: Dummy receiver (0x7ff59c0a6400) activated
Aug 24 11:48:16 vnas1 vdr[6706]: [8432] VNSI: activate live receiver: 1
Aug 24 11:48:16 vnas1 vdr[6706]: [8432] DVBAPI: 0.0 set CAM decrypt (SID 38102 (0x94D6), caLm 4, HasCaDescriptors 1)
Aug 24 11:48:17 vnas1 vdr[6706]: [8432] VNSI: Audio stream change, pid: 524, channels: 6, samplerate: 48000
Aug 24 11:48:17 vnas1 vdr[6706]: [8432] VNSI: Audio stream change, pid: 526, channels: 2, samplerate: 48000
Aug 24 11:48:17 vnas1 vdr[6706]: [8432] VNSI: Audio stream change, pid: 525, channels: 2, samplerate: 48000
Aug 24 11:48:17 vnas1 vdr[6706]: [8432] VNSI: Video stream change, pid: 523, width: 1920, height: 1080, aspect: 1,777778
Aug 24 11:48:21 vnas1 vdr[6706]: [6737] VNSI: Requesting clients to reload channel list
Aug 24 11:48:23 vnas1 vdr[6706]: [8432] VNSI: exit streamer thread
Aug 24 11:48:23 vnas1 vdr[6706]: [8426] VNSI: LiveStreamer::Close - close
Aug 24 11:48:23 vnas1 vdr[6706]: [8426] VNSI: close video input ...
Aug 24 11:48:23 vnas1 vdr[6706]: [8426] VNSI: activate live receiver: 0
Aug 24 11:48:23 vnas1 vdr[6706]: [8426] VNSI: Dummy receiver (0x7ff59c0a6400) deactivated
Aug 24 11:48:23 vnas1 vdr[6706]: [8426] VNSI: close video input ...
Aug 24 11:48:23 vnas1 vdr[6706]: [8426] VNSI: LiveStreamer::Close - close
Aug 24 11:48:23 vnas1 vdr[6706]: [8426] VNSI: close video input ...
Aug 24 11:48:23 vnas1 vdr[6706]: [8426] VNSI: Successfully found following device: 0x13cb4b0 (1) for receiving, priority=0
Aug 24 11:48:23 vnas1 vdr[6706]: [8426] VNSI: Dummy receiver (0x7ff530013460) activated
Aug 24 11:48:23 vnas1 vdr[6706]: [8426] VNSI: activate live receiver: 1
Aug 24 11:48:23 vnas1 vdr[6706]: [8426] DVBAPI: 0.0 set CAM decrypt (SID 27114 (0x69EA), caLm 4, HasCaDescriptors 1)
Aug 24 11:48:23 vnas1 vdr[6706]: [8426] VNSI: Successfully switched to channel 28 - SyFy HD
Aug 24 11:48:23 vnas1 vdr[6706]: [8426] VNSI: Started streaming of channel SyFy HD (timeout 14 seconds)
Aug 24 11:48:23 vnas1 vdr[6706]: [8449] VNSI: Created stream for pid=543 and type=8
Aug 24 11:48:23 vnas1 vdr[6706]: [8449] VNSI: Created stream for pid=544 and type=1
Aug 24 11:48:23 vnas1 vdr[6706]: [8449] VNSI: Created stream for pid=545 and type=1
Aug 24 11:48:23 vnas1 vdr[6706]: [6706] ERROR: no OSD provider available - using dummy OSD!
Aug 24 11:48:24 vnas1 vdr[6706]: [8449] VNSI: Audio stream change, pid: 544, channels: 6, samplerate: 48000
Aug 24 11:48:24 vnas1 vdr[6706]: [8449] VNSI: Audio stream change, pid: 545, channels: 2, samplerate: 48000
Aug 24 11:48:24 vnas1 vdr[6706]: [8449] VNSI: Video stream change, pid: 543, width: 1920, height: 1080, aspect: 1,777778
Aug 24 11:48:33 vnas1 vdr[6706]: [8449] VNSI: exit streamer thread
Aug 24 11:48:33 vnas1 vdr[6706]: [8426] VNSI: LiveStreamer::Close - close
Aug 24 11:48:33 vnas1 vdr[6706]: [8426] VNSI: close video input ...
Aug 24 11:48:33 vnas1 vdr[6706]: [8426] VNSI: activate live receiver: 0
Aug 24 11:48:33 vnas1 vdr[6706]: [8426] VNSI: Dummy receiver (0x7ff530013460) deactivated
Aug 24 11:48:33 vnas1 vdr[6706]: [8426] VNSI: close video input ...
Aug 24 11:48:33 vnas1 vdr[6706]: [8426] VNSI: cxSocket::read(fd=40): eof, connection closed
Aug 24 11:48:33 vnas1 vdr[6706]: [6737] VNSI: Client with ID 32 seems to be disconnected, removing from client list

Its annoying that for SATIP Channels the stream has to bee stopped and then the switched channel to be started.

Any Idea for the cause of this?

best regards

seahawk1986 commented 7 years ago

How many tuners are available to the satip plugin? By default the plugin expects 2 usable Sat>IP tuners:


Configuration:

The plugin accepts a "--devices" (-d) command-line parameter defaulting
to two. This parameter defines how many simultaneous transponders can
be received, if there are available SAT>IP tuners.

If only one Tuner is available, you need to set -d 1 or it will fail when trying to use the second tuner.

Karl-opec commented 7 years ago

The satip Server has 8 Tuners and I have set -d 8 to the satip plugin.

Karl-opec commented 7 years ago

I have opened the same issue on the satip git. The satip author commented the following:

Incompatibility  to receiver handling done in VNSI plugin. Satip detects that no one is
using any receivers on the device and shutting it down to prevent  unnecessary
network traffic.

https://github.com/rofafor/vdr-plugin-satip/issues/42

What can i do to help to diagnose the base of the issue?

FernetMenta commented 7 years ago

That explanations sounds very strange. On channel change vnsi closes the active receiver and creates a new one. That may take a few milli seconds. You won't expects any resource shutting down due to some ms of inactivity, will you?

Karl-opec commented 7 years ago

I don't have an answer for that. milliseconds might have an impact. Perhaps it is an issue with the changed locking sequence in vdr since 2.3.6. where vnsi and satip have some deadlocks?

My observations are: start a satip channel gives a vnsi VNSI: Channel: no data 16 , stopping it and starting it again gives a streaming channel. switching to an other satip channel the gives VNSI: Channel: no data 16 stopping it and start again gives streaming channel. When vdr start a recording of a satip channel it works as it should.

Anyhow how to proceed from here?

FernetMenta commented 7 years ago

the reported issue can occur if the selected channel has no valid PIDs at the time it is activated and the device does not implement ChannelChange status message.