Recording started 15mins after scheduled (5 mins after show started airing)

yes, that original file look odd - thanks for checking this.

Hi @sa2000

Here’s another similar one. This time my logs caught it - 20 logs go back 48 hours (which indicates I am still logging too much).

Regardless, here are the details:

I was recording 2 episodes of MacGyver on Pick yesterday - both with 10 minute pre/post buffers.

The 9pm aired fine, the 10pm did not.
Screenshot 2021-04-25 at 11.08.03

Plex thinks it recorded though:

10pm file has (0 bytes)

My HDHomerun logs show nothing happened for the 10pm recording:

20210424-19:50:00 Tuner: tuner0 tuning 104 Channel 4 HD (t8dvbt2:682MHz-17664)
20210424-19:50:00 Tuner: tuner1 tuning 35 Pick (t8dvbt:602MHz-22208)
20210424-19:50:01 Tuner: tuner1 streaming http to 192.168.1.63:33252
20210424-19:50:01 Tuner: tuner0 streaming http to 192.168.1.63:33244
20210424-20:50:01 Tuner: tuner2 tuning 19 Dave (t8dvbt:602MHz-22272)
20210424-20:50:02 Tuner: tuner2 streaming http to 192.168.1.63:48576
20210424-21:10:09 Tuner: tuner1 http stream ended (remote closed)
20210424-22:29:58 Tuner: tuner2 http stream ended (remote closed)

20210424-19:50:00 - 20:50 local - starting Planet of Apes (10 min pre-buffer)
20210424-19:50:00 - 20:50 local - starting 9pm MacGyver (10 min pre-buffer)
20210424-20:50:01 - 21:50 local - starting Mock the Week (10 min pre-buffer)
20210424-21:10:09 - 22:10 local - ending 9pm MacGyver (10 min post-buffer)
…nothing for 10pm MacGyver

I have attached all the logs, but it kicks off in #7 - there are over 1000 entries for 20:50 alone.

Appreciate your help on this.
Plex Media Scanner.7.log (29.9 KB)
Archive.zip (14.6 MB)

@sa2000

Here’s a 2nd one - hopefully you’ll be able to look at both and figure out why I need 10 logs/day next week :slight_smile:

Plex says “All Creatures Get and Small” s04e04 was not recorded this morning on Drama +1 this morning. Interestingly, there should have been. no reason why it did not record an hour earlier on Drama (as there were no conflicts).
Screenshot 2021-05-01 at 08.41.28

Detail screen said: “airing as already in progress”:

Below Arte all the HDHomerun logs from this morning. As you can see, no tuner was used (again):

20210501-00:09:53 Tuner: tuner0 http stream ended (remote closed)
20210501-00:45:01 Tuner: tuner0 tuning 21 5 USA (t8dvbt:538MHz-12992)
20210501-00:45:02 Tuner: tuner0 streaming http to 192.168.1.63:59700
20210501-02:45:00 Tuner: tuner0 http stream ended (remote closed)

My 20 logs still only go back 2 days, but that was enough - Log 1 has the correct timeframe, but have attached all anyway (because 48 hours is still a problem).

Archive.zip (15.5 MB)

Thanks!

I started looking at this.

Looking into “All Creatures Great and Small”

So the airing for Season 4 Episode 4 The Pig Man Cometh was starting at 02:50 am 1st May on 020 Drama and at 03:50 am on 073 Drama + 1

Throughout the time up these start times, the episode appears to have existed in the library - the first time when it was no longer in the library was at 04:04 am - The recording got started and aborted as the program had already started.

Extracts from log

Apr 30, 2021 23:55:08.028 [0x7f46b98f0b38] DEBUG - Subscription: We found a match in the library for 'All Creatures Great & Small - E4 - The Pig Man Cometh'
May 01, 2021 01:10:11.059 [0x7f46bed64b38] DEBUG - Subscription: We found a match in the library for 'All Creatures Great & Small - E4 - The Pig Man Cometh'
May 01, 2021 01:10:21.160 [0x7f46be655b38] DEBUG - Subscription: We found a match in the library for 'All Creatures Great & Small - E4 - The Pig Man Cometh'
May 01, 2021 03:05:05.604 [0x7f46baabfb38] DEBUG - Subscription: We found a match in the library for 'All Creatures Great & Small - E4 - The Pig Man Cometh'
May 01, 2021 03:45:09.734 [0x7f46bb456b38] DEBUG - Subscription: We found a match in the library for 'All Creatures Great & Small - E4 - The Pig Man Cometh'
May 01, 2021 04:03:44.174 [0x7f46bbfd1b38] DEBUG - Subscription: We found a match in the library for 'All Creatures Great & Small - E4 - The Pig Man Cometh'
May 01, 2021 04:03:58.413 [0x7f46bbfd1b38] DEBUG - Subscription: We found a match in the library for 'All Creatures Great & Small - E4 - The Pig Man Cometh'

May 01, 2021 04:04:40.892 [0x7f46bbfb6b38] DEBUG - Subscription: No match in the library for 'All Creatures Great & Small - E4 - The Pig Man Cometh', grabbing.

