JumpToProgram's OpenFile failed [[ SOLVED ]]

For discussion of topics specific to MythTV on linux
Post Reply
53ri41
Newcomer
Posts: 11
Joined: Tue Sep 13, 2016 3:32 pm
United States of America

JumpToProgram's OpenFile failed [[ SOLVED ]]

Post by 53ri41 »

I'm frustrated. I really like MythTV, but MythTV really doesn't like me back.

I'm a windows-to-linux convert (so I have a rather weak understanding of the under-pinnings of linux) that wants to be able to setup a pvr/live-tv setup, and MythTV has stomped on all of my attempts. This effort was looking promising, until I tried to watch live-tv Error: [ JumpToProgram's OpenFile failed ] which googles to be some non-descript issue that many have encountered without a definitive solution, beyond posts suggesting that the tuners aren't setup correctly... I've deleted and re-installed the capture cards several times, but if I deviate from the partially working setup, I end up with a non-working setup. It seems like there's a million others out there who have this tuner-card running live-tv just fine.

When I try to watch live TV, I get an error The frontend will record via the tuner(s) (at least for a few minutes) but can't actually watch them?

Is this noob fixable? If I buy an updated tuner-card (I'm eyeing hauppauge's HDquad), do these woes go away?

Fedora 25 (Gnome)
Core2Quad 9450
Hauppauge pvr2250
nvidia gt430

Any help is appreciated.
-Cyril [[ Solution ]]

full log hosted here

Code: Select all

2017-03-15 18:24:23.641435 I  Player(0): Video timing method: DRM
2017-03-15 18:24:23.656664 I  TV::StartPlayer(): Created player.
2017-03-15 18:24:23.656724 I  TV::HandleStateChange(): Changing from None to WatchingLiveTV
2017-03-15 18:24:23.656733 I  TV::HandleStateChange(): State is LiveTV & mctx == ctx
2017-03-15 18:24:23.657347 I  TV::HandleStateChange(): UpdateOSDInput done
2017-03-15 18:24:23.657356 I  TV::HandleStateChange(): UpdateLCD done
2017-03-15 18:24:23.657557 I  TV::HandleStateChange(): ITVRestart done
2017-03-15 18:24:23.658959 I  TV::HandleStateChange(): Main UI disabled.
2017-03-15 18:24:23.659124 I  TV::StartTV(): Entering main playback loop.
2017-03-15 18:24:23.662656 I  ScreenSaverDBus: Successfully inhibited screensaver via org.freedesktop.ScreenSaver. cookie 1368814291. nom nom
2017-03-15 18:24:23.663704 W  ScreenSaverDBus: Failed to disable screensaver: Type of message, '(ss)', does not match expected type '(susu)'
2017-03-15 18:24:23.713038 I  VideoOutput: Created YV12 OSD.
2017-03-15 18:24:24.448246 E  FileRingBuf(/mnt/DubStuff/Video/TV (recorded)/1032_20170315222424.ts): OpenFile(): File too small (0B).
2017-03-15 18:24:24.448324 E  Player(0): JumpToProgram's OpenFile failed (input type: DVB).
2017-03-15 18:24:24.448360 E  LiveTVChain has 2 entries
   DUMMY: 1032 (22:24:23 to 22:24:24)
*    DVB: 1032 (22:24:24 to 22:30:00) discontinuous
 
2017-03-15 18:24:24.448376 E  Player(0): Unknown recorder error, exiting decoder
2017-03-15 18:24:24.628851 I  TV::HandleStateChange(): Attempting to change from WatchingLiveTV to None
2017-03-15 18:24:24.630812 I  Setup Interrupt handler
2017-03-15 18:24:24.630824 I  Setup Terminated handler
2017-03-15 18:24:24.873880 I  TV::HandleStateChange(): Changing from WatchingLiveTV to None
2017-03-15 18:24:24.874163 I  TV::StartTV(): Exiting main playback loop.
Last edited by 53ri41 on Sat Mar 18, 2017 10:36 pm, edited 1 time in total.
User avatar
dizygotheca
Developer
Posts: 267
Joined: Wed Sep 03, 2014 9:02 am
Great Britain

