Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Timer in VDR with VPS enabled leads to annoying Reminders in Kodi 19 #162

Closed
nd2000 opened this issue Dec 12, 2021 · 44 comments
Closed

Timer in VDR with VPS enabled leads to annoying Reminders in Kodi 19 #162

nd2000 opened this issue Dec 12, 2021 · 44 comments

Comments

@nd2000
Copy link

nd2000 commented Dec 12, 2021

Steps to reproduce:

  • Create a timer in VDR with VPS enabled
  • Start Kodi

Now Kodi 19 has a timer of type "Reminder" that will pop up before the start.
There is no chance to disable the reminder.

Up to Kodi 18 the timer was of type "VPS" without annoying reminder.

@phunkyfish
Copy link
Member

phunkyfish commented Dec 12, 2021

Please supply a full debug log and can take a look.

Also screenshots please.

@AlwinEsch @ksooo i don’t see any obvious reason from the addon code why this happens.

@nd2000
Copy link
Author

nd2000 commented Dec 12, 2021

OK, lets create a timer in VDR Live with VPS enabled (sorry for German locale)
grafik

Now, VDR timer is created
grafik

Lets start kodi and go to TV Timer overview, a new reminder is created
grafik

Detail view of reminder
grafik

Logfile (kodi.log): https://paste.kodi.tv/uluqezecur.kodi

@phunkyfish
Copy link
Member

Thanks. Could you move the debug log to a paste site like paste.kodi.tv? Then it’s easier to access/read and doesn’t clutter the issue.

@nd2000
Copy link
Author

nd2000 commented Dec 12, 2021

@phunkyfish
Copy link
Member

Also, this is an INFO log and not a DEBUG log.

Try following: https://kodi.wiki/view/Log_file/Easy

@nd2000
Copy link
Author

nd2000 commented Dec 12, 2021

Also, this is an INFO log and not a DEBUG log.

Try following: https://kodi.wiki/view/Log_file/Easy

Really?
Settings > System Settings > Logging > Enable debug logging is set to true.

Wait, let me enable "Enable component-specific logging"...

@nd2000
Copy link
Author

nd2000 commented Dec 12, 2021

@phunkyfish
Copy link
Member

phunkyfish commented Dec 12, 2021

Ok, I wonder is there something going wrong or missing under hood. We moved from a C API to a C++ API in Kodi 19 and there could be a subtle issue causing this.

I found this error in your log:

2021-12-12 14:29:31.279 T:22648   ERROR <general>: AddOnLog: pvr.vdr.vnsi: ReadResult - request timed out after 3 seconds
2021-12-12 14:29:31.279 T:22648   ERROR <general>: AddOnLog: pvr.vdr.vnsi: GetTimerTypes - Can't get response packed
2021-12-12 14:29:31.281 T:22639    INFO <general>: PVR Manager: Starting

But I see similar errors for many of the Kodi API calls.

@AlwinEsch any ideas what’s happening?

@micclass62
Copy link

Any news on this one? I do see the very annoying pop-ups in Kodi for all my timers in vdr (which all do use VPS) since Kodi 19 too. Anything I could to to help?

@phunkyfish
Copy link
Member

Can you explain what VPS is?

@nd2000
Copy link
Author

nd2000 commented Jan 7, 2022

@phunkyfish
Copy link
Member

I wonder if for some reason the VPS timer is not being created. Or that the VDR protocol version is somehow being reported incorrectly causing the timer types to not be created (

if (GetProtocol() >= 9)
).

@micclass62
Copy link

micclass62 commented Jan 8, 2022

Indeed, I do find something fishy in the kodi.log:
2022-01-08 09:01:49.005 T:6460 INFO <general>: AddOnLog: pvr.vdr.vnsi: SupportRecordingsUndelete - Undelete not supported on backend (min. Ver. 1.3.0; Protocol 7)

but:
INFO <general>: AddOnLog: pvr.vdr.vnsi: Logged in at '1641630716+3600' to 'VDR-Network-Streaming-Interface (VNSI) Server' Version: '1.8.0' with protocol version '13'

