Tvheadend

I've tried to replicate it this morning and haven't been able to. I've left the debug logs on to try and get that log when I catch it. Meanwhile here's what I caught in the tvheadend syslog:

Aug  6 21:12:00 ulisses tvheadend[979]: dvr: Recording completed: "/home/hts/2013-08-06/RTP 1-Telejornal.2013-08-06.20-00.ts" 
Aug  6 21:12:00 ulisses tvheadend[979]: dvr: "Telejornal" on "RTP 1": End of program: Completed OK
Aug  6 22:52:56 ulisses tvheadend[979]: htsp: Got connection from 10.23.67.219
Aug  6 22:52:56 ulisses tvheadend[979]: htsp: 10.23.67.219: Welcomed client software: XBMC Media Center (HTSPv8)
Aug  6 22:52:56 ulisses tvheadend[979]: htsp: 10.23.67.219 [ XBMC Media Center ]: Identified as user admin
Aug  6 22:52:56 ulisses tvheadend[979]: htsp: 10.23.67.219 [ admin | XBMC Media Center ]: Privileges raised
Aug  6 22:54:09 ulisses tvheadend[979]: htsp: 10.23.67.219 [ admin | XBMC Media Center ]: Write error -- Connection reset by peer
Aug  6 22:54:09 ulisses tvheadend[979]: htsp: 10.23.67.219 [ admin | XBMC Media Center ]: Disconnected
Aug  6 22:54:09 ulisses tvheadend[979]: htsp: Got connection from 10.23.67.219
Aug  6 22:54:09 ulisses tvheadend[979]: htsp: 10.23.67.219: Welcomed client software: XBMC Media Center (HTSPv8)
Aug  6 22:54:09 ulisses tvheadend[979]: htsp: 10.23.67.219 [ XBMC Media Center ]: Identified as user admin
Aug  6 22:54:09 ulisses tvheadend[979]: htsp: 10.23.67.219 [ admin | XBMC Media Center ]: Privileges raised
Aug  6 22:54:40 ulisses tvheadend[979]: htsp: 10.23.67.219 [ admin | XBMC Media Center ]: Write error -- Connection reset by peer
Aug  6 22:54:40 ulisses tvheadend[979]: htsp: 10.23.67.219 [ admin | XBMC Media Center ]: Disconnected
Aug  6 22:54:40 ulisses tvheadend[979]: htsp: Got connection from 10.23.67.219
Aug  6 22:54:40 ulisses tvheadend[979]: htsp: 10.23.67.219: Welcomed client software: XBMC Media Center (HTSPv8)
Aug  6 22:54:40 ulisses tvheadend[979]: htsp: 10.23.67.219 [ XBMC Media Center ]: Identified as user admin
Aug  6 22:54:40 ulisses tvheadend[979]: htsp: 10.23.67.219 [ admin | XBMC Media Center ]: Privileges raised
Aug  6 22:54:51 ulisses tvheadend[979]: htsp: 10.23.67.219 [ admin | XBMC Media Center ]: Disconnected
Aug  6 22:54:51 ulisses tvheadend[979]: htsp: 10.23.67.219 [ admin | XBMC Media Center ]: Write error -- Broken pipe
Aug  6 22:54:51 ulisses tvheadend[979]: htsp: Got connection from 10.23.67.219
Aug  6 22:54:51 ulisses tvheadend[979]: htsp: 10.23.67.219: Welcomed client software: XBMC Media Center (HTSPv8)
Aug  6 22:54:51 ulisses tvheadend[979]: htsp: 10.23.67.219 [ XBMC Media Center ]: Identified as user admin
Aug  6 22:54:51 ulisses tvheadend[979]: htsp: 10.23.67.219 [ admin | XBMC Media Center ]: Privileges raised
Aug  6 22:55:08 ulisses tvheadend[979]: htsp: 10.23.67.219 [ admin | XBMC Media Center ]: Disconnected
Aug  6 22:55:08 ulisses tvheadend[979]: htsp: 10.23.67.219 [ admin | XBMC Media Center ]: Write error -- Broken pipe
Aug  6 22:55:08 ulisses tvheadend[979]: htsp: Got connection from 10.23.67.219
Aug  6 22:55:08 ulisses tvheadend[979]: htsp: 10.23.67.219: Welcomed client software: XBMC Media Center (HTSPv8)
Aug  6 22:55:08 ulisses tvheadend[979]: htsp: 10.23.67.219 [ XBMC Media Center ]: Identified as user admin
Aug  6 22:55:08 ulisses tvheadend[979]: htsp: 10.23.67.219 [ admin | XBMC Media Center ]: Privileges raised
Aug  6 22:55:15 ulisses tvheadend[979]: htsp: 10.23.67.219 [ admin | XBMC Media Center ]: Disconnected
Aug  6 22:55:15 ulisses tvheadend[979]: htsp: Got connection from 10.23.67.219
Aug  6 22:55:15 ulisses tvheadend[979]: htsp: 10.23.67.219: Welcomed client software: XBMC Media Center (HTSPv8)
Aug  6 22:55:15 ulisses tvheadend[979]: htsp: 10.23.67.219 [ XBMC Media Center ]: Identified as user admin
Aug  6 22:55:15 ulisses tvheadend[979]: htsp: 10.23.67.219 [ admin | XBMC Media Center ]: Privileges raised
Aug  6 22:55:32 ulisses tvheadend[979]: htsp: 10.23.67.219 [ admin | XBMC Media Center ]: Disconnected

The recording that ends at 21:12 is the same that is being viewed at 22:52.

This looks like a bug in XBMC (pvr.hts). I'd want to know first why XBMC appears to keep disconnecting. This has been reported by a few people and I don't think either side has got to the bottom of it.

