[Usability] - Restart on resume | Page 2

Discussion in 'Improvement Suggestions' started by Requiem, June 4, 2014.

  1. The_Stig
    • Premium Supporter

    The_Stig Retired Team Member

    Joined:
    April 5, 2005
    Messages:
    2,176
    Likes Received:
    288
    Ratings:
    +426 / 5
    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?!?


     
    • Thank You! Thank You! x 1
  2. Google AdSense Guest Advertisement



    to hide all adverts.
  3. Requiem
    • Premium Supporter

    Requiem MP Donator

    Joined:
    January 1, 2012
    Messages:
    585
    Likes Received:
    80
    Gender:
    Male
    Ratings:
    +174 / 2
    Home Country:
    Germany Germany
    Show System Specs
    @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.
     
    • Thank You! Thank You! x 2
  4. The_Stig
    • Premium Supporter

    The_Stig Retired Team Member

    Joined:
    April 5, 2005
    Messages:
    2,176
    Likes Received:
    288
    Ratings:
    +426 / 5
    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.
     
  5. mm1352000
    • Team MediaPortal

    mm1352000 Development Group

    Joined:
    September 1, 2008
    Messages:
    21,541
    Likes Received:
    4,752
    Ratings:
    +8,221 / 17
    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...]
     
  6. Requiem
    • Premium Supporter

    Requiem MP Donator

    Joined:
    January 1, 2012
    Messages:
    585
    Likes Received:
    80
    Gender:
    Male
    Ratings:
    +174 / 2
    Home Country:
    Germany Germany
    Show System Specs
    Standby was at 22:07 yesterday evening, resume on 10:57 today.

    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 ;-)


    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.
     
  7. mm1352000
    • Team MediaPortal

    mm1352000 Development Group

    Joined:
    September 1, 2008
    Messages:
    21,541
    Likes Received:
    4,752
    Ratings:
    +8,221 / 17
    Home Country:
    New Zealand New Zealand
    Sure, fine - I'm not saying you can't use them... but for now disabling them will make debugging a lot easier.

    Without the server logs its impossible to be sure ;) ... but at least it looked like timeshifting started successfully.
     
  8. Requiem
    • Premium Supporter

    Requiem MP Donator

    Joined:
    January 1, 2012
    Messages:
    585
    Likes Received:
    80
    Gender:
    Male
    Ratings:
    +174 / 2
    Home Country:
    Germany Germany
    Show System Specs
    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: June 11, 2014
  9. mm1352000
    • Team MediaPortal

    mm1352000 Development Group

    Joined:
    September 1, 2008
    Messages:
    21,541
    Likes Received:
    4,752
    Ratings:
    +8,221 / 17
    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)?
     
    • Like Like x 1
  10. HomeY
    • Team MediaPortal

    HomeY Test Group

    Joined:
    February 23, 2008
    Messages:
    6,460
    Likes Received:
    2,627
    Gender:
    Male
    Occupation:
    Network Engineer
    Location:
    ::1
    Ratings:
    +4,737 / 16
    Home Country:
    Netherlands Netherlands
    Show System Specs
    @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 (Text):
    1. [2014-06-10 22:07:42,188] [Log    ] [MPMain   ] [INFO ] - Main: OnSuspend - Done
    And resumed this morning @ 10:57
    Code (Text):
    1. [2014-06-11 10:57:06,482] [Log    ] [MPMain   ] [DEBUG] - Main: WM_DEVICECHANGE (Event: DBT_DEVICEARRIVAL)
    2. [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 (Text):
    1. [2014-06-11 10:57:37,915] [Log    ] [MPMain   ] [INFO ] - Main: OnResumeAutomatic - Done
    I see a 20 seconds delay at this point:
    Code (Text):
    1. [2014-06-11 10:57:10,477] [Log    ] [MPMain   ] [DEBUG] - Window: TvPlugin.TvFullScreen init
    2. [2014-06-11 10:57:10,487] [Log    ] [MPMain   ] [DEBUG] - TvFullScreen:init->OSD:Off
    3. [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 (Text):
    1. [2014-06-11 10:57:54,141] [Log    ] [8        ] [DEBUG] - FRITZ!Box Manager: BackGroundWorker: Running refresh view task
    2. [2014-06-11 10:57:37,944] [Log    ] [MPMain   ] [DEBUG] - Main: WM_POWERBROADCAST (PBT_APMRESUMESUSPEND)
    3. [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 (Text):
    1. [2014-06-11 10:58:22,140] [Log    ] [43       ] [INFO ] - FRITZ!Box Manager: FritzBox: Waiting 30 seconds before reconnecting
    2. [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.
     
    • Like Like x 3
  11. HomeY
    • Team MediaPortal

    HomeY Test Group

    Joined:
    February 23, 2008
    Messages:
    6,460
    Likes Received:
    2,627
    Gender:
    Male
    Occupation:
    Network Engineer
    Location:
    ::1
    Ratings:
    +4,737 / 16
    Home Country:
    Netherlands Netherlands
    Show System Specs
    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 (Text):
    1. [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
    2. database disk image is malformed
    3. [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
    4. database disk image is malformed
    5. [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
    6. database disk image is malformed
    And the Fritz!Box Manager:
    Code (Text):
    1. [2014-06-11 11:16:28,739] [Error  ] [10       ] [ERROR] - FRITZ!Box Manager: FritzBox: Receiving callback failed: Object Disposed Exeption
    2. [2014-06-11 12:17:55,489] [Error  ] [16       ] [ERROR] - FRITZ!Box Manager: FritzBox: Connecting failed: FRITZ!Box DNS name could not be resolved
    3. [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 (Text):
    1. [2014-06-11 12:17:31,695] [Log    ] [MPMain   ] [INFO ] - Main: OnSuspend - Done
    and resumed about 10 minutes later @ 12:27:
    Code (Text):
    1. [2014-06-11 12:27:47,514] [Log    ] [54       ] [INFO ] - FRITZ!Box Manager: FritzBox: Connecting
    And done resuming @ 12:28:
    Code (Text):
    1. [2014-06-11 12:28:20,024] [Log    ] [MPMain   ] [INFO ] - Main: OnResumeAutomatic - Done
    Now let's look @ the delays that are there.
    Code (Text):
    1. [2014-06-11 12:27:52,025] [Error  ] [54       ] [ERROR] - FRITZ!Box Manager: FritzBox: Connecting failed: FRITZ!Box DNS name could not be resolved
    2. [2014-06-11 12:27:52,033] [Log    ] [52       ] [INFO ] - FRITZ!Box Manager: FritzBox: Waiting 29 seconds before reconnecting
    3. [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 (Text):
    1. [2014-06-11 12:28:10,011] [Log    ] [MPMain   ] [INFO ] - Main: OnResumeAutomatic - waiting on resume 10 secs
    2. [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 (Text):
    1. [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?
     
    • Like Like x 3
Loading...

Users Viewing Thread (Users: 0, Guests: 0)

  1. This site uses cookies to help personalise content, tailor your experience and to keep you logged in if you register.
    By continuing to use this site, you are consenting to our use of cookies.
    Dismiss Notice
  • About The Project

    The vision of the MediaPortal project is to create a free open source media centre application, which supports all advanced media centre functions, and is accessible to all Windows users.

    In reaching this goal we are working every day to make sure our software is one of the best.

             

  • Support MediaPortal!

    The team works very hard to make sure the community is running the best HTPC-software. We give away MediaPortal for free but hosting and software is not for us.

    Care to support our work with a few bucks? We'd really appreciate it!