knewc UI Client put player in background

[BrettB]

Hey, Martin.

For a while (going back to v4 and I'm pretty sure X-NEWA), we would occasionally (a couple of times a week, maybe) have an issue where when we'd start a show playing, the player seems to be put in the background and the Recording list continues to display. (You can hear the video playing, but not see it.) Pressing buttons (like the arrows, the stop, etc.) affect both the Recording list and the playing video in the background. If I exit out of knewc back to the Kodi main menu, then I see the video playing in the background.

It may be coincidence, but since the upgrade to the latest Nextpvr v5 version yesterday morning, I've had it happen multiple times. For the latest, I captured logs. Kodi's been running for a while, so the kodi log is very large. I put it in the folder with the NextPVR logs. You can download them here:

Logs Download

The occurance this moring was at 7:01:

Code:

2019-11-18 07:01:14.687 T:1860170608  DEBUG: LIRC: - NEW 160 0 KEY_OK devinput (KEY_OK)
2019-11-18 07:01:14.718 T:1937563664  DEBUG: HandleKey: 11 (0x0b, obc244) pressed, action is Select
2019-11-18 07:01:14.718 T:1051718512  DEBUG: False
2019-11-18 07:01:14.719 T:1051718512  DEBUG: http://192.168.143.10:8866/control?time=1574082074&key=13&client=sdl-KNEW50xb827ebd2d752&sid=1e6cd64892534d59aa60b8a9ad544aff
2019-11-18 07:01:15.742 T:1051718512  DEBUG: http://192.168.143.10:8866/activity?format=json&client=sdl-KNEW50xb827ebd2d752&sid=1e6cd64892534d59aa60b8a9ad544aff
2019-11-18 07:01:15.762 T:1051718512  DEBUG: {u'recording_title': u'American Housewife', u'recording_description': u"When Greg hosts a meeting for the Westport Historical Guild to welcome back Stan, Katie's homemade lasagna is a huge hit with the guys; Angela and Doris step in to help Oliver with his Teen Help Line interview.", u'url': u'/stream?client=1e6cd64892534d59aa60b8a9ad544aff&seek=1308&f=E%3A%5CNPVR%20Recordings2%5CAmerican%20Housewife%5CAmerican%20Housewife.S04E04.Lasagna.ts', u'screen': u'Recordings', u'supports_server_skip': u'true', u'recording_name': u'American Housewife', u'recording_resume': u'1308', u'file': u'E:\\NPVR Recordings2\\American Housewife\\American Housewife.S04E04.Lasagna.ts', u'recording_id': u'14586', u'recording_subtitle': u'Lasagna', u'recording_duration': u'2157'}
2019-11-18 07:01:15.774 T:1051718512  DEBUG: True
2019-11-18 07:01:15.793 T:1184875376  DEBUG: #XBMCPlayer#
2019-11-18 07:01:15.794 T:1184875376  DEBUG: started player
2019-11-18 07:01:15.874 T:1184875376  DEBUG: E:/NPVR Recordings2/American Housewife/American Housewife.S04E04.Lasagna.ts
2019-11-18 07:01:15.916 T:1184875376  DEBUG: Playing E:/NPVR Recordings2/American Housewife/American Housewife.S04E04.Lasagna.ts
2019-11-18 07:01:15.917 T:1184875376  DEBUG: player started

[mvallevand]

I can see the cause in the logs, the client tells the server to turn on normal rendering

2019-11-18 07:01:23.464 T:967791472 DEBUG: http://192.168.143.10:8866/control?media...a9ad544aff

I am thinking it might be a slight delay when you move from the D to E drive but I need to check things out further

Unfortunately the server side logging from UI client looks extensive it doesn't log the useful information so this might not be trivial and I might need to add more logging in the client.

Martin

[BrettB]

I can see the  cause in the logs, the client tells the server to turn on normal rendering

2019-11-18 07:01:23.464 T:967791472  DEBUG: http://192.168.143.10:8866/control?media...a9ad544aff

I am thinking it might be a slight delay when you move from the D to E drive but I need to check things out further

Unfortunately the server side logging from UI client looks extensive it doesn't log the useful information so this might not be trivial and I might need to add more logging in the client.

Martin

I have thought that it seems like often when it happens is when the playback has been idle for a while. So likely due to some sort of slower response time (probably due to a drive needing to spin up).

[mvallevand]

@Brettb in the latest 2.80 rc I did put in an extra debug line to see if it gives me any additional information.

Martin

[BrettB]

@Brettb in the latest 2.80 rc I did put in an extra debug line to see if it gives me any additional information.

Martin

Is that in the repository? I'm out of town until Sunday night for work and to visit my mom. So I probably won't have an opportunity to install and test that at home until after that.

EDIT: Nevermind. I just saw it in another thread.

[BrettB]

I just had this happen again this morning at 7:37. It was the first thing that I had tried to watch this morning. So I'm sure that the hard drive where the recording is stored had to be spun up. I immediately stopped the playback.

Then I spent a little time gathering logs, looking at them, etc. getting ready to post. And at 8:01, I started trying to play it again. And it did the same thing. I'm guessing the drive might have spun down again in the 20 minutes or so that nothing had been happening with it. This time, I stopped it and then immediately tried again (8:02) and it began playing fine. All of these should be in the kodi.log in this logs download:

Download Logs

Hopefully the additional logging you added in this version will help.

-Brett

[mvallevand]

I do see the scenario.

Code:

2019-12-07 07:37:54.512 T:1291793264   DEBUG: {u'recording_title': u'NCIS: Los Angeles', u'recording_descri
...
2019-12-07 07:38:03.503 T:1275007856   DEBUG: Stop state
2019-12-07 07:38:03.503 T:1275007856   DEBUG: 2
2019-12-07 07:38:03.504 T:1275007856   DEBUG: http://192.168.143.10:8866/control?media=stop

and it look like it is time based since that is 3.5 seconds before video starts streaming (that NextPVR doesn't know about)

I have to figure out if it is better to abandon the playback and tell Kodi to stop playing the file too, or try and wait for Kodi. I am a bit worried that after 13 seconds of black screen you might start clicking keys out of frustration.

Martin

[mvallevand]

I think I need to work on the state machine a little bit more I have started the player but because of startup delays it looks like the player is reporting it is not playing video after initially reporting it was I will probably need more logging to confirm that.

Martin

[BrettB]

I think I need to work on the state machine a little bit more I have started the player but because of startup delays it looks like the player is reporting it is not playing video after initially reporting it was I will probably need more logging to confirm that.

Martin

Doe "...I will probably need more logging to confirm that." mean more samples from me when it happens or that you need me to run a different version which does more logging?

[mvallevand]

Primarily for me I have to see what states of true and false I need to expect. Right now it doesn't expect a reset but it is possible I am not turning something off.

Martin