Opened 9 years ago

Closed 4 years ago

#12290 closed Bug Report - General (Fixed)

Commercial Flagging isn't being queued.

Reported by: Bill Meek <keemllib@…> Owned by: Roger Siddons
Priority: minor Milestone: 30.1
Component: MythTV - General Version: Master Head
Severity: medium Keywords:
Cc: Ticket locked: no

Description

In: TVRecEvent programinfo.cpp (GetFilesize?) the existing returned filesize is sometimes 0 and TVRec::FinishedRecording? won't allow the job to be queued if the file size is less than 1000 bytes.

This has deactivated all commercial flagging. A workaround is attached (not a fix.)

Attachments (8)

commercial-flagging-not-queued-workaround.patch0 (2.5 KB) - added by Bill Meek <keemllib@…> 9 years ago.
Workaround - tested on: v0.28-pre-2261-g53254f3
mythbackend.20150420180329.30958.log (32.2 KB) - added by Bill Meek <keemllib@…> 9 years ago.
1st try blocked
mythbackend.20150422001210.13197.log (210.9 KB) - added by Bill Meek <keemllib@…> 9 years ago.
Additional LOG()s added.
12290.patch (1.2 KB) - added by Bill Meek 8 years ago.
before.log (10.3 KB) - added by Roger Siddons 8 years ago.
Zero filesize
after.log (9.6 KB) - added by Roger Siddons 8 years ago.
Correct filesize
12290-Bills-instrumentation.patch (2.8 KB) - added by Roger Siddons 8 years ago.
Logging
12290-Report-correct-filesize-at-recording-end.patch (2.0 KB) - added by Roger Siddons 8 years ago.
Fix

Download all attachments as: .zip

Change History (43)

Changed 9 years ago by Bill Meek <keemllib@…>

Workaround - tested on: v0.28-pre-2261-g53254f3

comment:1 Changed 9 years ago by km@…

Thanks to Bill Meek for the workaround. I've had to use it to patch programinfo.cpp every time that file gets updated on the trunk for the last 5 months. Isn't it about time to integrate it?

comment:2 Changed 9 years ago by stuartm

I believe this was fixed months ago.

comment:3 Changed 9 years ago by stuartm

Resolution: Fixed
Status: newclosed

If this continues to be a problem for anyone then we need more information. The file size is not even stored in ProgramInfo? any more, they are saved to and read from RecordingFile? and the corresponding RecordedFile? table.

comment:4 Changed 9 years ago by Stuart Morgan <smorgan@…>

In 767370fe7ea41f78ae99b7cd1ef4ddcdf5d8d016/mythtv:

Until the filesize is removed from ProgramInfo?, make sure it's kept up to date. There may be bits of code still looking there instead. Refs #12290

comment:5 Changed 9 years ago by Bill Meek <keemllib@…>

Resolution: Fixed
Status: closednew

Sorry, that doesn't solve the issue.

I added some LOG()s to demonstrate.

tv_rec.cpp:936 (FinishedRecording) - fsize>=1000 allows previewgen. fsize=0.
...
tv_rec.cpp:989 (FinishedRecording) - fsize<1000 disables commflag/xcode. fsize=0.

Full log and LOG() patch attached.

Changed 9 years ago by Bill Meek <keemllib@…>

1st try blocked

comment:6 Changed 9 years ago by Bill Meek <keemllib@…>

To answer the questions on the mythtv channel, it's not the 0 byte file case. The recording plays back OK, manual commercial flagging works OK

mysql> SELECT recordedid FROM recorded WHERE title='Love It or List It';
| recordedid |
|       2916 |

mysql> SELECT r.filesize,rf.filesize FROM recorded AS r,
    recordedfile AS rf WHERE r.recordedid=2916 and rf.recordedid=2916;
| filesize  | filesize  |
| 883567100 | 883567100 |

comment:7 Changed 9 years ago by stuartm

Thanks for the follow up Bill. So it seems the cached RecordingInfo? used in TVRec isn't being updated ...

comment:8 Changed 9 years ago by Stuart Morgan <smorgan@…>

In cf4da125a78bde32fb309fbddfc557993d4045fe/mythtv:

Ensure RecordingFile? object is loaded when we call RI::GetFilesize?()

Refs #12290

comment:9 Changed 9 years ago by Stuart Morgan <smorgan@…>

