Project

General

Profile

Urgently need help debugging server playback problems

Added by Paul Farquhar over 9 years ago

After my difficulties with the older tvheadend server I decided to upgrade to the latest version.
I am now running HTS Tvheadend 3.9.2670~g08c4af7~precise

I still have substantial problems and need help to debug what is going wrong.

The problem is: Playback of recorded live TV and live TV suffer from clients having to reconnect during playback.

Clients are kodi 14.2
Both use the pvr.tvh addon 0.98 from here: http://stalin.negge.fi/files/pvr.tvh/

In the output below I started two clients, one openelec the other Win7. The clients were not started at the same time as you can see from the fileRead debug messages.

I started playback of two different live TV recordings - both failed at the exact same time.
As both clients failed I would expect the problem to be with the server.
I have checked the network, even connected client and server on a switch - I still have connection problems.

I also tried a much older openelec version with the xbmc tvheadend pluging - same result, playback stops.

The server runs Ubuntu 12.04.5 LTS (GNU/Linux 3.11.0-24-generic x86_64)

How can I narrow down what is going on?
What is causing the server not to respond?

A my family uses tvheadend to watch TV I really have a serious problem!
I am thankful for all the help I can get.

Thanks,

Paul

Debug outputs:
Win7 (192.168.178.37):
03:20:34 T:9584 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - sending message [fileRead : 512]
03:20:34 T:4960 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - received response [512]
03:20:35 T:9584 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - vfs read id=2 size=969197
03:20:35 T:9584 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - sending message [fileRead : 513]
03:20:39 T:9584 ERROR: AddOnLog: Tvheadend Client: pvr.tvh - Command fileRead failed: No response received
03:20:39 T:9584 ERROR: ffmpeg2570: [matroska,webm] Read error

03:20:39 T:4960 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - connecting to tvserver:9982
03:20:39 T:9584 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - vfs read id=2 size=969197
03:20:39 T:4960 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - waiting for connection...
03:20:39 T:9584 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - waiting for registration...
03:20:39 T:4960 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - connected
03:20:39 T:9968 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - sending hello
03:20:39 T:9968 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - sending message [hello : 1]
03:20:39 T:4960 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - received response [1]
03:20:39 T:9968 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - connected to HTS Tvheadend / 3.9.2670~g08c4af7~precise (HTSPv19)

openelec (192.168.178.57) time skewed by 2 hours:
01:20:34 T:140225221216000 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - vfs read id=2 size=986587
01:20:34 T:140225221216000 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - sending message [fileRead : 285]
01:20:34 T:140225873274624 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - received response [285]
01:20:34 T:140225086183168 DEBUG: webserver: request received for /jsonrpc?Player.GetActivePlayers
01:20:34 T:140225330255616 DEBUG: webserver: request received for /jsonrpc?Player.GetProperties
01:20:34 T:140225112176384 DEBUG: webserver: request received for /jsonrpc?Playlist.GetItems
01:20:34 T:140225112176384 DEBUG: webserver: request received for /jsonrpc?Player.GetItem
01:20:34 T:140225221216000 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - vfs read id=2 size=984179
01:20:34 T:140225221216000 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - sending message [fileRead : 286]
01:20:35 T:140225873274624 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - received response [286]
01:20:35 T:140225221216000 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - vfs read id=2 size=934934
01:20:35 T:140225221216000 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - sending message [fileRead : 287]
01:20:36 T:140225112176384 DEBUG: webserver: request received for /jsonrpc?Player.GetActivePlayers
01:20:36 T:140225330255616 DEBUG: webserver: request received for /jsonrpc?Player.GetProperties
01:20:36 T:140225086183168 DEBUG: webserver: request received for /jsonrpc?Playlist.GetItems
01:20:36 T:140225086183168 DEBUG: webserver: request received for /jsonrpc?Player.GetItem
01:20:38 T:140225086183168 DEBUG: webserver: request received for /jsonrpc?Player.GetActivePlayers
01:20:38 T:140225330255616 DEBUG: webserver: request received for /jsonrpc?Player.GetProperties
01:20:38 T:140225112176384 DEBUG: webserver: request received for /jsonrpc?Playlist.GetItems
01:20:38 T:140225112176384 DEBUG: webserver: request received for /jsonrpc?Player.GetItem
01:20:39 T:140225221216000 ERROR: AddOnLog: Tvheadend Client: pvr.tvh - Command fileRead failed: No response received
01:20:39 T:140225221216000 ERROR: ffmpeg[7F88BA7FC700]: [matroska,webm] Read error

