Sometimes no image rendered when playing video (4 Viewers)

[CyberSimian]

Loading external players is only done once per mediaportal session, so it should be present earlier and doesn't give a hint... Same holds for the Loadnotifies

Thinking about this now, I should have tried to reproduce as exactly as possible what I did when the error occurred.

The planescene..GUIVideooverlay looks like something interesting...
I'll see if I can find something or add more logging...

Thank you . This problem has not occurred as frequently as in the past, but I cannot think of changes to the system, or my way of using it, that might have affected this. (I have altered the networking recently, by adding a second network card, but it seems unlikely that that would cause a reduction in occurrences.)

Which editor is that where you compare logs? I'm always struggling to do an easy comparision without the timestamps.

I use an old version of Blair Thompson's "X" editor. The version that I use is character based (a "CUI"), but there is a much newer version that may (or may not) be GUI based (I must get around to trying it someday). The comparison that I described above used the editor in the fashion of a blink comparator. I simply scrolled to the right until the timestamps in the log were off the left edge of the screen and then alternated between the two log files in the editing ring. However...

Looking through my library of BAT files I see that I have a "logclean.bat" which removes all of the lines from "PowerScheduler", as nowadays those lines are merely noise (I am sure that they were useful when "PowerScheduler" was still being developed). The catch is that "logclean.bat" uses "delall.rex", which is the program that actually does the work:

:* logclean.bat
call delall.rex "[PS StandbyWakeup]" /R %*
call delall.rex "- PS: " /R %*
call delall.rex "*" /C:1-26 %*

Rexx is a "yasl" ("Yet Another Scripting Language"), but it is the one that I routinely use on my system for all scripting work. . I have just added the "/C" option to "delall.rex" to delete columns 1-26 (i.e. the timestamp in MP log files). You are welcome to have a copy of "delall.rex" if you wish, but the catch is that you will need to install a Rexx interpreter in order to run it. The good news is that there is a truly excellent open-source freeware Rexx interpreter called "Open Object Rexx", which can be downloaded from SourceForge. Note: the X editor uses Rexx as its macro language, so if you want to use X, you will need to install Rexx.

-- from CyberSimian in the UK

 

[bta489]

New set of logs attached to this post.

