Functions called twice

Dev Community Dev/API Corner
1

Trying to create a channel, but don’t understand why all functions are called twice. I don’t understand why it’s happening.
Simple Plugin just to demonstrate

def Start():
	Log("== Start ==")
	HTTP.CacheTime = 0
	HTTP.Headers['User-agent']="Mozilla/5.0 (Macintosh; Intel Mac OS X 10.12; rv:55.0) Gecko/20100101 Firefox/55.0"

	ObjectContainer.title1 = TITLE
	ObjectContainer.art = R(ART)
	DirectoryObject.thumb = R(ICON)
	DirectoryObject.art = R(ART)
	EpisodeObject.thumb = R(ICON)
	EpisodeObject.art = R(ART)
	VideoClipObject.thumb = R(ICON)
	VideoClipObject.art = R(ART)

@handler(PREFIX, TITLE, art=ART, thumb=ICON)
def MainMenu():
	Log("== Main Menu ==")
	randomNumber = str(random.random())
	Log(randomNumber)

	oc = ObjectContainer()
	oc.add(DirectoryObject(key=Callback(SubLevel, title=randomNumber), title=randomNumber))

	return oc

def SubLevel(title):
	Log("== SubLevel (%s) ==" %title)
	return ObjectContainer(header="Empty", message=title)

I’m using an android phone to browse the channel and I see this in the logs. I open the channel and click the item.

2018-03-03 09:00:34,865 (8b4) :  INFO (logkit:16) - == Main Menu ==
2018-03-03 09:00:34,865 (8b4) :  INFO (logkit:16) - 0.48122084455
2018-03-03 09:00:34,865 (8b4) :  WARNING (runtime:1065) - Generating a callback path for a function with no route: <function SubLevel at 0x057B6A30>
2018-03-03 09:00:34,867 (8b4) :  DEBUG (base:117) - Checking if com.plexapp.plugins.xmtest is broken
2018-03-03 09:00:34,868 (8b4) :  DEBUG (networking:166) - Requesting 'http://127.0.0.1:32400/:/plugins/com.plexapp.system/messaging/function/X1N0b3JlU2VydmljZTpJc0NoYW5uZWxCcm9rZW4_/Y2VyZWFsMQoxCmxpc3QKMApyMAo_/Y2VyZWFsMQoxCmRpY3QKMQpzMjYKY29tLnBsZXhhcHAucGx1Z2lucy54bXRlc3RzMTAKaWRlbnRpZmllcnIwCg__'
2018-03-03 09:00:34,892 (8b4) :  DEBUG (runtime:88) - Sending packed state data (107 bytes)
2018-03-03 09:00:34,892 (8b4) :  DEBUG (runtime:924) - Response: [200] MediaContainer, 609 bytes
2018-03-03 09:00:35,365 (81c) :  DEBUG (runtime:717) - Handling request GET /video/xmtest
2018-03-03 09:00:35,371 (81c) :  DEBUG (runtime:49) - Received packed state data (80 bytes)
2018-03-03 09:00:35,374 (81c) :  DEBUG (runtime:814) - Found route matching /video/xmtest
2018-03-03 09:00:35,375 (81c) :  INFO (logkit:16) - == Main Menu ==
2018-03-03 09:00:35,377 (81c) :  INFO (logkit:16) - 0.682650233191
2018-03-03 09:00:35,378 (81c) :  WARNING (runtime:1065) - Generating a callback path for a function with no route: <function SubLevel at 0x057B6A30>
2018-03-03 09:00:35,378 (81c) :  DEBUG (base:117) - Checking if com.plexapp.plugins.xmtest is broken
2018-03-03 09:00:35,381 (81c) :  DEBUG (networking:166) - Requesting 'http://127.0.0.1:32400/:/plugins/com.plexapp.system/messaging/function/X1N0b3JlU2VydmljZTpJc0NoYW5uZWxCcm9rZW4_/Y2VyZWFsMQoxCmxpc3QKMApyMAo_/Y2VyZWFsMQoxCmRpY3QKMQpzMjYKY29tLnBsZXhhcHAucGx1Z2lucy54bXRlc3RzMTAKaWRlbnRpZmllcnIwCg__'
2018-03-03 09:00:35,407 (81c) :  DEBUG (runtime:88) - Sending packed state data (107 bytes)
2018-03-03 09:00:35,408 (81c) :  DEBUG (runtime:924) - Response: [200] MediaContainer, 614 bytes
2018-03-03 09:01:18,052 (392c) :  DEBUG (runtime:717) - Handling request GET /video/xmtest/:/function/SubLevel?function_args=Y2VyZWFsMQoxCmRpY3QKMQpzMTQKMC42ODI2NTAyMzMxOTFzNQp0aXRsZXIwCg__
2018-03-03 09:01:18,052 (392c) :  DEBUG (runtime:49) - Received packed state data (80 bytes)
2018-03-03 09:01:18,066 (392c) :  DEBUG (runtime:814) - Found route matching /video/xmtest/:/function/SubLevel
2018-03-03 09:01:18,068 (392c) :  DEBUG (runtime:125) - Calling function 'SubLevel'
2018-03-03 09:01:18,068 (392c) :  INFO (logkit:16) - == SubLevel (0.682650233191) ==
2018-03-03 09:01:18,069 (392c) :  DEBUG (runtime:88) - Sending packed state data (107 bytes)
2018-03-03 09:01:18,069 (392c) :  DEBUG (runtime:924) - Response: [200] MediaContainer, 311 bytes
2018-03-03 09:01:18,174 (35b8) :  DEBUG (runtime:717) - Handling request GET /video/xmtest/:/function/SubLevel?function_args=Y2VyZWFsMQoxCmRpY3QKMQpzMTQKMC42ODI2NTAyMzMxOTFzNQp0aXRsZXIwCg__
2018-03-03 09:01:18,178 (35b8) :  DEBUG (runtime:49) - Received packed state data (80 bytes)
2018-03-03 09:01:18,181 (35b8) :  DEBUG (runtime:814) - Found route matching /video/xmtest/:/function/SubLevel
2018-03-03 09:01:18,183 (35b8) :  DEBUG (runtime:125) - Calling function 'SubLevel'
2018-03-03 09:01:18,184 (35b8) :  INFO (logkit:16) - == SubLevel (0.682650233191) ==
2018-03-03 09:01:18,190 (35b8) :  DEBUG (runtime:88) - Sending packed state data (107 bytes)
2018-03-03 09:01:18,190 (35b8) :  DEBUG (runtime:924) - Response: [200] MediaContainer, 311 bytes