Re: JumpToProgram's OpenFile failed

Post by dizygotheca »

+1 for the pastebin.
Probably fixable, if we see enough evidence ;-)
2017-03-15 19:00:00.319704 E FileRingBuf(/mnt/DubStuff/Video/TV (recorded)/1031_20170315230000.ts): OpenFile(): File too small (0B).
In LiveTv the frontend asks the backend to start recording that file, for it to stream. It's failing - 0 bytes - so we need to see the corresponding backend log as well.
https://www.mythtv.org/wiki/Posting_Logs
Note the bit about not trimming off the start at:
mythbackend version: master [v0.27-pre2-278-g3eef99e]
That's where all the pertinent info about tuners is.
53ri41
Newcomer
Posts: 11
Joined: Tue Sep 13, 2016 3:32 pm
United States of America

Re: JumpToProgram's OpenFile failed

Post by 53ri41 »

dizygotheca wrote: [ ... ]
In LiveTv the frontend asks the backend to start recording that file, for it to stream. It's failing - 0 bytes - so we need to see the corresponding backend log as well.
[ ... ]
More info needed. got it.
These logs are from terminal startup of the front-and-back-ends. If this information is not sufficient, then I will gladly use another log method.
The longer of the complete logs (backend) spans ~2 minutes.

I appreciate your help dizygotheca.

Complete Frontend log link, error snippet below (& following events that occurred within 12:18:32):

Code: Select all

2017-03-16 12:18:32.162559 E  FileRingBuf(/mnt/DubStuff/Video/TV (recorded)/1032_20170316161832.ts): OpenFile(): File too small (0B).
2017-03-16 12:18:32.162633 E  Player(0): JumpToProgram's OpenFile failed (input type: DVB).
2017-03-16 12:18:32.162670 E  LiveTVChain has 2 entries
   DUMMY: 1032 (16:18:31 to 16:18:32)
*    DVB: 1032 (16:18:32 to 16:30:00) discontinuous

2017-03-16 12:18:32.162685 E  Player(0): Unknown recorder error, exiting decoder
2017-03-16 12:18:32.267890 I  TV::HandleStateChange(): Attempting to change from WatchingLiveTV to None
2017-03-16 12:18:32.269811 I  Setup Interrupt handler
2017-03-16 12:18:32.269826 I  Setup Terminated handler
2017-03-16 12:18:32.801616 I  TV::HandleStateChange(): Changing from WatchingLiveTV to None
2017-03-16 12:18:32.801945 I  TV::StartTV(): Exiting main playback loop.
2017-03-16 12:18:32.802065 I  ScreenSaverDBus: Screensaver uninhibited via org.freedesktop.ScreenSaver
2017-03-16 12:18:32.817525 N  Resuming idle timer
Complete backend log link, time-corresponding snippet below:

Code: Select all

2017-03-16 12:18:31.177273 I  MainServer: MainServer::ANN Playback
2017-03-16 12:18:31.177284 I  MainServer: adding: ninefortyfive(19c2390) as a client (events: 0)
2017-03-16 12:18:31.179526 I  TVRec[1]: Changing from None to WatchingLiveTV
2017-03-16 12:18:31.182156 I  TVRec[1]: HW Tuner: 1->1
2017-03-16 12:18:31.182175 I  TVRec[1]: TuningFrequency
2017-03-16 12:18:31.187858 N  AutoExpire: CalcParams(): Max required Free Space: 3.0 GB w/freq: 14 min
2017-03-16 12:18:31.191321 W  LoadFromProgram(): SQL contains LIMIT clause, caller should be updated to use limit parameter instead
2017-03-16 12:18:31.213472 N  ApplyRecordRecGroupChange: LiveTV to LiveTV (2)
2017-03-16 12:18:32.053850 N  AutoExpire: CalcParams(): Max required Free Space: 3.0 GB w/freq: 14 min
2017-03-16 12:18:32.055020 W  LoadFromProgram(): SQL contains LIMIT clause, caller should be updated to use limit parameter instead
2017-03-16 12:18:32.061191 N  ApplyRecordRecGroupChange: LiveTV to LiveTV (2)
2017-03-16 12:18:32.104140 I  TVRec[1]: TuningNewRecorder - CreateRecorder()
2017-03-16 12:18:32.285276 I  TVRec[1]: Changing from WatchingLiveTV to None
2017-03-16 12:18:32.797664 N  Finished Recording: Container: MPEG2-TS Video Codec: mpeg2video (720x480 A/R: 2 29.97fps) Audio Codec: ac3
2017-03-16 12:18:32.798451 I  TVRec[1]: FinishedRecording(1032_2017-03-16T16:18:32Z) damaged recq:<RecordingQuality overall_score="0" key="1032_2017-03-16T16:18:32Z" countinuity_error_count="0" packet_count="21">
    <Gap start="2017-03-16T16:18:32Z" end="2017-03-16T16:30:00Z" duration="687" />