I have had less screen time lately, and in that time only a few occurences, mostly of the 'other type' (where I can't toggle the GUI) so I didn't save the logs for those. This one is of the 'right' kind, like the previous ones (info-button toggles the fullscreen osd and navigation back to menu works fine).

 

[doskabouter]

Hm, no OverflowException to be found in those logs...
I'm beginning to suspect that overflow exception is just a red herring, and the undelying cause is something competely different
On the other hand, those overflows are relatively easy to debug and fix... But in your latest Mediaportal.log there is absolutely no error present, so not much to cling on to here...

 

[bta489]

well...that's unfortunate.
I just checked some other logfiles, the only suspect logs are in the FanartHandler.log around that time. It complains that it could not load an image due to insufficient RAM:

LoadImageFastFromFile: Unable to load Imagefile (corrupt?): C:\ProgramData\Team MediaPortal\MediaPortal\Thumbs\Fan Art\fanart\original\80252-5.jpg - Nicht genügend Arbeitsspeicher.

The file appears to be broken, I deleted it. I doubt it really ran out of memory, though. My hwinfo logs I had running while waiting for occurances of the error show RAM usage of 30-50% over several days of normal usage.

I had a dynamically allocated ramdisk set up, but it was not used for anything. I have removed this now as well.

 

[CyberSimian]

@doskabouter : I had another occurrence of my "no video" problem on Sunday, and this time I immediately repeated the sequence of actions (as far as I could remember), but without allowing the MP or Windows screen savers to operate. I have renamed the logs "good" and "bad", and performed the following edits:

• Removed the "PowerScheduler" lines.
• Removed the timestamps.
• Removed the lines preceding a point near where I initiated playback.
• Removed the lines following the "Shutdown dialog" line.

The logs are identical except for:

• The good log has several lines for "resume playback" (I had forgotten to reset the resume point), but I think that we can ignore these lines.
• There are about 1450 lines of what I think is the new debug logging that you added. This debug logging is completely absent from the bad log.

Ignoring the "resume playback" lines, we have these lines common to both logs:

TSReaderPlayer:Window (0,0)-(100,100) - (420,0)-(1500,1080)
TSReaderPlayer: SetSourcePosition 1
TSReaderPlayer: SetSourcePosition 2
VMR9Helper: Playing -> Repainting, Frames 50
GUIVideoOverlay : SetCurrentFile DoesPostRender _fileName Gardeners' World Easter Special (BBC2 HD) 2021-04-02 21.00.00
PlaneScene: PresentImage() dispose surfaces
VMR9: Repainting -> Playing, Frames: 50

The good log then has these lines which are missing from the bad log:

PlaneScene: crop T, B  : 0, 0
PlaneScene: crop L, R  : 0, 0
PlaneScene: video WxH  : 1920x1080
PlaneScene: video AR   : 16:9
PlaneScene: screen WxH : 1920x1080
PlaneScene: AR type    : Normal
PlaneScene: PixelRatio : 1
PlaneScene: src        : (0,0)-(1920,1080)
PlaneScene: dst        : (0,0)-(1920,1080)
start drawtexture 104180320 369098751
drawtexture after fontengineset
drawtexture after FontEngineSetSamplerState
drawtexture start DrawTextureSegment
Drawtexturesegment 0 0 1920 1080 0 0 1920 1080 1920 1080 369098751
Drawtexturesegment done
drawtexture done
...block starting "start drawtexture" repeated many many times...

The logs become identical again at this point:

Centarea: Command "178" mapped
Main: Stopping media
g_Player.doStop() keepTimeShifting = False keepExclusiveModeOn = False
g_Player.OnStopped()
GUIVideoFiles: OnPlayBackStopped idFile=3173 timeMovieStopped=9 resumeData= bdtitle=1000
GUIVideoFiles: OnPlayBackStopped store resume time
RadioRecorded:OnPlayRecordingBackStopped Video P:\TV\Interests\Gardening\Gardeners' World\Gardeners' World Easter Special (BBC2 HD) 2021-04-02 21.00.00.ts
TvRecorded:OnPlayRecordingBackStopped Video P:\TV\Interests\Gardening\Gardeners' World\Gardeners' World Easter Special (BBC2 HD) 2021-04-02 21.00.00.ts
g_Player.doStop() - stop

My guess (and we all know how accurate my guesses are ) is that at some point during the processing that initiates playback, a test is performed which gives the wrong result, and this wrong result causes the code containing your debug logging to be bypassed. So I think that we need to add debug logging to the functions that are executed prior to your existing debug logging.

If you have the time to add the additional logging, I would suggest keeping a look out for any test involving either the MP screen saver or the Windows screen saver, perhaps something like:

if screen_saver_is_active
then { do_nothing; }
else { display_the_video_stream; }

If code like this actually exists, it suggests that the MP screen saver is not being reset correctly (but this is just a guess ).

-- from CyberSimian in the UK

 

[doskabouter]

Hm just checked screensaver code and at first sight nothing to be done there (but add some logging anyway)
Also added more logging to pinpoint where it deviates from the good path (hopefully)

 

[CyberSimian]

Also added more logging to pinpoint where it deviates from the good path (hopefully)

Thank you for adding the extra debug logging.
I have installed the modified files and have been watching some live TV and recorded TV.

One quirk that I noticed is with regard to the quantity of logging. I watched a 30-minute recording, and then exited MP to examine the log file. I found the "playback stopping" lines in "MediaPortal.log", but I could not find the "playback starting" lines. I then looked at the "MediaPortal.n.log" files (n=1 to 5), but the "playback starting" lines were nowhere to be found . All of the previous log files are filled with the new debug logging. It seems that MP starts a new log file when the log reaches about 5 MByte in size (around 60K lines), and keeps only the previous five logs (TV Server keeps the previous ten logs).

I don't think that filling the log files matters greatly, as when the "no video" error occurs, I will stop playback immediately, so the important "playback starting" lines will be in the current log file.

From looking at the log file, I notice that when a recording was being played, the log file has two lines that repeat every 20 msec, namely "In screensaver" and "Not blank". So I suppose that the screen saver code is executed every 20 msec to check whether it should do anything.

There is one unrelated (I think) quirk that looks like it might be an error. So far I have always assumed that the error log files contained the errors from the corresponding full log files. So "MediaPortal-Error.1.log" contains the error lines from "MediaPortal.1.log". With the extra debug logging, that is no longer true. For example, "MediaPortal.5.log" is a log from today, but "MediaPortal-Error.5.log" shows the error lines from yesterday. So for some reason the error log files and the full log files are no longer being kept in step.

I will continue using the debug versions and see if I can provoke the error, but so far I have not noticed a correlation with any particular sequence of actions (other than the MP and/or the Windows screen savers operating when on a MP panel, but that is not enough to guarantee that the error will occur -- it seems as though there is some other factor involved).

Thank you for the work that you have done so far!

-- from CyberSimian in the UK

 

[doskabouter]

Thank you for adding the extra debug logging.
I have installed the modified files and have been watching some live TV and recorded TV.

One quirk that I noticed is with regard to the quantity of logging. I watched a 30-minute recording, and then exited MP to examine the log file. I found the "playback stopping" lines in "MediaPortal.log", but I could not find the "playback starting" lines. I then looked at the "MediaPortal.n.log" files (n=1 to 5), but the "playback starting" lines were nowhere to be found . All of the previous log files are filled with the new debug logging. It seems that MP starts a new log file when the log reaches about 5 MByte in size (around 60K lines), and keeps only the previous five logs (TV Server keeps the previous ten logs).

I don't think that filling the log files matters greatly, as when the "no video" error occurs, I will stop playback immediately, so the important "playback starting" lines will be in the current log file.

From looking at the log file, I notice that when a recording was being played, the log file has two lines that repeat every 20 msec, namely "In screensaver" and "Not blank". So I suppose that the screen saver code is executed every 20 msec to check whether it should do anything.

There is one unrelated (I think) quirk that looks like it might be an error. So far I have always assumed that the error log files contained the errors from the corresponding full log files. So "MediaPortal-Error.1.log" contains the error lines from "MediaPortal.1.log". With the extra debug logging, that is no longer true. For example, "MediaPortal.5.log" is a log from today, but "MediaPortal-Error.5.log" shows the error lines from yesterday. So for some reason the error log files and the full log files are no longer being kept in step.

I will continue using the debug versions and see if I can provoke the error, but so far I have not noticed a correlation with any particular sequence of actions (other than the MP and/or the Windows screen savers operating when on a MP panel, but that is not enough to guarantee that the error will occur -- it seems as though there is some other factor involved).

Thank you for the work that you have done so far!

-- from CyberSimian in the UK

Thanks!
If the screensaver stuff is getting in the way of more important logging, just use the original mediaportal.exe (that is my only addition there)
I think that cycling logs (if they get too big) is interfering with the numbers of the error logs, but as you said it's no big issue

 

[CyberSimian]

Also added more logging to pinpoint where it deviates from the good path (hopefully)

I tried to reproduce the error this morning, and this time the error occurred . I have created good and bad logs as before, and edited them to remove what I think is not significant (to make comparing the logs simpler). Some observations:

• In parts of the logs that are identical, occasionally lines occur slightly out of order. I guess that this is simply different threads inserting lines into the log at slightly different times (so these differences are not significant).
• I think that playback processing starts at the line containing PlayRecording: (this string occurs only once in each log).
• Ignoring line-ordering differences, the logs are identical from that point up to a few lines after the first occurrence of the string not Isplayingvideo
• In the bad log, the string not Isplayingvideo occurs 334 times, whereas in the good log it occurs only once. So the bad log keeps saying "not playing video" when the good log is playing video.

I hope that my editing has not removed anything significant from the logs.

-- from CyberSimian in the UK

 

[doskabouter]

Well that is a quick turnaround time I guess you get better and better in triggering the error.
Now to add extra logging to find why that IsPlayingVideo isn't set properly... I'll do that as soon as I have time for it