I do use the vnsiserver Plugin from the following GIT repository https://github.com/mdre77/vdr-plugin-vnsiserver
which has
/** Current VNSI Protocol Version number */
#define VNSI_PROTOCOLVERSION 13
in vnsicommand.h.

@phunkyfish
Copy link
Member

Ok, I think we are getting closer to the problem. Unfortunately I don’t have a VDR setup so can’t debug.

@AlwinEsch is this something you could check?

@micclass62
Copy link

There seems to be a more general communication issue between the kodi plugin and the vnsiserver on vdr side when the plugins starts up: (the same sequence even happens if I do run the vdr instance on the same computer as kodi and access to plugin via 127.0.0.1) There is a sginificant delay when the plugin starts.

ERROR : AddOnLog: pvr.vdr.vnsi: SupportChannelScan - Can't get response packed
INFO : AddOnLog: pvr.vdr.vnsi: SupportRecordingsUndelete - Undelete not supported on backend (min. Ver. 1.3.0; Protocol 7)
INFO : AddOnLog: pvr.vdr.vnsi: Logged in at '1641634029+3600' to 'VDR-Network-Streaming-Interface (VNSI) Server' Version: '1.8.0' with protocol version '13'
INFO : Loading skin file: MyPVRChannels.xml, load type: KEEP_IN_MEMORY
ERROR : AddOnLog: pvr.vdr.vnsi: ReadResult - request timed out after 3 seconds
ERROR : AddOnLog: pvr.vdr.vnsi: SupportChannelScan - Can't get response packed
INFO : CPythonInvoker(0, /home/michaelc/.kodi/addons/service.xbmc.versioncheck/resources/lib/runner.py): script successfully run
INFO : Python interpreter stopped
ERROR : AddOnLog: pvr.vdr.vnsi: ReadResult - request timed out after 3 seconds
INFO : AddOnLog: pvr.vdr.vnsi: SupportRecordingsUndelete - Can't get response packed
ERROR : AddOnLog: pvr.vdr.vnsi: ReadResult - request timed out after 3 seconds
ERROR : AddOnLog: pvr.vdr.vnsi: GetTimerTypes - Can't get response packed
INFO : PVR Manager: Starting
ERROR : GetChannelGroupMembers: Add-on 'VDR-Network-Streaming-Interface (VNSI) Server:vdr02.mchome.dom:34890' returned an error: server error
ERROR : GetChannelGroupMembers: PVR client 'VDR-Network-Streaming-Interface (VNSI) Server:vdr02.mchome.dom:34890' returned an error: server error
ERROR : GetChannelGroups: Add-on 'VDR-Network-Streaming-Interface (VNSI) Server:vdr02.mchome.dom:34890' returned an error: server error
ERROR : GetChannelGroups: PVR client 'VDR-Network-Streaming-Interface (VNSI) Server:vdr02.mchome.dom:34890' returned an error: server error
INFO : PVR Manager: Started

There are no corresponding errors in the log of the vdr!

But from then on things look good (and almost everything is working - live tv, playing of records, timers created via kodi and timers created via vdr ). Would there be a way to create a VPS timer via Kodi? I do not see anything like that in Kodi.

@phunkyfish
Copy link
Member

If the kodi addon understood the capabilities of the VDR backend then it should have VPS timers available. The fact it does not means that something is going wrong initially which is what needs fixing.

@micclass62
Copy link

micclass62 commented Jan 8, 2022

O.k. I see. And am fully agreeing. As a test I did comment out that

if (GetProtocol() >= 9)

test in ClientInstance.cpp in CVNSIClientInstance::GetTimerTypes. And now the Timers are handled correctly. So the initial failing calls must be fixed ... unfortunately my C++ capabilites are somewhat limited ... but I do have a working setup with the ability to build the kodi plugin as well as the vdr side quite easily for testing if that would help.

