MP2 - V2.1 [MP2-558] 2.1pre Error in SlimTV3 (1 Viewer)

[MrTechno]

MediaPortal.Plugins.SlimTv.Service.SlimTvService.GetProgramsGroup(IChannelGroup channelGroup, DateTime from, DateTime to, IList`1& programs) in C:\Users\Michael\OneDrive\MediaPortal\MrTechno.FEAT_MIA_Rework_v2_WifiRemoteForMP2\MediaPortal\Source\UI\TV\SlimTvService3\SlimTvService3.cs:line 371
   at MediaPortal.Plugins.SlimTv.Service.UPnP.SlimTvServiceImpl.OnGetProgramsGroup(DvAction action, IList`1 inParams, IList`1& outParams, CallContext context) in C:\Users\Michael\OneDrive\MediaPortal\MrTechno.FEAT_MIA_Rework_v2_WifiRemoteForMP2\MediaPortal\Source\UI\TV\SlimTvService\UPnP\SlimTvServiceImpl.cs:line 488
   at UPnP.Infrastructure.Dv.DeviceTree.DvAction.FireActionInvoked(IList`1 inParams, IList`1& outParams, CallContext context) in c:\Users\Michael\OneDrive\MediaPortal\MrTechno.FEAT_MIA_Rework_v2_WifiRemoteForMP2\MediaPortal\Source\Core\UPnP\Infrastructure\Dv\DeviceTree\DvAction.cs:line 146
   at UPnP.Infrastructure.Dv.DeviceTree.DvAction.InvokeAction(IList`1 inParameters, IList`1& outParameters, Boolean checkSignature, CallContext context) in c:\Users\Michael\OneDrive\MediaPortal\MrTechno.FEAT_MIA_Rework_v2_WifiRemoteForMP2\MediaPortal\Source\Core\UPnP\Infrastructure\Dv\DeviceTree\DvAction.cs:line 129
   at UPnP.Infrastructure.Dv.SOAP.SOAPHandler.HandleRequest(DvService service, Stream messageStream, Encoding streamEncoding, Boolean subscriberSupportsUPnP11, CallContext context, String& result) in c:\Users\Michael\OneDrive\MediaPortal\MrTechno.FEAT_MIA_Rework_v2_WifiRemoteForMP2\MediaPortal\Source\Core\UPnP\Infrastructure\Dv\SOAP\SOAPHandler.cs:line 155

 

[MrTechno]

Found the real problem:

[2017-01-02 10:02:04,703] [10467  ] [15       ] [INFO ] - SlimTvService: Timeout waiting for running system state.

and tracked it down to AbstractSlimTvService::InitAsync

if (await Task.WhenAny(task, Task.Delay(10000)) != task || task.Result == false)

Looks like ten seconds is not long enough for MP2-Server to get up and running. It's intermittent though so sometimes it is long enough. I'll open a JIRA.

 

[HTPCSourcer]

Would it be better to wait until the TVServer is really becoming available rather than having a fixed time? I would think that the server service is somehow signaling that it's online. In any case a polling cycle with a configurable timeout (e.g. 60 sec) would also do the job.

 

[MrTechno]

Would it be better to wait until the TVServer is really becoming available rather than having a fixed time?

That's pretty much what it does. The max wait in is hard coded at 10 seconds, you only get one chance to initialised, the log level in the event of a timeout is at INFO and SlimTV provider is then in a weird limbo state where it's registered for use but it's actually ready.

 

[morpheus_xx]

That's pretty much what it does. The max wait in is hard coded at 10 seconds, you only get one chance to initialised, the log level in the event of a timeout is at INFO and SlimTV provider is then in a weird limbo state where it's registered for use but it's actually ready.

Not sure if I have implemented it this way, but it's not the best way.

Other plugin are listening for system state messages and then continue their initialization. Could you change please this in SlimTv well?

Edit:
found a change by @henso here: https://github.com/MediaPortal/MediaPortal-2/commit/5426ced9b946f0e6eb234e867757dadbeafc5f56

 

[MrTechno]

@henso 's change makes it better but there's still the possibility of a timeout. I had a large PendingResourcesSettings XML file at the time because I stopped the server during an import, maybe that's what took the extra time to initialise? If I make the timeout 30 seconds and change the logging to ERROR level it will start to show up in OTE.

 

[morpheus_xx]

change makes it better but there's still the possibility of a timeout

Not exactly:
Before the timer checked in 500ms interval for an available DB without timeout. So the service was available whenever the rest of system is "ready".

The change improves the shutdown handling during crash/initialization phase, but I'm not happy how it looks now.

 

[MrTechno]

I'm not happy how it looks now.

What would you like the fix to be? I got it working on my machine by changing the timeout:

if (await Task.WhenAny(task, Task.Delay(30000)) != task || task.Result == false)

 

[morpheus_xx]

What would you like the fix to be? I got it working on my machine by changing the timeout:

I think it should look like:

• Subscribe for SystemState messages: act on SystemState.Running / ShutDown, one example: https://github.com/MediaPortal/Medi...nPRenderer/UPnP/UPnPRendererPlugin.cs#L84-L94 (there are more plugins doing this already, maybe this could be in a helper class or service?)
  
• When SystemState.Running arrives, start the init background thread
• Having a "abort" field, either as bool or ResetEvent, that can be used to signal shutdown request during init phase and check this for signalled state

One thing I'm not sure about:
I could have checked for "SystemState.Running" before, but as this code depends on a registered database service, the "SystemState.Running" might be too early, as plugins are possibly enabled in another order (have not checked code). So the initial check for database service was maybe better for the purpose.

 

[MrTechno]

Created https://github.com/MediaPortal/MediaPortal-2/tree/FIX_MP2-558_Error_in_SlimTV3 for this.

Subscription works but now there's a different problem:

[2017-01-03 14:20:45,716] [227686 ] [69       ] [ERROR] - Error: UPnPServer: Error handling HTTP request 'http://127.0.0.1:61622/upnphost/description/uuid:ecc068a5-581c-4312-95d2-211e83d86c18'
[2017-01-03 14:20:45,727] [227697 ] [69       ] [ERROR] - Error: UPnPServer: Exception is The given key was not present in the dictionary.:
   at System.Collections.Generic.Dictionary`2.get_Item(TKey key)
   at UPnP.Infrastructure.Dv.DeviceTree.DvService.AddDeviceDescriptionForService(XmlWriter writer, EndpointConfiguration config) in C:\Users\Michael\OneDrive\MediaPortal\MrTechno.FEAT_MP2.1_DLNA\MediaPortal\Source\Core\UPnP\Infrastructure\Dv\DeviceTree\DvService.cs:line 276
   at UPnP.Infrastructure.Dv.DeviceTree.DvDevice.AddDeviceDescriptionsRecursive(IHttpRequest request, XmlWriter writer, EndpointConfiguration config, CultureInfo culture) in C:\Users\Michael\OneDrive\MediaPortal\MrTechno.FEAT_MP2.1_DLNA\MediaPortal\Source\Core\UPnP\Infrastructure\Dv\DeviceTree\DvDevice.cs:line 396
   at UPnP.Infrastructure.Dv.DeviceTree.DvDevice.BuildRootDeviceDescription(IHttpRequest request, ServerData serverData, EndpointConfiguration config, CultureInfo culture) in C:\Users\Michael\OneDrive\MediaPortal\MrTechno.FEAT_MP2.1_DLNA\MediaPortal\Source\Core\UPnP\Infrastructure\Dv\DeviceTree\DvDevice.cs:line 310
   at UPnP.Infrastructure.Dv.UPnPServer.HandleHTTPRequest_NoLock(IHttpClientContext context, IHttpRequest request) in C:\Users\Michael\OneDrive\MediaPortal\MrTechno.FEAT_MP2.1_DLNA\MediaPortal\Source\Core\UPnP\Infrastructure\Dv\UPnPServer.cs:line 332

Adding the TV service used to happen during activation, now it happens after running state at which point it's too late.