I am not sure why the current logic resulted in an attempt to start the recording then - only to realize that would be a partial recording and then aborted

So for this example - it did not get recorded at the right time because Plex Media Server believed it was already in the library

I will look at the other example MacGyver and also see why logs filling faster than before.

Cheers. Is this something the devs need to look at?

There was a transcoder failure for the 2nd recording which got appended to the first transcoder job that was capturing the channel stream

Apr 24, 2021 21:50:15.686 [0x7f964ba23700] ERROR - [Transcoder] [mpegts @ 0x132e4c0] sample rate not set

Apr 24, 2021 21:50:15.687 [0x7f9676e6b700] ERROR - [Transcoder] Could not write header for output file #0 (incorrect codec parameters ?): Invalid argument

Apr 24, 2021 21:50:15.687 [0x7f9649fc5700] ERROR - [Transcoder]

leading to

Apr 24, 2021 21:50:15.690 [0x7f96a5e81700] DEBUG - Jobs: '/share/CACHEDEV1_DATA/.qpkg/PlexMediaServer/Plex Transcoder' exit code for process 32148 is 1 (failure) 

I do not know why the transcoder failed in this way. Is back-to-back recording for same channel with 10 minute pre/post buffers working at other times ?

I need to establish if this is reproducible or some timing issue

I do back-back all the time - but need to confirm it is the same channel - not sure how to do that easily though.

…but Plex should know whether it is possible or not and have given me the warning triangle if not. possible,

It should be possible - don;t know at this stage if this is a one-off or a regression

Another thought; I have a 4 tuner HDHomerun and they were not all in use. If Plex can’t handle back-to-back on the same tuner, why didn’t it use the spare one?

I’ll try to look at my HDHomerun logs today and see if it has been doing back to back before (or is there a dev you know who can answer this)?

I have just tested back-to-back with a 2-tuner HD Homerun and i had 3 recordings of 15 minute episodes on one of the children channels with 10 minute for pre and post amble for each - and all 3 recorded ok,

Will need to see how your issue can be reproduced

Any more examples of these recording failures?

Actually, I have had a few but wasn’t sure if other examples would help

I’ll try something similar and let you know.

@sa2000

OK, in summary, it worked - but have kept logs which I can upload if you want…

I scheduled 3x 1hr shows and 2x 30 minute (back to back) shows:

Everything recorded OK. Here is a screenshot of the overlap with all 5 shows recording (on 4 tuners):
0938 5 recordings

Ignore American Pickers and Emmerdale - that was just me trying to find the right shows to record.

Here is the “after” DVR Schedule status:
1011 finshed:

Here are the HDHomerun logs (I have removed Emmerdale/American Pickers):

20210512-07:50:12 Tuner: tuner0 tuning 32 Paramount Netwo (t8dvbt:538MHz-16112)
20210512-07:50:12 Tuner: tuner0 streaming http to 192.168.1.63:36824
20210512-07:50:22 Tuner: tuner1 tuning 30 4Music (t8dvbt:602MHz-22368)
20210512-07:50:22 Tuner: tuner1 streaming http to 192.168.1.63:36934
20210512-07:50:28 Tuner: tuner2 tuning 29 E4+1 (t8dvbt:658MHz-8458)
20210512-07:50:29 Tuner: tuner2 streaming http to 192.168.1.63:37040

tuning and ending Emerdale and American Pickers here

20210512-07:55:44 Tuner: tuner3 tuning 21 5 USA (t8dvbt:538MHz-12992)
20210512-07:55:44 Tuner: tuner3 streaming http to 192.168.1.63:43402
20210512-09:09:59 Tuner: tuner0 http stream ended (remote closed)
20210512-09:09:59 Tuner: tuner1 http stream ended (remote closed)
20210512-09:09:59 Tuner: tuner3 http stream ended (remote closed)
20210512-09:10:01 Tuner: tuner2 http stream ended (remote closed)

Here are the recorded episodes:

Is anyone seeing this error when the show fails to record? This seems to happen when 2 shows are on the same channel back to back. I had the same thing happen with The Flash and Supergirl on CW. I have 6 tuners, and with the recording tonight, only 2 were needed, but it still failed to record. @sa2000 I have logs if you have a chance to take a look at them.

image

yes, that’s exactly what I posted further up the thread here.

Can you post the logs?

1 Like

Thanks. I’ll send the logs over to sa2000. This is happening to me all the time now. It just started about 2 weeks ago from what I noticed. It might have started sooner though and I just haven’t noticed the other missed recordings yet.

@sa2000 I sent the logs in a DM. Let us know if you find anything that might help point to a solution or if you need any more logs.

cool.

BTW, I don’t think there are any privacy issues posting the logs here - the advantage being that other people “who know” can also advise when @sa2000 isn’t around.

Do you have “Allow partial airings” enabled in the advanced settings for the items experiencing this problem?

image

If disabled, and the recording cannot start immediately for some reason, it could cause the recording to fail in this manner.