@phunkyfish
Copy link
Member

phunkyfish commented Jan 8, 2022

Can you search your log for SupportRecordingsUndelete. I think that the add-on is querying the version after it tries to use it, and therefor it fails.

I can add a PR with some logging if you can try it out.

#173

@micclass62
Copy link

Result:

2022-01-08 12:32:05.816 T:36245 ERROR : AddOnLog: pvr.vdr.vnsi: ChannelScan - Can't get response packed
2022-01-08 12:32:05.816 T:36245 INFO : AddOnLog: pvr.vdr.vnsi: RecordingsUndelete - Undelete not supported on backend (min. Ver. 1.3.0; Protocol 7)
2022-01-08 12:32:05.821 T:36284 INFO : AddOnLog: pvr.vdr.vnsi: Logged in at '1641641520+3600' to 'VDR-Network-Streaming-Interface (VNSI) Server' Version: '1.8.0' with protocol version '13'
2022-01-08 12:32:06.601 T:36171 INFO : Loading skin file: MyPVRChannels.xml, load type: KEEP_IN_MEMORY
2022-01-08 12:32:08.821 T:36284 ERROR : AddOnLog: pvr.vdr.vnsi: ReadResult - request timed out after 3 seconds
2022-01-08 12:32:08.821 T:36284 ERROR : AddOnLog: pvr.vdr.vnsi: ChannelScan - Can't get response packed
2022-01-08 12:32:09.235 T:36253 INFO : CPythonInvoker(0, /home/michaelc/.kodi/addons/service.xbmc.versioncheck/resources/lib/runner.py): script successfully run
2022-01-08 12:32:09.240 T:36253 INFO : Python interpreter stopped
2022-01-08 12:32:11.821 T:36284 ERROR : AddOnLog: pvr.vdr.vnsi: ReadResult - request timed out after 3 seconds
2022-01-08 12:32:11.821 T:36284 INFO : AddOnLog: pvr.vdr.vnsi: RecordingsUndelete - Can't get response packed
2022-01-08 12:32:14.821 T:36284 ERROR : AddOnLog: pvr.vdr.vnsi: ReadResult - request timed out after 3 seconds
2022-01-08 12:32:14.822 T:36284 ERROR : AddOnLog: pvr.vdr.vnsi: GetTimerTypes - Can't get response packed
2022-01-08 12:32:14.823 T:36243 INFO : PVR Manager: Starting
2022-01-08 12:32:14.829 T:36286 ERROR : GetChannelGroupMembers: Add-on 'VDR-Network-Streaming-Interface (VNSI) Server:vdr02.mchome.dom:34890' returned an error: server error
2022-01-08 12:32:14.829 T:36286 ERROR : GetChannelGroupMembers: PVR client 'VDR-Network-Streaming-Interface (VNSI) Server:vdr02.mchome.dom:34890' returned an error: server error
2022-01-08 12:32:14.851 T:36286 ERROR : GetChannelGroups: Add-on 'VDR-Network-Streaming-Interface (VNSI) Server:vdr02.mchome.dom:34890' returned an error: server error
2022-01-08 12:32:14.851 T:36286 ERROR : GetChannelGroups: PVR client 'VDR-Network-Streaming-Interface (VNSI) Server:vdr02.mchome.dom:34890' returned an error: server error
2022-01-08 12:32:14.902 T:36286 INFO : PVR Manager: Started

@phunkyfish
Copy link
Member

Anything printing the protocol version?

@micclass62
Copy link