Then I'd want to know what pvr.hts does when the connection goes down, any existing file subscription will be lost and need to be recreated. If its not doing that, which it probably isn't (and I probably wrote that code, naughty!) then it will generate the error your seeing.

Adam

I've activated XBMC logging so hopefully I'll be able to reproduce it and get you a better log of that.

I have also seen this the "last couple of months". It wasn't there in older versions of XBMC (pvr) and/or TVH.

Just to add a few datapoints:
I also see this, quite often. I'm running tvheadend on a backend (currently HTS Tvheadend 3.5.245~g6c9bff1, but have had this problem for several months across different git versions).

To this backend, I connect primarily from my Pivos XIOS M3 box, running the latest nightly builds (speedster) on a wired connection. The problem is intermittent.

I also connect via my tablet, running XBMC Frodo 12.2 (May 2013). Here it happens very often. (wireless).

Sometimes I use my laptop, Fedora 19, XBMC Frodo 12.2 (Jun 2013). Happens quite often here too. (wireless).

I have tried a different network cable from my backend to the router, just to make sure it is not related to a bad wire. Problem was the same.

Could it be a bad NIC in the backend? I don't see any signs of that in 'ifconfig', ie. no lost packages etc. but I'm not sure those numbers are to be trusted?

This is a WAF killer, and I'd be happy to do some testing to make it go away.

The more I see this the more I believe its an XBMC error. The unknown file ID errors make perfect sense, those file IDs are connection specific. So if the connection is lost and re-made, operations on those IDs are no longer valid and the client (XBMC) must re-open the files and start again.

I have never seen anything like this myself and I use XBMC<->TVH a lot, particularly for watching recorded content. But my guess is something in the network is flakey and XBMC is losing its connection, and having done so its not re-starting the file operations (which I'm sure I'll get hte blame for as I'm pretty sure I added that code to pvr.hts).

Adam

I recently switched from running the backend locally on my Raspbmc box, to a networked server. My Raspbmc box is connected via Wifi [no wired ethernet nearby], and I cannot play recorded programs reliably because of this problem. The recordings play fine over an NFS share.

Is there any info I can add that would help in tracking this problem down?

Hi,

I also have this issue.

Recordings work fine on the computer that has tvh installed, both other clients (also xbmc) get this error message.

I have the latest alpha on the cpu that runs tvh, and Frodo (12.3) on the other clients.

I will probably upgrade to the latest alpha on my clients to try and remedy the issue, hopefully this will work.

One other point of note it appears from wireshark that the connection is terminated from the XBMC client. It sends FIN,ACK on 9982 (which I understand is the media port) then immediately attempts reconnect on another port (SYN).

Just before the connection reset I see a HTTP 200 OK on port 9981 (from server about 1.5 seconds before disconnect):

{"boxid": "f3bce322ccce3b095976c65c86f49116672e272f","messages": [{"id": "_dev_dvb_adapter1_Montage_DS3103_TS202212070000_H_satconf_1","quality": 100,"signal": 38330,"ber": 0,"unc": 0,"notificationClass": "dvbMux"},{"identifier": "_dev_dvb_adapter1_Montage_DS3103_TS2022","signal": 58,"ber": 0,"unc": 0,"uncavg": 0,"bw": 4211200,"notificationClass": "tvAdapter"}]}

and a HTTP POST to the server (less than 300ms from the disconnect/connect of port 9982):

POST /comet/poll HTTP/1.1
Host: 192.168.1.200:9981
Connection: keep-alive
Content-Length: 58
Authorization: Basic dG9tOmNoYXJseQ==
Origin: http://192.168.1.200:9981
X-Requested-With: XMLHttpRequest
User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_9_1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/32.0.1700.102 Safari/537.36
Content-Type: application/x-www-form-urlencoded; charset=UTF-8
Accept: */*
Referer: http://192.168.1.200:9981/extjs.html
Accept-Encoding: gzip,deflate,sdch
Accept-Language: en-GB,en;q=0.8,en-US;q=0.6

Tom,

The http stuff is unrelated, that's just the ui receiving status updates which are pretty frequent.

As for htsp stuff, I think if you read my comments you should see I'm pretty convinced this is XBMC for 2 reasons:

1. It times things out too quickly.
2. When it reconnects it falls to reopen the file, that's probably my fault as I probably added that code.

I had a read of the PVr.HTS code a it had been a while since I looked at it and to be honest it's a bit of a mess. I started to rewrite it from scratch unfortunately I'm leaving for time again and I've been ill for last week.

But maybe I'll eventually finish it and then we'll have two options, though mine will no doubt be riddled with bugs!

Adam

This issue doesn't affect my regular usage (all gigabit wired here), but I did find a way to easily reproduce it in testing:

- OS X Mountain Lion host, running Virtualbox with bridged networking
- TVH running in VM as part of OpenElec
- XBMC running on the OS X host, point at TVH

The issue was so bad that not only did video constantly crap out, but resetting the PVR database would hang XBMC, and even trying to exit XBMC with PVR enabled would hang it.

The same TVH running in an OpenElec VM had no issue talking to an RPi across the network. I'm assuming it was related to the bridged networking and perhaps a windows scaling or other issue. Only using standard 1500 MTUs here.

Submitted this as a bug report to XBMC:

http://trac.xbmc.org/ticket/15126

Submitted it to the pvr-addons repo as well:

https://github.com/opdenkamp/xbmc-pvr-addons/issues/292

Why this is rejected ? - i also suffer from the problem on windows machines. this has nothing to do with network / wireless or wired.
as it happens to me in wired connection and do not happen in wireless connection.

this is a bug that should be fixed - and looks like not very hard to reproduce.

it return to my machines every few days.

Shlomi