Bug #1779
closed
"Unknown file id" error when viewing recordings in XBMC
Added by Pedro Côrte-Real over 11 years ago. Updated almost 11 years ago.
0%
Description
I'm using tvheadend as the livetv backend to XBMC. Livetv/EPG/recording works great, much better than mythtv ever did. The problem I've encountered is when playing a recording it will start and then soon after stop with an "Unknown file id" error. The file is safely on disk and I can download it and play it just fine.
xbmc is version 12.2~git20130502.1706-frodo-0precise
tvheadend is version 3.4.27~gfbda802~precise
Files
| xbmc.log (162 KB) xbmc.log | XBMC log of the issue | Pedro Côrte-Real, 2013-08-08 23:50 | |
| xbmc.log (186 KB) xbmc.log | Glen Browne, 2013-12-21 06:25 | ||
| disconnect.log (56.8 KB) disconnect.log | tail of tvheadend syslog during issue | Tom Greenwood, 2014-02-08 15:35 | |
| syslog (240 KB) syslog | Full syslog from tvheadend server | Tom Greenwood, 2014-02-08 15:35 | |
| xbmc.log (161 KB) xbmc.log | xbmc log file | Tom Greenwood, 2014-02-08 15:35 |
Updated by Adam Sutton over 11 years ago
- Status changed from New to Need feedback
Can you provide full debug logs from both TVH and XBMC.
Adam
Updated by Pedro Côrte-Real over 11 years ago
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.
Updated by Adam Sutton over 11 years ago
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
Updated by Pedro Côrte-Real over 11 years ago
I've activated XBMC logging so hopefully I'll be able to reproduce it and get you a better log of that.
Updated by Stig Larsson over 11 years ago
I have also seen this the "last couple of months". It wasn't there in older versions of XBMC (pvr) and/or TVH.
Updated by Pedro Côrte-Real over 11 years ago
Ok, caught the problem today. On the tvheadend side there doesn't seem to be much new:
Aug 08 22:42:29.491 [ INFO]:htsp: Got connection from 10.23.67.219 Aug 08 22:42:29.502 [ INFO]:htsp: 10.23.67.219: Welcomed client software: XBMC Media Center (HTSPv8) Aug 08 22:42:29.505 [ INFO]:htsp: 10.23.67.219 [ XBMC Media Center ]: Identified as user admin Aug 08 22:42:29.505 [ INFO]:htsp: 10.23.67.219 [ admin | XBMC Media Center ]: Privileges raised Aug 08 22:42:35.286 [ DEBUG]:HTSP: Opening file /home/hts/2013-08-08/TVI-Jornal Das 8.2013-08-08.20-00.ts -- OK Aug 08 22:43:25.855 [ INFO]:htsp: 10.23.67.219 [ admin | XBMC Media Center ]: Disconnected Aug 08 22:43:26.215 [ INFO]:htsp: 10.23.67.219 [ admin | XBMC Media Center ]: Write error -- Broken pipe Aug 08 22:43:26.215 [ DEBUG]:HTSP: Closed opened file /home/hts/2013-08-08/TVI-Jornal Das 8.2013-08-08.20-00.ts Aug 08 22:43:29.214 [ INFO]:htsp: Got connection from 10.23.67.219 Aug 08 22:43:29.225 [ INFO]:htsp: 10.23.67.219: Welcomed client software: XBMC Media Center (HTSPv8) Aug 08 22:43:29.227 [ INFO]:htsp: 10.23.67.219 [ XBMC Media Center ]: Identified as user admin Aug 08 22:43:29.227 [ INFO]:htsp: 10.23.67.219 [ admin | XBMC Media Center ]: Privileges raised Aug 08 22:43:41.257 [ INFO]:htsp: 10.23.67.219 [ admin | XBMC Media Center ]: Disconnected
but now I have a full xbmc log of the problem, I've attached it. Let me know if you need something else.
Updated by Martin Rusler over 11 years ago
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.
Updated by Glen Browne over 11 years ago
I get this too with most of the windows machines on my network playing recorded tv with xbmc frodo. I am using tvheadened Build: 3.5.244~gf5c5ffd-dirty. It's quite frustrating. I tend to watch recorded tv on an android using tvhguide instead as I can watch the same recordings without an issue. I'm no expert at deciphering logs sorry, but i can see a couple of examples in the attached log as follows and there are tonnes of lines preceding them that may show what happened prior. If anyone could shed any light on this I would be eternally grateful
18:15:43 T:3520 ERROR: AddOnLog: Tvheadend HTSP Client: CHTSPConnection::ReadResult - command failed - Unknown file id
and 18:16:59 T:1220 ERROR: AddOnLog: Tvheadend HTSP Client: CHTSPConnection::ReadResult - command failed - Unknown file id
Updated by Adam Sutton over 11 years ago
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
Updated by Hiro Protagonist over 11 years ago
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?
Updated by Patric Gustavsson about 11 years ago
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.
Updated by Tom Greenwood about 11 years ago
- File disconnect.log disconnect.log added
- File syslog syslog added
- File xbmc.log xbmc.log added
I have this issue as well I have just installed 3.4.27~gfbda802~raring and am getting this problem. The client is XBMC 12.3 running on Mac.
I have attached full debug logs. I tailed the syslog so you could see just the part where I was playing the stream.
If there is anything I can do to help let me know. I think tvheadend is quite a bit easier to use than mythtv and would like to give it a good try but this issue seems to be a show stopper for me.
Playing the same over HTTP using VLC seems OK though there are a couple of minor stutters in an hour playback.
Updated by Tom Greenwood about 11 years ago
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
Updated by Adam Sutton about 11 years ago
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
Updated by Hero of Shapeir about 11 years ago
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.
Updated by Adam Sutton about 11 years ago
- Status changed from Need feedback to Rejected
This is a bug in pvr.hts, nothing to do with TVH. If you want a more reliable XBMC plugin, try pvr.tvh.
Adam
Updated by Pedro Côrte-Real about 11 years ago
Submitted this as a bug report to XBMC:
Updated by Pedro Côrte-Real about 11 years ago
Submitted it to the pvr-addons repo as well:
Updated by Shlomi Cohen almost 11 years ago
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