You can see the main menu was called twice and then sublevel was called twice. I have a random number generator in the main menu just to prove it is actually being called twice and not just double up in the logs. The android client displayed the 2nd random number (0.682650233191) and not the first.

2

@xmcnuggetx
what happens if you increase HTTP.CacheTime? (any value greater 0)
/R

######Plugins: ARDMediathek2016, Plex-Plugin-KIKA_und_tivi, Plex-Plugin-3Sat_Mediathek, Plex-Plugin-Flickr, Plex-Plugin-TagesschauXL, Plex-Plugin-Phoenix_Mediathek, TuneIn2017, Shoutcast2017, Plex-Plugin-ZDFmobile

3

Changing it to 30 has no effect. Still fires twice. It was actually left over from the sample channel. This currently isn’t making any http calls.

2018-03-03 13:14:05,548 (dd0) :  INFO (logkit:16) - == Main Menu ==
2018-03-03 13:14:05,548 (dd0) :  INFO (logkit:16) - 0.717029036226
2018-03-03 13:14:05,549 (dd0) :  WARNING (runtime:1065) - Generating a callback path for a function with no route: <function SubLevel at 0x057259B0>
2018-03-03 13:14:05,549 (dd0) :  DEBUG (base:117) - Checking if com.plexapp.plugins.xmtest is broken
2018-03-03 13:14:05,549 (dd0) :  DEBUG (networking:166) - Requesting 'http://127.0.0.1:32400/:/plugins/com.plexapp.system/messaging/function/X1N0b3JlU2VydmljZTpJc0NoYW5uZWxCcm9rZW4_/Y2VyZWFsMQoxCmxpc3QKMApyMAo_/Y2VyZWFsMQoxCmRpY3QKMQpzMjYKY29tLnBsZXhhcHAucGx1Z2lucy54bXRlc3RzMTAKaWRlbnRpZmllcnIwCg__'
2018-03-03 13:14:05,568 (dd0) :  DEBUG (runtime:88) - Sending packed state data (107 bytes)
2018-03-03 13:14:05,568 (dd0) :  DEBUG (runtime:924) - Response: [200] MediaContainer, 614 bytes
2018-03-03 13:14:05,786 (185c) :  DEBUG (runtime:717) - Handling request GET /video/xmtest
2018-03-03 13:14:05,788 (185c) :  DEBUG (runtime:49) - Received packed state data (80 bytes)
2018-03-03 13:14:05,789 (185c) :  DEBUG (runtime:814) - Found route matching /video/xmtest
2018-03-03 13:14:05,789 (185c) :  INFO (logkit:16) - == Main Menu ==
2018-03-03 13:14:05,790 (185c) :  INFO (logkit:16) - 0.455720503774
2018-03-03 13:14:05,790 (185c) :  WARNING (runtime:1065) - Generating a callback path for a function with no route: <function SubLevel at 0x057259B0>
2018-03-03 13:14:05,792 (185c) :  DEBUG (base:117) - Checking if com.plexapp.plugins.xmtest is broken
2018-03-03 13:14:05,793 (185c) :  DEBUG (networking:166) - Requesting 'http://127.0.0.1:32400/:/plugins/com.plexapp.system/messaging/function/X1N0b3JlU2VydmljZTpJc0NoYW5uZWxCcm9rZW4_/Y2VyZWFsMQoxCmxpc3QKMApyMAo_/Y2VyZWFsMQoxCmRpY3QKMQpzMjYKY29tLnBsZXhhcHAucGx1Z2lucy54bXRlc3RzMTAKaWRlbnRpZmllcnIwCg__'
2018-03-03 13:14:05,816 (185c) :  DEBUG (runtime:88) - Sending packed state data (107 bytes)
2018-03-03 13:14:05,818 (185c) :  DEBUG (runtime:924) - Response: [200] MediaContainer, 614 bytes
4