comment:10 Changed 9 years ago by Bill Meek <keemllib@…>

I added 2 more LOG()s and they return:

TVRecEvent recordinginfo.cpp:1628 (GetFilesize) - #12290 GetRecordingFile()->m_fileSize = 0
TVRecEvent recordinginfo.cpp:1637 (GetFilesize) - #12290 ProgramInfo::GetFilesize() = 0

And more LOG()s in RecordingFile::RecordingFile? and RecordingFile::Save:

This keeps incrementing during the recording:

recordingfile.cpp RecordingFile::Save() #12290, m_fileSize=405709264

Which then starts returning 0 (1268 times) after the recording finishes

Full log attached.

Changed 9 years ago by Bill Meek <keemllib@…>

Additional LOG()s added.

comment:11 Changed 9 years ago by drew@…

Can anything be done to further this along? This bug is quite annoying for those of us that don't build from source to manually patch.

If someone can point me where to start, I don't mind attempting a patch myself.

comment:12 Changed 8 years ago by Stuart Auchterlonie

Milestone: unknown0.28

Changed 8 years ago by Bill Meek

Attachment: 12290.patch added

comment:13 Changed 8 years ago by Bill Meek

POC patch, works fine, I just don't know how to treat the other 6 calls to FinishedRecording().

comment:14 Changed 8 years ago by JYA

Bill, anything more required ? that last patch seems good enough to me.

comment:15 Changed 8 years ago by Bill Meek <keemllib@…>

Unfortunately, it isn't enough. When RingBufferChanged() (https://code.mythtv.org/cgit/mythtv/tree/mythtv/libs/libmythtv/tv_rec.cpp#n3358) is used, I've not been able to recover a size. I haven't seen the other 4 calls to FinishedRecording() used. Had to go back to the workaround in comment 1.

comment:16 Changed 8 years ago by km@…

I can also report that the new patch is not a complete solution. Some recordings get flagged others don't. With the original patch all recordings that are set for auto flagging get flagged.

With neither patch, nothing gets auto flagged.

comment:17 Changed 8 years ago by Bill Meek <bmeek@…>

In 2e98fb583276c3966fed21fab354b11c7e5d591c/mythtv:

Restore queuing of jobs when a recording finishes.

Reverts a portion of ffef83f. In TVRec::FinishedRecording?, a check
of the recording's filesize is made. If it's less than 1000, then
PreviewGeneratorQueue? isn't run. JOB_COMMFLAG and JOB_TRANSCODE
get removed from the queue.

After ffef83f ProgramInfo::GetFilesize? will, at times, return a
filesize of 0 even though it's not. This is always 0 at the end
of a recording (only DVB and HDHOMERUN card types tested.)

This workaround will use the RecordedInfo? filesize value if it's
non zero because in all tests, if non zero, the RI filesize
matched the value returned from the DB.

If RI filesize is zero, then there's no way to know if it's valid,
so use the 'old' DB query. If VB_RECORD is set and the DB filesize
is > 0 (and RI filesize = 0) then LOG.

I'm assuming that simply removing the 1000 byte test is a worse
workaround to the problem.

Refs #12290

comment:18 Changed 8 years ago by Bill Meek <bmeek@…>

In 4ffac871792a83aa354230a0655651c934c2bf40/mythtv:

Restore queuing of jobs when a recording finishes.

Reverts a portion of ffef83f. In TVRec::FinishedRecording?, a check
of the recording's filesize is made. If it's less than 1000, then
PreviewGeneratorQueue? isn't run. JOB_COMMFLAG and JOB_TRANSCODE
get removed from the queue.

After ffef83f ProgramInfo::GetFilesize? will, at times, return a
filesize of 0 even though it's not. This is always 0 at the end
of a recording (only DVB and HDHOMERUN card types tested.)

This workaround will use the RecordedInfo? filesize value if it's
non zero because in all tests, if non zero, the RI filesize
matched the value returned from the DB.

If RI filesize is zero, then there's no way to know if it's valid,
so use the 'old' DB query. If VB_RECORD is set and the DB filesize
is > 0 (and RI filesize = 0) then LOG.

I'm assuming that simply removing the 1000 byte test is a worse
workaround to the problem.

Refs #12290

(cherry picked from commit 2e98fb583276c3966fed21fab354b11c7e5d591c)

comment:19 Changed 8 years ago by Stuart Auchterlonie