I added some code in front of the check:
bool CVNSIClientInstance::SupportRecordingsUndelete() { kodi::Log(ADDON_LOG_INFO, "%s - Protocol Version: %d", __func__, GetProtocol()); if (GetProtocol() > 7) {

The result is:
2022-01-08 13:25:28.842 T:38974 INFO : AddOnLog: pvr.vdr.vnsi: SupportRecordingsUndelete - Protocol Version: 0
2022-01-08 13:25:28.842 T:38974 INFO : AddOnLog: pvr.vdr.vnsi: SupportRecordingsUndelete - Undelete not supported on backend (min. Ver. 1.3.0; Protocol 7)

So Indeed, the GetProtocol Macro delivers a wrong number at the time the SupportRecordingsUndelete function is called. But later on it is correct. Is the session to vnsiserver handling in an extra thread???

@phunkyfish
Copy link
Member

Can you try the latest version of the PR: #173

I've tried to force a login before calling those functions.

@micclass62
Copy link

Compiles, but unfortunately makes kodi crashing during startup ...

@micclass62
Copy link

Here is definitely some race going on. After creation of the Instance via ADDON_STATUS CPVRAddon::CreateInstance the next what happens is already a CVNSIClientInstance::GetCapabilities call, before a cVNSISession::Login call happens. Thus the m_protocol is still at 0 at that point in time. Which makes some other calls to fail.

@phunkyfish
Copy link
Member

phunkyfish commented Jan 8, 2022

Ya, I see the same from the log above. If I knew which call to wait on that would be easy enough to add.

the problem is login is called from numerous places and I don’t know which is the right one to wait on.

But if we figure that out it’s pretty easy. Or maybe we just try waiting for the first login call.

@micclass62
Copy link

O.k. now I have tried to wait until at least one login has happened in GetCapabilities and things do work then. But as being a C-Coder (30 years ago), my code is for sure not well suited to be commited.
Additionally I do see GetCapabilities called multiple times which does not make sense to me either. I guess the whole Code needs some review on how the the CVNSIClientInstance is handled.

@ksooo
Copy link
Member

ksooo commented Jan 8, 2022

Multiple GetCapabilities Calls are intended.

Guys, here is how "asnc connect" protocol (a bit simplified) works:

  • Kodi calls Create on the add-on
  • add-on starts async (!) connect to backend, returns OK to Kodi immediately
  • Kodi calls GetCapabilties
  • add-on returns just what it has at that moment, no need to wait until successful connect/login
  • once connected/logged in, add-on notifies Kodi async (!) via ConnectionStateChanged(CONNECTED) that the add-on is ready to use
  • Kodi calls getCapabilities again
  • add-on returns just what it has now that connect/login has completed
  • Kodi fetches updates for channels, timers, recordings, etc.

HTH

@phunkyfish
Copy link
Member

phunkyfish commented Jan 8, 2022

The fact that GetCapabilities as @ksooo has said is called multiple times is fine.

What we really need is to make sure that GetTimerTypes is not called prior to a login call happening as this is the source of the problem.

Likely the addon is reporting it’s connected before it actually is due to some issue with the TCP calls (this is just a hunch).

@ksooo
Copy link
Member

ksooo commented Jan 8, 2022

What we really need is to make sure that GetTimerTypes is not called prior to a login call happening as this is the source of the problem.

Why? GetTimerTypes is also called multiple times, like GetCapabilties and others. The add-on must simply give the information it has at time of the call. I have the same situation (some timer types only available if backend has at least a certain version) with pvr.hts and it is working fine.

@phunkyfish
Copy link
Member

For some reason the version of the backend does not get loaded prior to any timer types call. We need to figure out why that is.

@micclass62
Copy link

For me it looks like the whole code is not written with the assumption in mind that some Methods are called before a connection is available. The second call to GetCapabilites does not seem to "fix" the wrong answers from the first call. I can get everything to work correctly for the VPS timers when I do wait at the begin of GetCapabilities until we are logged into the vnsi server.

This works for me, but I would not consider it to be "the fix"
(https://cloud.michaelclass.de/s/pCH5wnart26897J)

@phunkyfish
Copy link
Member

For me it looks like the whole code is not written with the assumption in mind that some Methods are called before a connection is available. The second call to GetCapabilites does not seem to "fix" the wrong answers from the first call. I can get everything to work correctly for the VPS timers when I do wait at the begin of GetCapabilities until we are logged into the vnsi server.

This works for me, but I would not consider it to be "the fix" (https://cloud.michaelclass.de/s/pCH5wnart26897J)

The addon shouldn’t need to worry about the order. But I reckon in this case the addon is mis-reporting some state which is causing this problem.

@ksooo
Copy link
Member

ksooo commented Jan 10, 2022

@micclass62 please activate PVR compenent logging in addition to enable debug logging and send a new log.

@ksooo
Copy link
Member

ksooo commented Jan 10, 2022

@micclass62 seems that you are able to modify and compile the add-on by yourself. So, can you tell us what exactly the second GetTimerTypes call returns? Is the protocol version set properly on second call?

@micclass62
Copy link

Here you go:

https://paste.kodi.tv/ikelibalav.kodi

I have added a line that prints the Protocol Version inside the GetTimerTypes method ...

@ksooo
Copy link
Member

ksooo commented Jan 11, 2022

Thanks. There goes something wrong at the add-on side.

ddOnLog: pvr.vdr.vnsi: GetTimerTypes - Protocol is currently: 13
2022-01-11 15:28:38.670 T:9578    DEBUG <general>: Presentation: Frame was discarded by compositor
2022-01-11 15:28:41.640 T:9621     INFO <general>: Skipped 44 duplicate messages..
2022-01-11 15:28:41.640 T:9621    ERROR <general>: AddOnLog: pvr.vdr.vnsi: ReadResult - request timed out after 3 seconds
2022-01-11 15:28:41.640 T:9621    ERROR <general>: AddOnLog: pvr.vdr.vnsi: GetTimerTypes - Can't get response packed
 if (GetProtocol() >= 9)
    {
      cRequestPacket vrp;
      vrp.init(VNSI_TIMER_GETTYPES);
      auto vresp = ReadResult(&vrp);
      if (!vresp)
      {
        kodi::Log(ADDON_LOG_ERROR, "%s - Can't get response packed", __func__);
        return PVR_ERROR_NO_ERROR;
      }

So, root cause for your problem is that timer types cannot be obtained from the backend for whatever reason.
And: Returning "no error" in case the timer types cannot be obtained from the backend is definitely a bug.

@micclass62
Copy link

Yes, the errors can be observed all the time. But it is definitely not the network nor the vdr/vnsi-sever. I did a test with the vdr/vnsi-server running on the same host as kodi and accessed the vnsi-server via 127.0.0.1 with exactly the same behaviour.

@ksooo
Copy link
Member

ksooo commented Jan 11, 2022

@AlwinEsch by any chance, did the move from P8PLATFORM to kissnet break something here???? Please have a look and report back here. Thanks.

@micclass62
Copy link

Hello,

I could find now a less intrusive change to fix (better: work around) the VPS-Timers not appearing issue. It does NOT fix the underlying issue of something going wrong in the network communication as discussed above.

But: If I do change in pvr.vdr.vnsi/src/ClientInstance.cpp the order of the creation of the Timers (in essence do the VPS Timer add immediately atfer the Protocol > 9 check, my VPS timers do show up correctly.

diff -r -Bc pvr.vdr.vnsi/src/ClientInstance.cpp pvr.vdr.vnsi-patched/src/ClientInstance.cpp
*** pvr.vdr.vnsi/src/ClientInstance.cpp	2022-01-15 15:56:17.540491210 +0100
--- pvr.vdr.vnsi-patched/src/ClientInstance.cpp	2022-01-15 15:58:02.317632490 +0100
***************
*** 1003,1008 ****
--- 1003,1020 ----
      // addition timer supported by backend
      if (GetProtocol() >= 9)
      {
+       // VPS Timer
+       kodi::addon::PVRTimerType type;
+ 
+       type.SetId(VNSI_TIMER_TYPE_VPS);
+       type.SetDescription(kodi::addon::GetLocalizedString(30203));
+       type.SetAttributes(PVR_TIMER_TYPE_IS_MANUAL | PVR_TIMER_TYPE_SUPPORTS_ENABLE_DISABLE |
+                          PVR_TIMER_TYPE_SUPPORTS_CHANNELS | PVR_TIMER_TYPE_SUPPORTS_START_TIME |
+                          PVR_TIMER_TYPE_SUPPORTS_END_TIME | PVR_TIMER_TYPE_SUPPORTS_PRIORITY |
+                          PVR_TIMER_TYPE_SUPPORTS_LIFETIME |
+                          PVR_TIMER_TYPE_SUPPORTS_RECORDING_FOLDERS);
+       types.push_back(std::move(type));
+ 
        cRequestPacket vrp;
        vrp.init(VNSI_TIMER_GETTYPES);
        auto vresp = ReadResult(&vrp);
***************
*** 1026,1043 ****
                             PVR_TIMER_TYPE_SUPPORTS_PRIORITY | PVR_TIMER_TYPE_SUPPORTS_LIFETIME);
          types.push_back(std::move(type));
        }
- 
-       // VPS Timer
-       kodi::addon::PVRTimerType type;
- 
-       type.SetId(VNSI_TIMER_TYPE_VPS);
-       type.SetDescription(kodi::addon::GetLocalizedString(30203));
-       type.SetAttributes(PVR_TIMER_TYPE_IS_MANUAL | PVR_TIMER_TYPE_SUPPORTS_ENABLE_DISABLE |
-                          PVR_TIMER_TYPE_SUPPORTS_CHANNELS | PVR_TIMER_TYPE_SUPPORTS_START_TIME |
-                          PVR_TIMER_TYPE_SUPPORTS_END_TIME | PVR_TIMER_TYPE_SUPPORTS_PRIORITY |
-                          PVR_TIMER_TYPE_SUPPORTS_LIFETIME |
-                          PVR_TIMER_TYPE_SUPPORTS_RECORDING_FOLDERS);
-       types.push_back(std::move(type));
      }
  
      return PVR_ERROR_NO_ERROR;
--- 1038,1043 ----

Can we get this somehow until we do find the correct resolution? The issue is VERY annoying as I do see Pop-UPs all the time when watching a movie while there are some recordings going on. Unfortunately I can only build kodi on my Linux Workstation, but not for the Android platform (which is my main platform for watching TV - either on an tablet or on a FIre4k stick on TV) so I would be very much interessted into getting the fix for all my devices.

Cheers,
Michael

@phunkyfish
Copy link
Member

phunkyfish commented Jan 15, 2022

For this is to be fixed properly we’ll need to wait until @AlwinEsch has some time to take a look. Any other attempts other than fixing the comms problem are just getting lucky with timing or they are hacks.

If you need something why not create a PR and use the builds from Jenkins in the meantime?

@AlwinEsch
Copy link
Contributor

Becomed this weekend a bit more time and created a fix request about.
The transfered data was becomed wrong during Kodi's start and also if connection was not present and later done by Kodi.
A call to Kodi has blocked for some seconds the processes between add-on and VDR, by this was then come the errors.

Here the related request #174, the way is a bit ugly but on tests it has worked 😅.

@AlwinEsch
Copy link
Contributor

AlwinEsch commented Jan 15, 2022

For other OS's to test are binaries available here https://jenkins.kodi.tv/blue/organizations/jenkins/kodi-pvr%2Fpvr.vdr.vnsi/detail/PR-174/3/artifacts

For your Linux you need to compile by self and can be done with add of this patch https://github.com/kodi-pvr/pvr.vdr.vnsi/pull/174.patch to your code for tests.

@micclass62
Copy link

Thank a lot! This seems in deed to fix the issue. I have rebuild my local linux client (with a minor adjustment as I am still at Matrix) and things go smooth now. Startup of the vnsi client is now fast (not waiting multiple times for timeouts any more) and timers are correct.
Thanks again!!

@AlwinEsch
Copy link
Contributor

Brought in the requests and releases on Nexus and Matrix.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

5 participants