[Usability] Restart on resume (3 Viewers)

The_Stig

Retired Team Member
  • Premium Supporter
  • April 5, 2005
    2,176
    428
    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

    MP Donator
  • Premium Supporter
  • January 1, 2012
    588
    216
    Home Country
    Germany Germany
    @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.
     

    mm1352000

    Retired Team Member
  • Premium Supporter
  • September 1, 2008
    21,577
    8,224
    Home Country
    New Zealand New Zealand
    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 Donator
  • Premium Supporter
  • January 1, 2012
    588
    216
    Home Country
    Germany Germany
    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

    Retired Team Member
  • Premium Supporter
  • September 1, 2008
    21,577
    8,224
    Home Country
    New Zealand New Zealand
    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

    MP Donator
  • Premium Supporter
  • January 1, 2012
    588
    216
    Home Country
    Germany Germany
    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?)
     
    Last edited:

    mm1352000

    Retired Team Member
  • Premium Supporter
  • September 1, 2008
    21,577
    8,224
    Home Country
    New Zealand New Zealand
    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

    Test Group
  • Team MediaPortal
  • February 23, 2008
    6,475
    4,645
    49
    ::1
    Home Country
    Netherlands Netherlands
    @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
    Code:
    [2014-06-10 22:07:42,188] [Log    ] [MPMain   ] [INFO ] - Main: OnSuspend - Done
    And resumed this morning @ 10:57
    Code:
    [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:
    Code:
    [2014-06-11 10:57:37,915] [Log    ] [MPMain   ] [INFO ] - Main: OnResumeAutomatic - Done

    I see a 20 seconds delay at this point:
    Code:
    [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:
    Code:
    [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:
    Code:
    [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

    Test Group
  • Team MediaPortal
  • February 23, 2008
    6,475
    4,645
    49
    ::1
    Home Country
    Netherlands Netherlands
    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:
    Code:
    [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:
    Code:
    [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:
    Code:
    [2014-06-11 12:17:31,695] [Log    ] [MPMain   ] [INFO ] - Main: OnSuspend - Done
    and resumed about 10 minutes later @ 12:27:
    Code:
    [2014-06-11 12:27:47,514] [Log    ] [54       ] [INFO ] - FRITZ!Box Manager: FritzBox: Connecting
    And done resuming @ 12:28:
    Code:
    [2014-06-11 12:28:20,024] [Log    ] [MPMain   ] [INFO ] - Main: OnResumeAutomatic - Done

    Now let's look @ the delays that are there.
    Code:
    [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:
    Code:
    [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:
    Code:
    [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?
     

    Users who are viewing this thread

    Top Bottom