Milestone: 0.280.29

Moving to 0.29

comment:20 Changed 8 years ago by Stuart Auchterlonie

Milestone: 0.2929.0

Milestone renamed

comment:21 Changed 8 years ago by Roger Siddons

The "Hack fix" (31da15ad7) wasn't implemented correctly.

There are 2 instances of m_recording_file (in 2 separate RecInfos): the TVRec one is created at start of the recording and never updated, the Recorder one contains the updated filesize (and other data).

That patch intends to reload the stale instance but it is ineffective because the TVRec instance already exists. It needs to be forcibly reloaded.

I reverted the 4 patches on this ticket (2e98fb5832, 31da15ad7, cf4da125a78, 767370fe7e) and applied Bill's instrumentation to reproduce the before.log. Then applied the new patch to produce the after.log.

Changed 8 years ago by Roger Siddons

Attachment: before.log added

Zero filesize

Changed 8 years ago by Roger Siddons

Attachment: after.log added

Correct filesize

Changed 8 years ago by Roger Siddons

Logging

Changed 8 years ago by Roger Siddons

Fix

comment:22 Changed 8 years ago by stuartm

Milestone: 29.00.28.1
Owner: set to stuartm
Status: newaccepted

comment:23 Changed 7 years ago by Stuart Auchterlonie

Milestone: 0.28.10.28.2

Moving remaining open 0.28.1 tickets to 0.28.2

comment:24 Changed 7 years ago by Roger Siddons

Status: acceptedinfoneeded

Can anyone confirm whether the solution in comment 21 fixes the issue ?

comment:25 Changed 7 years ago by Roger Siddons

Owner: changed from stuartm to Roger Siddons

comment:26 in reply to:  24 Changed 7 years ago by Bill Meek

Replying to rsiddons:

Can anyone confirm whether the solution in comment 21 fixes the issue ?

Roger,

Only two tests, and flagging is queued (and works.) That's with the four reverts plus your fix. I should track it for a few days as others have reported inconsistent results with previous patches.

Looks like an edge case when the backend is restarted mid recording. The 2nd recording is flagged, the 1st isn't. I don't recall ever testing this originally and haven't tried with the old solution yet. Likely a new issue.

comment:27 Changed 7 years ago by Roger Siddons

Thanks Bill,

Soak-test by all means but it would be nice if we could tidy this up for 28.2

The "old solution" was a work-around to the fact that a new implementation wasn't working properly.

I don't actually use the commflagger. I landed here because I had an issue with 0 filesizes elsewhere. Turns out it was unrelated...

However, isn't the job created by an end-of-recording event ? Should the backend check for interrupted recordings due for comm-flagging on startup ? User should start it manually IMO. And outside the scope of this ticket :)

comment:28 Changed 7 years ago by Bill Meek

Seems to be working great. Tested on v29-pre. Do you want to push the four reverts and fix or would you like me to?

Last edited 7 years ago by Bill Meek (previous) (diff)

comment:29 Changed 7 years ago by Roger Siddons

Milestone: 0.28.229.0
Status: infoneededassigned

On review, it appears to no longer be an issue on 28/fixes: the work-around seems to be effective.

Whilst the fixes in comment:21 fix the specific issue on this ticket, the underlying changes that provoked it remain incomplete so it's not robust enough to be back-ported.

Targeting it for 29/master, once I've assessed what is still broken & the way forward.

Leaving this open to track it. Please report any observations of wrong filesizes.

comment:30 Changed 6 years ago by Stuart Auchterlonie

Milestone: 29.029.1

comment:31 Changed 6 years ago by Roger Siddons

Milestone: 29.129.2

comment:32 Changed 5 years ago by dizygotheca

Milestone: 29.230.1

comment:33 Changed 4 years ago by Mac Michaels

Is 3 years long enough to track this issue?

comment:34 Changed 4 years ago by Stuart Auchterlonie

Status: assignedinfoneeded

Bill, is this still an issue, or can this be closed?

comment:35 Changed 4 years ago by Bill Meek

Resolution: Fixed
Status: infoneededclosed

It's working. But I just undid a single conversion from Stuart Morgan's ProgramInfo? -> RecordedInfo? work. I see Roger kept it open to track the root cause.

Closing. A new ticket can be used to track the underlying issue if someone wants to go after it.

Note: See TracTickets for help on using tickets.