</RecordingQuality>
 
2017-03-16 12:18:32.815104 I  Playback sock(19c2390) 'ninefortyfive' disconnected
User avatar
dizygotheca
Developer
Posts: 267
Joined: Wed Sep 03, 2014 9:02 am
Great Britain

Re: JumpToProgram's OpenFile failed

Post by dizygotheca »

Strange log.
2017-03-16 12:18:32.104140 I TVRec[1]: TuningNewRecorder - CreateRecorder()
2017-03-16 12:18:32.285276 I TVRec[1]: Changing from WatchingLiveTV to None
It fails very quickly, which suggests a misconfigured tuner.

And, at the start, I would also expect to see some evidence of your tuners; something like:
N CoreContext main_helpers.cpp:597 (run_backend) MythBackend: Starting up as the master server.
I CoreContext recorders/dvbchannel.cpp:712 (Tune) DVBChan[1](/dev/dvb/adapter0/frontend0): Next tuning after less than 1000ms. Delaying by 1000ms
I CoreContext recorders/dvbchannel.cpp:712 (Tune) DVBChan[2](/dev/dvb/adapter1/frontend0): Next tuning after less than 1000ms. Delaying by 1000ms
I CoreContext programinfo.cpp:2387 (CheckProgramIDAuthorities) Found 15 distinct programid authorities
for DVB tuners on a PCI card.

So I'm not sure what that tuner 1 it's using, actually is.

I'm not familiar with Fedora, but these (Ubuntu) commands should work. You might need to 'translate' them otherwise.

Can you verify that the tuner is installed properly. Google suggests firmware has been an issue in the past. Hopefully that's history by now.
From a terminal:

Code: Select all

$ dmesg | grep -i dvb
or

Code: Select all

$dmesg
for pages of it.
And confirm it contains lines similar to https://www.linuxtv.org/wiki/index.php/ ... nel_output
Particularly something like:
DVB: registering adapter 1 frontend 0 (Samsung S5H1411 QAM/8VSB Frontend)...
Common pitfalls to be aware of:

1. mythtv-setup & mythbackend should never both be running at the same time. They both expect exclusive use of the tuners and strangeness results.
Usually mythbackend runs in the background (a daemon process). mythtv-setup will try/claim it has stopped the backend but that is not reliable due to recent changes on some distributions. It depends on whether your settings for "Server halt command" are appropriate
https://www.mythtv.org/wiki/Setup_Gener ... up_Options
For now, it's advisable to manually check the backend isn't running before running mythtv-setup:

Code: Select all

$ps aux | grep backend
If it is, then kill it until it goes away.

Code: Select all

$killall mythbackend
2. In mythtv-setup always use "Delete all tuners on all hosts", configure your tuners, and do not be tempted to edit them. You should be well-practised by now!
The UI is buggy and can result in misconfigured/cross-linked tuners and strange behaviour. You don't need to delete your Video Sources or rescan channels when doing this.
53ri41
Newcomer
Posts: 11
Joined: Tue Sep 13, 2016 3:32 pm
United States of America

Re: JumpToProgram's OpenFile failed

Post by 53ri41 »