01:20:39 T:140225221216000 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - vfs read id=2 size=967702
01:20:39 T:140225221216000 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - sending message [fileRead : 288]
01:20:39 T:140225221216000 ERROR: AddOnLog: Tvheadend Client: pvr.tvh - failed to write (Invalid argument)
01:20:39 T:140225221216000 ERROR: AddOnLog: Tvheadend Client: pvr.tvh - failed to transmit
01:20:39 T:140225221216000 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - vfs read id=2 size=967702
01:20:39 T:140225221216000 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - sending message [fileRead : 289]
01:20:39 T:140225221216000 ERROR: AddOnLog: Tvheadend Client: pvr.tvh - failed to write (Invalid argument)
01:20:39 T:140225221216000 ERROR: AddOnLog: Tvheadend Client: pvr.tvh - failed to transmit
01:20:39 T:140225873274624 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - connecting to tvserver:9982
01:20:39 T:140225873274624 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - waiting for connection...
01:20:39 T:140225873274624 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - connected
01:20:39 T:140225498048256 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - sending hello
01:20:39 T:140225498048256 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - sending message [hello : 1]
01:20:39 T:140225873274624 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - received response [1]
01:20:39 T:140225498048256 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - connected to HTS Tvheadend / 3.9.2670~g08c4af7~precise (HTSPv19)

syslog ouput in webtool from tvheadend:
2015-04-06 03:20:35.000 mpegts: 11361.75H in 19.2 - tuning on STV090x Multistandard : DVB-S #2
2015-04-06 03:20:37.563 subscription: 015A: "scan" subscribing to mux "11361.75H", weight: 2, adapter: "STV090x Multistandard : DVB-S #2", network: "19.2", service: "Raw PID Subscription"
2015-04-06 03:20:37.563 mpegts: 11347V in 19.2 - tuning on STV090x Multistandard : DVB-S #1
2015-04-06 03:20:38.427 subscription: 015B: "scan" subscribing to mux "11347V", weight: 2, adapter: "STV090x Multistandard : DVB-S #1", network: "19.2", service: "Raw PID Subscription"
2015-04-06 03:20:38.427 mpegts: 11552.75H in 19.2 - tuning on STV090x Multistandard : DVB-S #0
2015-04-06 03:20:39.139 subscription: 015C: "scan" subscribing to mux "11552.75H", weight: 2, adapter: "STV090x Multistandard : DVB-S #0", network: "19.2", service: "Raw PID Subscription"
2015-04-06 03:20:39.727 htsp: 192.168.178.37 [ tv | XBMC Media Center ]: Disconnected
2015-04-06 03:20:39.730 htsp: Got connection from 192.168.178.37
2015-04-06 03:20:39.730 htsp: 192.168.178.37: Welcomed client software: XBMC Media Center (HTSPv12)
2015-04-06 03:20:39.731 htsp: Got connection from 192.168.178.57
2015-04-06 03:20:39.731 htsp: 192.168.178.57: Welcomed client software: XBMC Media Center (HTSPv12)
2015-04-06 03:20:39.731 htsp: 192.168.178.57 [ XBMC Media Center ]: Write error -- Broken pipe
2015-04-06 03:20:39.731 htsp: 192.168.178.37 [ tv | XBMC Media Center ]: Write error -- Broken pipe
2015-04-06 03:20:39.731 htsp: 192.168.178.57 [ XBMC Media Center ]: Disconnected
2015-04-06 03:20:39.794 htsp: 192.168.178.37 [ XBMC Media Center ]: Identified as user tv
2015-04-06 03:20:39.794 htsp: 192.168.178.37 [ tv | XBMC Media Center ]: Privileges raised
2015-04-06 03:20:44.028 htsp: 192.168.178.37 [ tv | XBMC Media Center ]: Write error -- Connection reset by peer
2015-04-06 03:20:44.028 htsp: 192.168.178.37 [ tv | XBMC Media Center ]: Disconnected
2015-04-06 03:20:44.093 htsp: Got connection from 192.168.178.37
2015-04-06 03:20:44.287 htsp: 192.168.178.37: Welcomed client software: XBMC Media Center (HTSPv12)
2015-04-06 03:20:44.441 htsp: 192.168.178.37 [ XBMC Media Center ]: Identified as user tv
2015-04-06 03:20:44.441 htsp: 192.168.178.37 [ tv | XBMC Media Center ]: Privileges raised
2015-04-06 03:20:45.000 mpegts: 11552.75H in 19.2 - scan needs more time
2015-04-06 03:20:45.000 mpegts: 11347V in 19.2 - scan needs more time
2015-04-06 03:20:45.000 mpegts: 11361.75H in 19.2 - scan needs more time
2015-04-06 03:20:47.235 htsp: 192.168.178.37 [ tv | XBMC Media Center ]: Write error -- Connection reset by peer
2015-04-06 03:20:47.288 htsp: 192.168.178.37 [ tv | XBMC Media Center ]: Disconnected
2015-04-06 03:20:47.444 htsp: Got connection from 192.168.178.37
2015-04-06 03:20:47.444 htsp: 192.168.178.37: Welcomed client software: XBMC Media Center (HTSPv12)
2015-04-06 03:20:47.595 htsp: 192.168.178.37 [ XBMC Media Center ]: Identified as user tv
2015-04-06 03:20:47.595 htsp: 192.168.178.37 [ tv | XBMC Media Center ]: Privileges raised
2015-04-06 03:20:48.996 htsp: 192.168.178.37 [ tv | XBMC Media Center ]: Write error -- Connection reset by peer
2015-04-06 03:20:48.996 htsp: 192.168.178.37 [ tv | XBMC Media Center ]: Disconnected
2015-04-06 03:20:49.132 htsp: Got connection from 192.168.178.37
2015-04-06 03:20:49.286 htsp: 192.168.178.37: Welcomed client software: XBMC Media Center (HTSPv12)
2015-04-06 03:20:49.594 htsp: 192.168.178.37 [ XBMC Media Center ]: Identified as user tv
2015-04-06 03:20:49.594 htsp: 192.168.178.37 [ tv | XBMC Media Center ]: Privileges raised
2015-04-06 03:20:52.773 mpegts: 11361.75H in 19.2 scan complete
2015-04-06 03:20:52.773 subscription: 015A: "scan" unsubscribing
2015-04-06 03:20:54.449 htsp: 192.168.178.37 [ tv | XBMC Media Center ]: Write error -- Connection reset by peer
2015-04-06 03:20:54.449 htsp: 192.168.178.37 [ tv | XBMC Media Center ]: Disconnected
2015-04-06 03:20:54.627 htsp: Got connection from 192.168.178.37
2015-04-06 03:20:54.773 htsp: 192.168.178.37: Welcomed client software: XBMC Media Center (HTSPv12)
2015-04-06 03:20:54.881 htsp: 192.168.178.37 [ XBMC Media Center ]: Identified as user tv
2015-04-06 03:20:54.881 htsp: 192.168.178.37 [ tv | XBMC Media Center ]: Privileges raised

