If you have not already, we suggest setting your Plex username to something else rather than email which is displayed on your posts in forum. You can change the username at https://app.plex.tv/desktop#!/account
Welcome to our forums! Please take a few moments to read through our Community Guidelines (also conveniently linked in the header at the top of each page). There, you'll find guidelines on conduct, tips on getting the help you may be searching for, and more!

Bug: PMS IP change not handled - Kodi log bloated to over 1 GB

DavidMayDavidMay Posts: 14Members, Plex Pass Plex Pass

Hi all,

The Plex for Kodi addon bloats my Kodi log to over 1 GB, because it repeatedly tries to get info from PMS using an old IP address after the server IP is changed (My router/ISP resets my public IP every 24 hours).

After I got my new IP, the PMS notices this and pushes the new IP to myPlex. However, the Plex Kodi addon does not "see" this and tries to update the Home Hub with the old IP again and again. Instead of five minutes, the refresh is triggered again the very second after the previous one failed.

The "connection time out" error messages bloat the Kodi log and cause unnecessary CPU usage. I am not sure, what the root cause of this is, I usually manually quit Plex and go into the Kodi main menu after I am finished. The HTPC/Server constantly runs with Kodi in the background, system screensaver activates after 10 mins, no standby.

Could you please fix this?

Addon 0.1.1, Kodi 17.4, PMS 1.9.2.4285, Windows Server 2008 R2; PMS is running on the same machine as Kodi

Here are the logs, the router logged the reconnect at around 03:37 AM today:

PMS notices IP change and publishes it successfully:

 Sep 27, 2017 03:38:21.281 [3988] DEBUG - MyPlex: We appear to have regained Internet connectivity.
 Sep 27, 2017 03:38:21.281 [3988] DEBUG - PublicAddressManager: Obtaining public address and mapping port.
 Sep 27, 2017 03:38:21.282 [2104] DEBUG - PublicAddressManager: Obtaining public IP.
 Sep 27, 2017 03:38:21.282 [2104] DEBUG - HTTP requesting GET http://plex.tv/pms/:/ip
 Sep 27, 2017 03:38:21.420 [2104] DEBUG - HTTP 200 response from GET http://plex.tv/pms/:/ip
 Sep 27, 2017 03:38:21.420 [2104] DEBUG - PublicAddressManager: Got public IP from http://plex.tv: NEW.IP.ADDR
 Sep 27, 2017 03:38:24.433 [2104] DEBUG - NAT: UPnP, found device <http://ROUTER.IP:49000/igddesc.xml> with private address <PMS.LOCAL.IP>
 Sep 27, 2017 03:38:24.448 [2104] DEBUG - NAT: UPnP, usable device <http://ROUTER.IP.1:49000/igddesc.xml> with private address <PMS.LOCAL.IP>.
 Sep 27, 2017 03:38:24.455 [2104] DEBUG - NAT: UPnP, public address is NEW.IP.ADDR
 Sep 27, 2017 03:38:24.461 [2104] DEBUG - MyPlex: Sending Server Info to myPlex (user=MY@EMAIL.COM, ip=, port=32400)
 Sep 27, 2017 03:38:24.463 [2104] DEBUG - HTTP requesting POST https://plex.tv/servers.xml?auth_token=xxxxxxxxxxxxxxxxxxxx&async=1&asyncIdentifier=199Yfcc8-d633-447f-8605-d54e1ef833X2
 Sep 27, 2017 03:38:24.746 [2104] DEBUG - HTTP 201 response from POST https://plex.tv/servers.xml?auth_token=xxxxxxxxxxxxxxxxxxxx&async=1&asyncIdentifier=199Yfcc8-d633-447f-8605-d54e1ef833X2
 Sep 27, 2017 03:38:24.747 [2104] DEBUG - MyPlex: Published Mapping State response was 201
 Sep 27, 2017 03:38:24.747 [2104] DEBUG - MyPlex: Got response for 75s328dc849ab0075654a205eb ~ registered NEW.IP.ADDR:32400
 Sep 27, 2017 03:38:24.752 [2104] DEBUG - MyPlex: Updating device connections (from timer: 0)