dizygotheca wrote:It fails very quickly, which suggests a misconfigured tuner.
[...] at the start, I would also expect to see some evidence of your tuners
Can you verify that the tuner is installed properly. [...]
And confirm it contains lines similar to https://www.linuxtv.org/wiki/index.php/ ... nel_output
Particularly something like:
DVB: registering adapter 1 frontend 0 (Samsung S5H1411 QAM/8VSB Frontend)...
I have those exact lines. It seems to see both tuners of the card.

Code: Select all

[22:01 mythtv ~]$ dmesg | grep -i dvb
[   15.933461] tveeprom 13-0000: TV standards NTSC(M) ATSC/DVB Digital (eeprom 0x88)
[   16.500849] DVB: registering new adapter (saa7164)
[   16.500855] saa7164 0000:02:00.0: DVB: registering adapter 0 frontend 0 (Samsung S5H1411 QAM/8VSB Frontend)...
[   19.255890] DVB: registering new adapter (saa7164)
[   19.255895] saa7164 0000:02:00.0: DVB: registering adapter 1 frontend 0 (Samsung S5H1411 QAM/8VSB Frontend)...
2. In mythtv-setup always use "Delete all tuners on all hosts", configure your tuners, and do not be tempted to edit them. You should be well-practised by now!
yeah, no kidding... :roll:

I deleted all tuners, set them up again, and the only value that I'm changing from defaults is the number of recordings in the recordings options button. It isn't obvious to me what other edits I should be making. After that, I head over to connection inputs and map each tuner to the EIT-source. I'm still getting the same results.

mythfrontend: [complete log]
where it appears to go sideways:

Code: Select all

2017-03-17 22:34:41.565368 I  ScreenSaverDBus: Successfully inhibited screensaver via org.freedesktop.ScreenSaver. cookie 392536604. nom nom
2017-03-17 22:34:41.566067 W  ScreenSaverDBus: Failed to disable screensaver: Type of message, '(ss)', does not match expected type '(susu)'
2017-03-17 22:34:41.619140 I  VideoOutput: Created YV12 OSD.
2017-03-17 22:34:42.263529 E  FileRingBuf(/mnt/DubStuff/Video/TV (recorded)/1031_20170318023442.ts): OpenFile(): File too small (0B).
2017-03-17 22:34:42.263593 E  Player(0): JumpToProgram's OpenFile failed (input type: DVB).
2017-03-17 22:34:42.263631 E  LiveTVChain has 2 entries
   DUMMY: 1031 (02:34:41 to 02:34:42)
*    DVB: 1031 (02:34:42 to 04:00:00) discontinuous
 
2017-03-17 22:34:42.263647 E  Player(0): Unknown recorder error, exiting decoder
2017-03-17 22:34:42.346264 I  TV::HandleStateChange(): Attempting to change from WatchingLiveTV to None
2017-03-17 22:34:42.348302 I  Setup Interrupt handler
2017-03-17 22:34:42.348324 I  Setup Terminated handler
2017-03-17 22:34:42.588978 I  TV::HandleStateChange(): Changing from WatchingLiveTV to None
2017-03-17 22:34:42.589303 I  TV::StartTV(): Exiting main playback loop.
mythbackend [complete log]
time corresponding portion:

Code: Select all

