[Usability] Restart on resume (3 Viewers)

[The_Stig]

As I have a blocked MP from version 1.7 on after a resume from standby unregularly, I will try to provide logs too, when I run into this problem again.

For the last days I have changed the wait time for MP after a resume to 10 seconds and haven't seen this problem anymore for quite a few days. So maybe indeed a plugin problem?!?

 

[Requiem]

@HomeY @mm1352000 These are the logs with MPSync disabled.
MP was frozen after resume.
Only thiing is that my 1 yeaar old daughter caught the remote control and switched on the HTPC withput switching on the TV and I got a displayport arror which I usually never get, so please ignore any errors related to that. If this makes the logs invalid I'll reproduce this with my remote in a safer place ;-)

@The_Stig Okay, I have increased wait time after resume from 5 to 10 seconds and see what happens.

 

[The_Stig]

MP was frozen after resume.

Didn't look at your logs, but please provide us with the relevant times, when did HTPC go to standby and when was the resume? Should make things easier to spot.

 

[mm1352000]

Could you get much more complicated?!?
HDMI + AudioSwitcher + multi-seat + auto-start TV + IFC + refresh rate changing... very complex.
Nothing stands out immediately, except this:
[2014-06-11 10:58:09,421] [Log ] [MPMain ] [INFO ] - CycleRefreshRate: unable to change refresh rate 50Hz for monitor 0
...and I'm not sure that could cause a freeze. There is so much room for things to go wrong. My suggestion would be to simplify to basics. Assuming HDMI + no AudioSwitcher + no auto-start + IFC disabled + refresh rate changing disabled works, you could enable them one by one to find the problem. If even the basic configuration causes problems then at least we will have simpler logs to work with.

[edit: Spoke too soon. There are a bunch of playback issues in the TsReader log...]

 

[Requiem]

MP was frozen after resume.

Didn't look at your logs, but please provide us with the relevant times, when did HTPC go to standby and when was the resume? Should make things easier to spot.

Standby was at 22:07 yesterday evening, resume on 10:57 today.

Could you get much more complicated?!?
HDMI + AudioSwitcher + multi-seat + auto-start TV + IFC + refresh rate changing... very complex.

Yes, indeed, but everything is needed :-P Sure there are simpler setups than mine.
Maybe this makes clear why I favor to have a restart oin resume ;-)

Nothing stands out immediately, except this:
[2014-06-11 10:58:09,421] [Log ] [MPMain ] [INFO ] - CycleRefreshRate: unable to change refresh rate 50Hz for monitor 0

Might be due the TV being switched off,a s I said, my daughter switched it on. I am gathering new logs with MPSync enabled at the moment.

As for error hunt, yes, I can disable options and switch them on again one by one.
I am seeing issues after resume in tsreader.log, yesterday evening everything seemed to be fine.
Maybe reinitialisation of the server really takes longer than 5 seconds to come available, so if this was the case, the startup delay increase should show an effect.

 

[mm1352000]

Yes, indeed, but everything is needed :-P

Sure, fine - I'm not saying you can't use them... but for now disabling them will make debugging a lot easier.

Maybe reinitialisation of the server really takes longer than 5 seconds to come available, so if this was the case, the startup delay increase should show an effect.

Without the server logs its impossible to be sure ... but at least it looked like timeshifting started successfully.

 

[Requiem]

Yes, indeed, but everything is needed :-P

Sure, fine - I'm not saying you can't use them... but for now disabling them will make debugging a lot easier.

Oh, I didnt mean to say that I am not willing to disable everything to track down issues. I just meant that in the end, I'd be glad if everything worked with everything enabled. And I am really thankful for your time and effort in helping me.

Okay, new logs. What has changed?
1. Resume delay upo to 10 from 5 seconds
2. MPSync reenabled
3. this time, everýthing switched on properly andf not by my daughter