Plexi Kodi log - first, udpate works well, then everything goes south - the error message is repeated every 1.5 seconds:

 03:38:47.493 T:5500  NOTICE: script.plex: Section is stale: REFRESHING - update: True
 03:38:47.493 T:4200  NOTICE: script.plex: BGThreader: (queue.0:worker.0): Active
 03:38:47.494 T:4200  NOTICE: script.plex: API: GET https://OLD-IP-ADDR.31e6422803fd4ff71df.plex.direct:32400/hubs?X-Plex-Token=****
 03:38:48.011 T:4200  NOTICE: script.plex: Showing hubs - Section: None - Update: True
 03:38:48.011 T:4200  NOTICE: script.plex: Hub: home.continue (1)
 03:38:48.022 T:4200  NOTICE: script.plex: Hub: home.ondeck (3)
 03:38:48.023 T:4200  NOTICE: script.plex: Hub: home.playlists (0)
 03:38:48.023 T:4200  NOTICE: script.plex: Hub: home.television.recent (10)
 03:38:48.038 T:4200  NOTICE: script.plex: Hub: home.movies.recent (10)
 03:38:48.039 T:4200  NOTICE: script.plex: Hub: home.videos.recent (0)
 03:38:48.039 T:4200  NOTICE: script.plex: Hub: home.photos.recent (0)
 03:38:48.039 T:4200  NOTICE: script.plex: Hub: home.music.recent (0)