2017-03-17 22:34:41.248595 I  MainServer: MainServer::ANN Playback
2017-03-17 22:34:41.248603 I  MainServer: adding: ninefortyfive(a602b0) as a client (events: 0)
2017-03-17 22:34:41.249856 I  TVRec[1]: Changing from None to WatchingLiveTV
2017-03-17 22:34:41.252095 I  TVRec[1]: HW Tuner: 1->1
2017-03-17 22:34:41.252108 I  TVRec[1]: TuningFrequency
2017-03-17 22:34:41.258813 N  AutoExpire: CalcParams(): Max required Free Space: 3.0 GB w/freq: 14 min
2017-03-17 22:34:41.281000 N  ApplyRecordRecGroupChange: LiveTV to LiveTV (2)
2017-03-17 22:34:42.144175 N  AutoExpire: CalcParams(): Max required Free Space: 3.0 GB w/freq: 14 min
2017-03-17 22:34:42.188751 N  ApplyRecordRecGroupChange: LiveTV to LiveTV (2)
2017-03-17 22:34:42.189343 I  TVRec[1]: TuningNewRecorder - CreateRecorder()
2017-03-17 22:34:42.353582 I  TVRec[1]: Changing from WatchingLiveTV to None
2017-03-17 22:34:42.585288 N  Finished Recording: Container: MPEG2-TS Video Codec: mpeg2video (0x0 A/R: 0 29.97fps) Audio Codec: ac3
2017-03-17 22:34:42.586095 I  TVRec[1]: FinishedRecording(1031_2017-03-18T02:34:42Z) damaged recq:<RecordingQuality overall_score="0" key="1031_2017-03-18T02:34:42Z">
    <Gap start="2017-03-18T01:30:00Z" end="2017-03-18T04:00:00Z" duration="9000" />
</RecordingQuality>
The part that I don't understand, is that the steup will record live tv.
From the main menu > program guide, and I select a program, I do NOT have the option to watch the channel, but I can record it, and it records rather reliably.
...HTH...
-Cyril

edit:
Backend log snippet of both tuners recording simultaneously

Code: Select all

2017-03-18 07:30:42.262797 I  TVRec[1]: Changing from None to RecordingOnly
2017-03-18 07:30:42.263696 I  TVRec[1]: HW Tuner: 1->1
2017-03-18 07:30:42.263726 I  TVRec[1]: TuningFrequency
2017-03-18 07:30:42.379802 I  Tuning recording: WordGirl: channel 1153 on cardid 1, sourceid 1
2017-03-18 07:30:42.455556 C  ProgramInfo(): Failed to find recorded entry for 0.
2017-03-18 07:30:43.589260 I  Updating status for WordGirl on cardid 1 (Tuning => Recording)
2017-03-18 07:30:43.892707 I  TVRec[1]: rec->GetPathname(): '/mnt/DubStuff/Video/1153_20170318113100.ts'
2017-03-18 07:30:43.893281 I  TVRec[1]: TuningNewRecorder - CreateRecorder()
2017-03-18 07:30:56.255714 I  MainServer: MainServer::ANN Monitor
2017-03-18 07:30:56.255724 I  MainServer: adding: ninefortyfive(226c290) as a client (events: 0)
2017-03-18 07:31:09.135628 I  Reschedule requested for MATCH 0 0 0 - HandleRescheduleRecordings
2017-03-18 07:31:09.153565 I  Scheduled 2 items in 0.0 = 0.01 match + 0.00 check + 0.00 place
2017-03-18 07:31:09.192182 I  TVRec[3]: Changing from None to RecordingOnly
2017-03-18 07:31:09.192885 I  TVRec[3]: HW Tuner: 3->3
2017-03-18 07:31:09.192898 I  TVRec[3]: TuningFrequency
2017-03-18 07:31:09.310524 I  Tuning recording: "WAVY News 10 Saturday @ 7am": channel 1101 on cardid 3, sourceid 1
2017-03-18 07:31:09.322447 C  ProgramInfo(): Failed to find recorded entry for 0.
2017-03-18 07:31:10.224581 I  Updating status for "WAVY News 10 Saturday @ 7am" on cardid 3 (Tuning => Recording)
2017-03-18 07:31:10.494939 I  TVRec[3]: rec->GetPathname(): '/mnt/DubStuff/Video/1101_20170318113100.ts'
2017-03-18 07:31:10.495637 I  TVRec[3]: TuningNewRecorder - CreateRecorder()
User avatar
dizygotheca
Developer
Posts: 267
Joined: Wed Sep 03, 2014 9:02 am
Great Britain

Re: JumpToProgram's OpenFile failed

Post by dizygotheca »

The part that I don't understand, is that the steup will record live tv.
Right. So recording works fine. Playback of a recording works fine. It's just Live Tv that's broken ?
From the main menu > program guide, and I select a program, I do NOT have the option to watch the channel, but I can record it, and it records rather reliably.
Good info. That is only available when the channel is "tunable".

