<div dir="ltr">I've seen these repeated "decoding error End of file" messages also with other use cases (live TV and recordings) so it is not specific for mythcommflag.<div>I had not realized that this bug was already that old, but having a "good" and a "bad" date does make bisecting possible.</div><div><br></div><div>Klaas.</div></div><br><div class="gmail_quote"><div dir="ltr" class="gmail_attr">On Tue, 20 Sept 2022 at 12:21, Eyal Lebedinsky <<a href="mailto:eyal@eyal.emu.id.au">eyal@eyal.emu.id.au</a>> wrote:<br></div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex">This is on up-to-date f36.<br>
<br>
I recently noticed that I get huge mythcommflag logs at times. I archive these so I checked back<br>
and I can see that this started when mythbackend changed in 2019-07-15 from<br>
mythcommflag version: fixes/29 [v29.1-v29.1-36-gdde16d475a] <a href="http://www.mythtv.org" rel="noreferrer" target="_blank">www.mythtv.org</a><br>
to<br>
mythcommflag version: fixes/30 [v30.0-v30.0-53-g6bd8cd4993] <a href="http://www.mythtv.org" rel="noreferrer" target="_blank">www.mythtv.org</a><br>
and this is still happening.<br>
<br>
It is by accident that I noticed the problem when archiving logs and wondering why they differ<br>
so much in size, here are the logs of one recent day:<br>
<br>
8514 09-16-2022 01:41 mythcommflag.20220915142648.3928671.log<br>
30980901 09-16-2022 05:38 mythcommflag.20220915191854.413609.log<br>
8699 09-16-2022 05:36 mythcommflag.20220915192259.416517.log<br>
8698 09-16-2022 07:34 mythcommflag.20220915205604.451699.log<br>
31718559 09-16-2022 12:00 mythcommflag.20220916012610.568727.log<br>
32057355 09-16-2022 12:00 mythcommflag.20220916013215.572183.log<br>
4769 09-16-2022 12:00 mythcommflag.20220916020020.585123.log<br>
31217919 09-16-2022 17:35 mythcommflag.20220916065626.714662.log<br>
8700 09-16-2022 17:35 mythcommflag.20220916070231.720047.log<br>
8392 09-16-2022 18:04 mythcommflag.20220916072536.728798.log<br>
19879 09-16-2022 19:40 mythcommflag.20220916083002.763603.log<br>
30842026 09-16-2022 20:06 mythcommflag.20220916092707.788562.log<br>
7971 09-16-2022 19:44 mythcommflag.20220916093312.792514.log<br>
8697 09-16-2022 21:59 mythcommflag.20220916105818.834161.log<br>
8392 09-16-2022 22:20 mythcommflag.20220916113423.853572.log<br>
29126 09-16-2022 22:51 mythcommflag.20220916120628.870365.log<br>
<br>
Here is the log of a typical small case.<br>
<br>
2022-09-20 18:42:21.425692 I [2945779/2945779] CoreContext ClassicCommDetector.cpp:542 (go) - 0%% Completed @ 877.193 fps.<br>
2022-09-20 18:42:38.604020 I [2945779/2945779] CoreContext ClassicCommDetector.cpp:542 (go) - 10%% Completed @ 526.224 fps.<br>
2022-09-20 18:42:55.755361 I [2945779/2945779] CoreContext ClassicCommDetector.cpp:542 (go) - 20%% Completed @ 528.394 fps.<br>
2022-09-20 18:48:11.804726 I [2945779/2945779] CoreContext ClassicCommDetector.cpp:542 (go) - 30%% Completed @ 77.605 fps.<br>
2022-09-20 18:54:16.131881 I [2945779/2945779] CoreContext ClassicCommDetector.cpp:542 (go) - 40%% Completed @ 50.7822 fps.<br>
2022-09-20 19:00:19.798849 I [2945779/2945779] CoreContext ClassicCommDetector.cpp:542 (go) - 50%% Completed @ 42.096 fps.<br>
2022-09-20 19:06:20.835929 I [2945779/2945779] CoreContext ClassicCommDetector.cpp:542 (go) - 60%% Completed @ 37.7903 fps.<br>
2022-09-20 19:12:24.337669 I [2945779/2945779] CoreContext ClassicCommDetector.cpp:542 (go) - 70%% Completed @ 35.2186 fps.<br>
2022-09-20 19:18:24.700522 I [2945779/2945779] CoreContext ClassicCommDetector.cpp:542 (go) - 80%% Completed @ 33.5123 fps.<br>
2022-09-20 19:24:28.523867 I [2945779/2945779] CoreContext ClassicCommDetector.cpp:542 (go) - 90%% Completed @ 32.2886 fps.<br>
2022-09-20 19:30:32.806448 I [2945779/2945779] CoreContext ClassicCommDetector.cpp:542 (go) - 100%% Completed @ 31.3679 fps.<br>
2022-09-20 19:35:25.417574 E [2945779/2950411] Decoder decoders/avformatdecoder.cpp:4964 (GetFrame) - decoding error End of file (-541478725)<br>
2022-09-20 19:35:26.516100 N [2945779/2945779] CoreContext main.cpp:955 (FlagCommercials) - Finished, 3 break(s) found.<br>
2022-09-20 19:35:26.553358 I [2945779/2945779] CoreContext platforms/mythpowerdbus.cpp:72 (~MythPowerDBus) - PowerDBus: Closing interfaces<br>
2022-09-20 19:35:26.554205 I [2945779/2945779] CoreContext mythcontext.cpp:1667 (~MythContext) - Waiting for threads to exit.<br>
2022-09-20 19:35:27.952436 I [2945779/2945779] CoreContext mythcontext.cpp:1673 (~MythContext) - Exiting<br>
<br>
Here is the log of a typical large case.<br>
<br>
At first I see the commercial flagging running while the recording happens (23:50:55-00:25:32).<br>
Then, following the recording ending I get a burst (221,918 lines) of messages (00:30:05-00:30:07, 2 seconds).<br>
Here is an excerpt from the log:<br>
<br>
2022-09-19 23:50:55.148850 I [3326968/3326968] CoreContext ClassicCommDetector.cpp:365 (go) - Finding Logo<br>
2022-09-19 23:51:07.898927 I [3326968/3326968] CoreContext ClassicCommDetector.cpp:542 (go) - 0%% Completed @ 1250 fps.<br>
2022-09-19 23:51:10.838582 I [3326968/3326968] CoreContext ClassicCommDetector.cpp:542 (go) - 10%% Completed @ 2517.39 fps.<br>
2022-09-19 23:51:13.724756 I [3326968/3326968] CoreContext ClassicCommDetector.cpp:542 (go) - 20%% Completed @ 2558.02 fps.<br>
2022-09-19 23:51:16.797471 I [3326968/3326968] CoreContext ClassicCommDetector.cpp:542 (go) - 30%% Completed @ 2517.26 fps.<br>
2022-09-19 23:55:32.964330 I [3326968/3326968] CoreContext ClassicCommDetector.cpp:542 (go) - 40%% Completed @ 113.524 fps.<br>
2022-09-20 00:00:32.941836 I [3326968/3326968] CoreContext ClassicCommDetector.cpp:542 (go) - 50%% Completed @ 66.5342 fps.<br>
2022-09-20 00:05:32.948848 I [3326968/3326968] CoreContext ClassicCommDetector.cpp:542 (go) - 60%% Completed @ 52.1309 fps.<br>
2022-09-20 00:10:32.963011 I [3326968/3326968] CoreContext ClassicCommDetector.cpp:542 (go) - 70%% Completed @ 45.1447 fps.<br>
2022-09-20 00:15:32.954310 I [3326968/3326968] CoreContext ClassicCommDetector.cpp:542 (go) - 80%% Completed @ 41.0202 fps.<br>
2022-09-20 00:20:32.951947 I [3326968/3326968] CoreContext ClassicCommDetector.cpp:542 (go) - 90%% Completed @ 38.2974 fps.<br>
2022-09-20 00:25:32.959836 I [3326968/3326968] CoreContext ClassicCommDetector.cpp:542 (go) - 100%% Completed @ 36.3656 fps.<br>
2022-09-20 00:30:05.151147 E [3326968/3335951] Decoder decoders/avformatdecoder.cpp:4964 (GetFrame) - decoding error End of file (-541478725)<br>
2022-09-20 00:30:05.151160 E [3326968/3335951] Decoder decoders/avformatdecoder.cpp:4964 (GetFrame) - decoding error End of file (-541478725)<br>
2022-09-20 00:30:05.151169 E [3326968/3335951] Decoder decoders/avformatdecoder.cpp:4964 (GetFrame) - decoding error End of file (-541478725)<br>
2022-09-20 00:30:05.151178 E [3326968/3335951] Decoder decoders/avformatdecoder.cpp:4964 (GetFrame) - decoding error End of file (-541478725)<br>
2022-09-20 00:30:05.151187 E [3326968/3335951] Decoder decoders/avformatdecoder.cpp:4964 (GetFrame) - decoding error End of file (-541478725)<br>
... [trimmed] many repeats of the last error message<br>
2022-09-20 00:30:07.257395 N [3326968/3326968] CoreContext main.cpp:955 (FlagCommercials) - Finished, 3 break(s) found.<br>
2022-09-20 00:30:07.257399 E [3326968/3335951] Decoder decoders/avformatdecoder.cpp:4964 (GetFrame) - decoding error End of file (-541478725)<br>
2022-09-20 00:30:07.257408 E [3326968/3335951] Decoder decoders/avformatdecoder.cpp:4964 (GetFrame) - decoding error End of file (-541478725)<br>
2022-09-20 00:30:07.257440 E [3326968/3335951] Decoder decoders/avformatdecoder.cpp:4964 (GetFrame) - decoding error End of file (-541478725)<br>
2022-09-20 00:30:07.257449 E [3326968/3335951] Decoder decoders/avformatdecoder.cpp:4964 (GetFrame) - decoding error End of file (-541478725)<br>
2022-09-20 00:30:07.266332 I [3326968/3326968] CoreContext platforms/mythpowerdbus.cpp:72 (~MythPowerDBus) - PowerDBus: Closing interfaces<br>
2022-09-20 00:30:07.266524 I [3326968/3326968] CoreContext mythcontext.cpp:1667 (~MythContext) - Waiting for threads to exit.<br>
<br>
$ grep -c '2022-09-20 00:30:0.*decoding error End of file' /data1/tmp/mythcommflag.20220919133532.3326968.log<br>
221918<br>
<br>
$ dnf list installed 'mythtv*'<br>
Installed Packages<br>
mythtv-backend.x86_64 32.0-1.44.20220625git4cf469cbbf.fc36 @rpmfusion-free-updates<br>
mythtv-base-themes.x86_64 32.0-1.44.20220625git4cf469cbbf.fc36 @rpmfusion-free-updates<br>
mythtv-common.x86_64 32.0-1.44.20220625git4cf469cbbf.fc36 @rpmfusion-free-updates<br>
mythtv-docs.noarch 32.0-1.44.20220625git4cf469cbbf.fc36 @rpmfusion-free-updates<br>
mythtv-frontend.x86_64 32.0-1.44.20220625git4cf469cbbf.fc36 @rpmfusion-free-updates<br>
mythtv-libs.x86_64 32.0-1.44.20220625git4cf469cbbf.fc36 @rpmfusion-free-updates<br>
mythtv-setup.x86_64 32.0-1.44.20220625git4cf469cbbf.fc36 @rpmfusion-free-updates<br>
mythtv-status.noarch 1.0.1-8.fc36 @rpmfusion-free<br>
<br>
-- <br>
Eyal Lebedinsky (<a href="mailto:eyal@eyal.emu.id.au" target="_blank">eyal@eyal.emu.id.au</a>)<br>
_______________________________________________<br>
mythtv-users mailing list<br>
<a href="mailto:mythtv-users@mythtv.org" target="_blank">mythtv-users@mythtv.org</a><br>
<a href="http://lists.mythtv.org/mailman/listinfo/mythtv-users" rel="noreferrer" target="_blank">http://lists.mythtv.org/mailman/listinfo/mythtv-users</a><br>
<a href="http://wiki.mythtv.org/Mailing_List_etiquette" rel="noreferrer" target="_blank">http://wiki.mythtv.org/Mailing_List_etiquette</a><br>
MythTV Forums: <a href="https://forum.mythtv.org" rel="noreferrer" target="_blank">https://forum.mythtv.org</a><br>
</blockquote></div>