You can try once more it with a route to function SubLevel.
If that doesn’t help, I have no idea.

I have noticed a simliar issue in my plugin tunein2017 few month ago . If HTTP.CacheTime was not set, it jumped back to Main from the function CreateTrackObject.
In server log the the name of the key function was lacking, like this: GET /music/tunein2017?includeConcerts=1&includeExtras... -
only plugin path and parameters, even though a route was set.
I was not able to locate the reason but it doesn’t happened any more after setting the CacheTime greater 0 (for me to 300).

/R

######Plugins: ARDMediathek2016, Plex-Plugin-KIKA_und_tivi, Plex-Plugin-3Sat_Mediathek, Plex-Plugin-Flickr, Plex-Plugin-TagesschauXL, Plex-Plugin-Phoenix_Mediathek, TuneIn2017, Shoutcast2017, Plex-Plugin-ZDFmobile

5

Added a route and even changed it to 300. Still fires twice. Start only gets called once, but main and sublevel get called twice.

2018-03-03 13:35:45,007 (2a84) :  INFO (logkit:16) - == Main Menu ==
2018-03-03 13:35:45,007 (2a84) :  INFO (logkit:16) - 0.924486452084
2018-03-03 13:35:45,007 (2a84) :  DEBUG (base:117) - Checking if com.plexapp.plugins.xmtest is broken
2018-03-03 13:35:45,009 (2a84) :  DEBUG (networking:166) - Requesting 'http://127.0.0.1:32400/:/plugins/com.plexapp.system/messaging/function/X1N0b3JlU2VydmljZTpJc0NoYW5uZWxCcm9rZW4_/Y2VyZWFsMQoxCmxpc3QKMApyMAo_/Y2VyZWFsMQoxCmRpY3QKMQpzMjYKY29tLnBsZXhhcHAucGx1Z2lucy54bXRlc3RzMTAKaWRlbnRpZmllcnIwCg__'
2018-03-03 13:35:45,026 (2a84) :  DEBUG (runtime:88) - Sending packed state data (107 bytes)
2018-03-03 13:35:45,026 (2a84) :  DEBUG (runtime:924) - Response: [200] MediaContainer, 545 bytes
2018-03-03 13:35:45,084 (3480) :  DEBUG (runtime:717) - Handling request GET /video/xmtest
2018-03-03 13:35:45,085 (3480) :  DEBUG (runtime:49) - Received packed state data (80 bytes)
2018-03-03 13:35:45,086 (3480) :  DEBUG (runtime:814) - Found route matching /video/xmtest
2018-03-03 13:35:45,086 (3480) :  INFO (logkit:16) - == Main Menu ==
2018-03-03 13:35:45,088 (3480) :  INFO (logkit:16) - 0.806540556027
2018-03-03 13:35:45,088 (3480) :  DEBUG (base:117) - Checking if com.plexapp.plugins.xmtest is broken
2018-03-03 13:35:45,089 (3480) :  DEBUG (networking:166) - Requesting 'http://127.0.0.1:32400/:/plugins/com.plexapp.system/messaging/function/X1N0b3JlU2VydmljZTpJc0NoYW5uZWxCcm9rZW4_/Y2VyZWFsMQoxCmxpc3QKMApyMAo_/Y2VyZWFsMQoxCmRpY3QKMQpzMjYKY29tLnBsZXhhcHAucGx1Z2lucy54bXRlc3RzMTAKaWRlbnRpZmllcnIwCg__'
2018-03-03 13:35:45,105 (3480) :  DEBUG (runtime:88) - Sending packed state data (107 bytes)
2018-03-03 13:35:45,105 (3480) :  DEBUG (runtime:924) - Response: [200] MediaContainer, 545 bytes
2018-03-03 13:37:00,892 (3458) :  DEBUG (runtime:717) - Handling request GET /video/xmtest/sublevel?title=0.806540556027
2018-03-03 13:37:00,894 (3458) :  DEBUG (runtime:49) - Received packed state data (80 bytes)
2018-03-03 13:37:00,897 (3458) :  DEBUG (runtime:814) - Found route matching /video/xmtest/sublevel
2018-03-03 13:37:00,898 (3458) :  INFO (logkit:16) - == SubLevel (0.806540556027) ==
2018-03-03 13:37:00,900 (3458) :  DEBUG (runtime:88) - Sending packed state data (107 bytes)
2018-03-03 13:37:00,901 (3458) :  DEBUG (runtime:924) - Response: [200] MediaContainer, 311 bytes
2018-03-03 13:37:01,153 (3ed4) :  DEBUG (runtime:717) - Handling request GET /video/xmtest/sublevel?title=0.806540556027
2018-03-03 13:37:01,154 (3ed4) :  DEBUG (runtime:49) - Received packed state data (80 bytes)
2018-03-03 13:37:01,157 (3ed4) :  DEBUG (runtime:814) - Found route matching /video/xmtest/sublevel
2018-03-03 13:37:01,157 (3ed4) :  INFO (logkit:16) - == SubLevel (0.806540556027) ==
2018-03-03 13:37:01,160 (3ed4) :  DEBUG (runtime:88) - Sending packed state data (107 bytes)
2018-03-03 13:37:01,161 (3ed4) :  DEBUG (runtime:924) - Response: [200] MediaContainer, 311 bytes
6