Please try with debug logging:

Code: Select all

$ mythbackend -v record,channel --loglevel debug
We only need the backend snippet you've already identified.
53ri41
Newcomer
Posts: 11
Joined: Tue Sep 13, 2016 3:32 pm
United States of America

Re: JumpToProgram's OpenFile failed

Post by 53ri41 »

dizygotheca wrote:So recording works fine. Playback of a recording works fine. It's just Live Tv that's broken ?
It seems so, yes. I have recorded some shows and watched them back without issue. I just can't get live TV.
Please try with debug logging:

Code: Select all

$ mythbackend -v record,channel --loglevel debug
We only need the backend snippet you've already identified.
frontend qualifier for the backend snippet:

Code: Select all

2017-03-18 14:10:45.675813 I  TV::TV(): Creating TV object
[...]
2017-03-18 14:10:46.803186 E  FileRingBuf(/mnt/DubStuff/Video/TV (recorded)/1031_20170318181046.ts): OpenFile(): File too small (0B).
2017-03-18 14:10:46.803272 E  Player(0): JumpToProgram's OpenFile failed (input type: DVB).
[ backend snippet ] pastebin'd the snippet because verbose-logging threw 280 lines for None -> WatchingLiveTV -> None.

-Cyril
User avatar
dizygotheca
Developer
Posts: 267
Joined: Wed Sep 03, 2014 9:02 am
Great Britain

Re: JumpToProgram's OpenFile failed

Post by dizygotheca »

That log looks fine right up until the last 2 lines.
Something is explicitly stopping it:
TVRec[1]: StopLiveTV(void) curRec: 0x7f5030197f10 pseudoRec: 0x0
That could originate from many places but a quick guess is the frontend.
Note that your LiveTV storage group has a space in it.

/mnt/DubStuff/Video/TV (recorded)/1031_20170318181045.ts

whilst your successful recordings (Default storage group?) don't

/mnt/DubStuff/Video/1101_20170318113100.ts

If you remove the space from that directory (or simply clear the LiveTv storage group - it will use the Default storage group) does it start working ?
53ri41
Newcomer
Posts: 11
Joined: Tue Sep 13, 2016 3:32 pm
United States of America

Re: JumpToProgram's OpenFile failed

Post by 53ri41 »

dizygotheca wrote: If you remove the space from that directory (or simply clear the LiveTv storage group - it will use the Default storage group) does it start working ?
That was it! Great catch. You're fantastic. :D and I'm embarrassed. :oops: Filename spaces in linux are always trouble, and re-using windows paths begs for this kind of issue
I couldn't figure out how to return the livetv storage group to the default empty state, so I pointed it to a "...video/TV" folder, and that did it.
Thanks again dizygotheca!
User avatar
dizygotheca
Developer
Posts: 267
Joined: Wed Sep 03, 2014 9:02 am
Great Britain

Re: JumpToProgram's OpenFile failed [[ SOLVED ]]

Post by dizygotheca »

mythtv-setup tends to use 'D' key for delete, 'E' key for edit etc.
Generally linux is fine with whitespace in filenames. That's just some old Myth code.
53ri41
Newcomer
Posts: 11
Joined: Tue Sep 13, 2016 3:32 pm
United States of America

Re: JumpToProgram's OpenFile failed [[ SOLVED ]]

Post by 53ri41 »

I still don't have a "watch this channel" type option from the program menu. Should I start a new thread for that?
User avatar
dizygotheca
Developer
Posts: 267
Joined: Wed Sep 03, 2014 9:02 am
Great Britain

Re: JumpToProgram's OpenFile failed [[ SOLVED ]]

Post by dizygotheca »

Yes. It should appear if you have free tuners that are attached to the 'Video Source' containing the channel.
So misconfigured video sources can prevent it.

I assume (mythtv-setup):
- You've only one video source & both tuners are attached to it.
- You're only using EIT
- Channel scanning worked (reasonably well).

Unforunately logging isn't sufficient here.
If you start a new thread I'll add instructions for dumping the necessary info.
Post Reply