Behaviour: Went to standby when running live TV. On resume, took notably longer to come back, than it came back with audio only live TV running and a black screen. Was able to exit with ALt+F4. Logs attached.
I have deleted my old (lenghty) server logs and will attach server logs in future posts.

I will now run a third watchdog round and disable all plugins/options mentioned by you,

edit: i cannot switch off HDMI, this is my only connection from HTPC to audio and TV output.
So I disabled: FritzBox plugin, MPsync, Dynamic Refrash Rate and IFC and switched the audio device from WASAPI to BASS player (this is what you meant by audio changer?)

 

[mm1352000]

Hmmmm, in both of these sets of logs I've seen something odd in the TsReader log. It is like PMT is received and streaming should start... but then the RTSP session is torn down... but it looks like streaming carries on anyway. I'm not so experienced with multi-seat setups so I'm not sure whether it is normal, but it doesn't look normal to me.

Just out of interest, have you ever tried UNC paths instead of RTSP (and if so what was the result)?

 

[HomeY]

@Requiem Just to be clear: Does the freeze happen directly after you resume from S3?

I've looked @ the first logset. It seems the system was suspended last night @ 22:07

[2014-06-10 22:07:42,188] [Log    ] [MPMain   ] [INFO ] - Main: OnSuspend - Done

And resumed this morning @ 10:57

[2014-06-11 10:57:06,482] [Log    ] [MPMain   ] [DEBUG] - Main: WM_DEVICECHANGE (Event: DBT_DEVICEARRIVAL)
[2014-06-11 10:57:06,496] [Log    ] [MPMain   ] [DEBUG] - Main: Device type is DBT_DEVTYP_DEVICEINTERFACE - Name: Realtek PCIe GBE Family Controller

Which was finished about 30 seconds later:

[2014-06-11 10:57:37,915] [Log    ] [MPMain   ] [INFO ] - Main: OnResumeAutomatic - Done

I see a 20 seconds delay at this point:

[2014-06-11 10:57:10,477] [Log    ] [MPMain   ] [DEBUG] - Window: TvPlugin.TvFullScreen init
[2014-06-11 10:57:10,487] [Log    ] [MPMain   ] [DEBUG] - TvFullScreen:init->OSD:Off
[2014-06-11 10:57:31,507] [Log    ] [MPMain   ] [DEBUG] - TvFullScreen: init, playing False, player.CurrentFile , TVHome.Card.TimeShiftFileName .tsbuffer

So when examining the logs after the 'OnResumeAutomatic - Done' part, the Fritz!BoxManager plugin gets started, and then this weird timestamp shows up:

[2014-06-11 10:57:54,141] [Log    ] [8        ] [DEBUG] - FRITZ!Box Manager: BackGroundWorker: Running refresh view task
[2014-06-11 10:57:37,944] [Log    ] [MPMain   ] [DEBUG] - Main: WM_POWERBROADCAST (PBT_APMRESUMESUSPEND)
[2014-06-11 10:58:00,221] [Log    ] [MPMain   ] [INFO ] - Main: OnResume - Switch to basic home screen

I've seen a 30 seconds delay in the reconnection:

[2014-06-11 10:58:22,140] [Log    ] [43       ] [INFO ] - FRITZ!Box Manager: FritzBox: Waiting 30 seconds before reconnecting
[2014-06-11 10:58:52,151] [Log    ] [43       ] [INFO ] - FRITZ!Box Manager: FritzBox: Connecting

And if this is a treading issue, that could explain the freeze. So besides the issues that mm spotted, i would suggest to disable the Fritz!Box Manager plugin first, and test again.

 

[HomeY]

Now the 2nd logs (MediaPortalLogs_11_06_14__12_29). The MediaPortal-Error.log already gives some hints on potential causes, which are the MPSync plugin:

[2014-06-11 11:16:15,292] [Error  ] [5        ] [ERROR] - MPSync: [Createtable] CREATE TABLE Image (Id TEXT PRIMARY KEY, Category TEXT, Provider TEXT, Key1 TEXT, Key2 TEXT, FullPath TEXT, SourcePath TEXT, AvailableRandom TEXT, Enabled TEXT, DummyItem TEXT, Time_Stamp TEXT) error with exception: database disk image is malformed
database disk image is malformed
[2014-06-11 11:16:15,354] [Error  ] [5        ] [ERROR] - MPSync: [Createtable] CREATE TABLE Version (Id INTEGER PRIMARY KEY, Version TEXT, Time_Stamp TEXT) error with exception: database disk image is malformed
database disk image is malformed
[2014-06-11 11:16:15,401] [Error  ] [5        ] [ERROR] - MPSync: [Createtable] CREATE TABLE mpsync_trigger (id INTEGER PRIMARY KEY AUTOINCREMENT, tablename TEXT, lastupdated TEXT) error with exception: database disk image is malformed
database disk image is malformed

And the Fritz!Box Manager:

[2014-06-11 11:16:28,739] [Error  ] [10       ] [ERROR] - FRITZ!Box Manager: FritzBox: Receiving callback failed: Object Disposed Exeption
[2014-06-11 12:17:55,489] [Error  ] [16       ] [ERROR] - FRITZ!Box Manager: FritzBox: Connecting failed: FRITZ!Box DNS name could not be resolved
[2014-06-11 12:27:52,025] [Error  ] [54       ] [ERROR] - FRITZ!Box Manager: FritzBox: Connecting failed: FRITZ!Box DNS name could not be resolved

In general, suspended @ 12:17:

[2014-06-11 12:17:31,695] [Log    ] [MPMain   ] [INFO ] - Main: OnSuspend - Done

and resumed about 10 minutes later @ 12:27:

[2014-06-11 12:27:47,514] [Log    ] [54       ] [INFO ] - FRITZ!Box Manager: FritzBox: Connecting

And done resuming @ 12:28:

[2014-06-11 12:28:20,024] [Log    ] [MPMain   ] [INFO ] - Main: OnResumeAutomatic - Done

Now let's look @ the delays that are there.

[2014-06-11 12:27:52,025] [Error  ] [54       ] [ERROR] - FRITZ!Box Manager: FritzBox: Connecting failed: FRITZ!Box DNS name could not be resolved
[2014-06-11 12:27:52,033] [Log    ] [52       ] [INFO ] - FRITZ!Box Manager: FritzBox: Waiting 29 seconds before reconnecting
[2014-06-11 12:28:10,003] [Log    ] [MPMain   ] [DEBUG] - Main: WM_POWERBROADCAST (PBT_APMRESUMEAUTOMATIC)

So again the Fritz!Box Manager failed to connect and waits 30 seconds. If you can confirm that the system was completely unresponsive during this time, this also points towards a threading issue with the plugin.
Off course the 10 seconds wait time (which you set) is in there:

[2014-06-11 12:28:10,011] [Log    ] [MPMain   ] [INFO ] - Main: OnResumeAutomatic - waiting on resume 10 secs
[2014-06-11 12:28:20,014] [Log    ] [MPMain   ] [DEBUG] - Main: OnResumeAutomatic - reopen Database

And about 18 seconds later the TV Stream is started:

[2014-06-11 12:28:38,231] [Log    ] [MPMain   ] [INFO ] - g_Player.OnStarted() rtsp://SERVER:554/stream3.0 media:TV

Overall this doesn't look that bad. From the first log entry after resume @ 12:27:52, till the TV stream was started @ 12:28:38 there are about 48 seconds. 10 seconds are defined wait time, so means it takes 38 seconds from the time you resume the system, till the TV stream isn't started.

Now i'm very curious about the test results from the WatchDog option #1. You don't need to manually disable the plugin, just start the WatchDog, select option 1 and put the system into standby as you always do.

Are you putting the system into standby with the remote button? And do you do so while LiveTV is still running?