@xmcnuggetx
I tried your sample in Web Player and Open PHT - normal behavior. With Plex Android app I get also the double output in Main.
Tomorrow I will make some tests and check the logs.
/R

######Plugins: ARDMediathek2016, Plex-Plugin-KIKA_und_tivi, Plex-Plugin-3Sat_Mediathek, Plex-Plugin-Flickr, Plex-Plugin-TagesschauXL, Plex-Plugin-Phoenix_Mediathek, TuneIn2017, Shoutcast2017, Plex-Plugin-ZDFmobile

7

@xmcnuggetx
you have discovered an interesting case. As my tests with the android app shows, the function Main() always is called twice. Web Player and Open PHT are not affected.
I compared several plugins with the same result. Obviously it’s not depending on the size of plugin, the size of code in Main, or if outer functions are called frome Main().

The comparison of plugin- and server-logs shows that also the plugin-thread is called twice by Framework:

1. call:
Plugin: 2018-03-04 08:36:39,455 Funktion Main
Server: 2018 08:36:40.040 Thread: Running async task started by thread 0x7f06dd3fe700
2. call:
Plugin: 2018-03-04 08:36:40,299 Funktion Main
Server: 2018 08:36:40.296 Thread: Running async task started by thread 0x7f06ddbff700.

It’s only a guess, but this behavior could be caused by a time-problem or a missing lock in the thread-code of the android app.
Anyway - this seems not bothering the plugin functions, so I can live with it.
/R

######Plugins: ARDMediathek2016, Plex-Plugin-KIKA_und_tivi, Plex-Plugin-3Sat_Mediathek, Plex-Plugin-Flickr, Plex-Plugin-TagesschauXL, Plex-Plugin-Phoenix_Mediathek, TuneIn2017, Shoutcast2017, Plex-Plugin-ZDFmobile