2015-04-06 03:20:58.287 mpegts: 11552.75H in 19.2 scan complete
2015-04-06 03:20:58.287 subscription: 015C: "scan" unsubscribing
2015-04-06 03:20:58.287 subscription: 015B: "scan" unsubscribing
2015-04-06 03:21:08.000 mpegts: 11626.5V in 19.2 - tuning on STV090x Multistandard : DVB-S #2
2015-04-06 03:21:10.627 subscription: 015E: "scan" subscribing to mux "11626.5V", weight: 2, adapter: "STV090x Multistandard : DVB-S #2", network: "19.2", service: "Raw PID Subscription"
2015-04-06 03:21:10.627 mpegts: 11670.75H in 19.2 - tuning on STV090x Multistandard : DVB-S #1
2015-04-06 03:21:13.007 subscription: 015F: "scan" subscribing to mux "11670.75H", weight: 2, adapter: "STV090x Multistandard : DVB-S #1", network: "19.2", service: "Raw PID Subscription"
2015-04-06 03:21:13.007 mpegts: 12109.5H in 19.2 - tuning on STV090x Multistandard : DVB-S #0
2015-04-06 03:21:14.199 subscription: 0160: "scan" subscribing to mux "12109.5H", weight: 2, adapter: "STV090x Multistandard : DVB-S #0", network: "19.2", service: "Raw PID Subscription"
2015-04-06 03:21:18.000 mpegts: 12109.5H in 19.2 - scan needs more time
2015-04-06 03:21:18.000 mpegts: 11670.75H in 19.2 - scan needs more time
2015-04-06 03:21:18.000 mpegts: 11626.5V in 19.2 - scan needs more time