03:43:55.570 T:5256  NOTICE: script.plex: API: GET https://OLD-IP-ADDR.31e6422803fd4ff71df.plex.direct:32400/hubs?X-Plex-Token=****
03:43:56.673 T:5500  NOTICE: script.plex: Section is stale: REFRESHING - update: True
03:43:56.673 T:3496  NOTICE: script.plex: BGThreader: (queue.0:worker.7): Active
03:43:56.674 T:3496  NOTICE: script.plex: API: GET https://OLD-IP-ADDR.31e6422803fd4ff71df.plex.direct:32400/hubs?X-Plex-Token=****
03:43:57.773 T:5500  NOTICE: script.plex: Section is stale: REFRESHING - update: True
03:43:58.957 T:4680  NOTICE: Previous line repeats 1 times.
03:43:58.957 T:4680   ERROR: _________________________________________________________________________________
03:43:58.957 T:4680   ERROR: script.plex: ERROR:
03:43:58.957 T:4680   ERROR:     Traceback (most recent call last):
03:43:58.957 T:4680   ERROR:       File "C:\Users\HTPC\AppData\Roaming\Kodi\addons\script.plex\lib\backgroundthread.py", line 83, in _runTask
03:43:58.957 T:4680   ERROR:         task._run()
03:43:58.957 T:4680   ERROR:       File "C:\Users\HTPC\AppData\Roaming\Kodi\addons\script.plex\lib\backgroundthread.py", line 37, in _run
03:43:58.957 T:4680   ERROR:         self.run()
03:43:58.957 T:4680   ERROR:       File "C:\Users\HTPC\AppData\Roaming\Kodi\addons\script.plex\lib\windows\home.py", line 67, in run
03:43:58.957 T:4680   ERROR:         hubs = HubsList(plexapp.SERVERMANAGER.selectedServer.hubs(self.section.key, count=HUB_PAGE_SIZE)).init()
03:43:58.957 T:4680   ERROR:       File "C:\Users\HTPC\AppData\Roaming\Kodi\addons\script.plex\lib\_included_packages\plexnet\plexserver.py", line 140, in hubs
03:43:58.957 T:4680   ERROR:         data = self.query(q, params=params)
03:43:58.957 T:4680   ERROR:       File "C:\Users\HTPC\AppData\Roaming\Kodi\addons\script.plex\lib\_included_packages\plexnet\plexserver.py", line 172, in query
03:43:58.957 T:4680   ERROR:         response = method(url, **kwargs)
03:43:58.957 T:4680   ERROR:       File "C:\Users\HTPC\AppData\Roaming\Kodi\addons\script.module.requests\lib\requests\sessions.py", line 501, in get
03:43:58.957 T:4680   ERROR:         return self.request('GET', url, **kwargs)
03:43:58.957 T:4680   ERROR:       File "C:\Users\HTPC\AppData\Roaming\Kodi\addons\script.module.requests\lib\requests\sessions.py", line 488, in request
03:43:58.957 T:4680   ERROR:         resp = self.send(prep, **send_kwargs)
03:43:58.957 T:4680   ERROR:       File "C:\Users\HTPC\AppData\Roaming\Kodi\addons\script.module.requests\lib\requests\sessions.py", line 609, in send
03:43:58.957 T:4680   ERROR:         r = adapter.send(request, **kwargs)
03:43:58.957 T:4680   ERROR:       File "C:\Users\HTPC\AppData\Roaming\Kodi\addons\script.module.requests\lib\requests\adapters.py", line 423, in send
03:43:58.957 T:4680   ERROR:         timeout=timeout
03:43:58.957 T:4680   ERROR:       File "C:\Users\HTPC\AppData\Roaming\Kodi\addons\script.module.requests\lib\requests\packages\urllib3\connectionpool.py", line 594, in urlopen
03:43:58.957 T:4680   ERROR:         chunked=chunked)
03:43:58.957 T:4680   ERROR:       File "C:\Users\HTPC\AppData\Roaming\Kodi\addons\script.module.requests\lib\requests\packages\urllib3\connectionpool.py", line 350, in _make_request
03:43:58.957 T:4680   ERROR:         self._validate_conn(conn)
03:43:58.957 T:4680   ERROR:       File "C:\Users\HTPC\AppData\Roaming\Kodi\addons\script.module.requests\lib\requests\packages\urllib3\connectionpool.py", line 835, in _validate_conn
03:43:58.957 T:4680   ERROR:         conn.connect()
03:43:58.957 T:4680   ERROR:       File "C:\Users\HTPC\AppData\Roaming\Kodi\addons\script.module.requests\lib\requests\packages\urllib3\connection.py", line 281, in connect
03:43:58.957 T:4680   ERROR:         conn = self._new_conn()
03:43:58.957 T:4680   ERROR:       File "C:\Users\HTPC\AppData\Roaming\Kodi\addons\script.plex\lib\_included_packages\plexnet\asyncadapter.py", line 148, in _new_conn
03:43:58.957 T:4680   ERROR:         timeout=self.timeout
03:43:58.957 T:4680   ERROR:       File "C:\Users\HTPC\AppData\Roaming\Kodi\addons\script.plex\lib\_included_packages\plexnet\asyncadapter.py", line 108, in create_connection
03:43:58.957 T:4680   ERROR:         for msg in self._connect(sock, sa):
03:43:58.957 T:4680   ERROR:       File "C:\Users\HTPC\AppData\Roaming\Kodi\addons\script.plex\lib\_included_packages\plexnet\asyncadapter.py", line 127, in _connect
03:43:58.957 T:4680   ERROR:         self._check_timeout()  # this should be done at the beginning of each loop
03:43:58.957 T:4680   ERROR:       File "C:\Users\HTPC\AppData\Roaming\Kodi\addons\script.plex\lib\_included_packages\plexnet\asyncadapter.py", line 78, in _check_timeout
03:43:58.957 T:4680   ERROR:         raise TimeoutException('connection timed out')
03:43:58.957 T:4680   ERROR:     TimeoutException: connection timed out
03:43:58.957 T:4680   ERROR: _________________________________________________________________________________
03:43:58.957 T:4680   ERROR: `
03:43:58.958 T:4680  NOTICE: script.plex: API: GET https://OLD-IP-ADDR.31e6422803fd4ff71df.plex.direct:32400/hubs?X-Plex-Token=****
03:43:59.973 T:5500  NOTICE: script.plex: Section is stale: REFRESHING - update: True

Best wishes

Answers

  • DavidMayDavidMay Posts: 14Members, Plex Pass Plex Pass
    edited October 10

    I spent further time looking at the Plex for Kodi code on GitHub. I could not see, if and where there is any mechanism that would update the PMS URL without invoking specific UI actions like refreshing the server list. So if the UI is idle and the server IP changes, you might get the problem above. The UI then also shows a constant loading "..." icon and becomes unresponsive.

    I found following workaround for me. I edited the plexserver.py file and modified the query method by forcing a resource refresh if any query is timed out. Add before existing exception handler:

        except asyncadapter.TimeoutException:
             util.ERROR()     
             plexapp.refreshResources(True)
             return None
    

    Now, add after the line calling the buildUrl method and assigning the url variable - in order to properly catch queries against empty connection URLs by the background thread of the plex script:

        # If URL is empty, try refresh resources and return empty set for now     
        if not url:
            util.WARN_LOG("Empty server url, returning None and refreshing resources")
            plexapp.refreshResources(True)
            return None   
    

    Lastly, add an import asyncadapter to the import section at the beginning of the file.

    A complete resource refresh is probably "overkill", but as far as I see, it seems to get the job done for now. Of course, I would appreciate it, if someone more familiar with the code or any of the devs could find a more elegant solution for this kind of problem :smile:

Sign In or Register to comment.