Skip to content
This repository has been archived by the owner on Oct 18, 2024. It is now read-only.

Executable (after subtitle grabbing) not working #355

Closed
joelteixeira opened this issue Oct 4, 2017 · 38 comments
Closed

Executable (after subtitle grabbing) not working #355

joelteixeira opened this issue Oct 4, 2017 · 38 comments

Comments

@joelteixeira
Copy link

Hello there, first of all thank you for this must have addon for Plex. I'm trying to get a notification whenever a subtitle is downloaded via Pushover. I already did all steps to use pushover from three different methods and all of them are working standalone but not being invoked by Sub-Zero:

1 - Via a batch file, called notifier.bat.
2 - Python script, called notif.py
3 - Shell script that I can invoke right from cmd or powershell using bash from WLS "bash -c "sh ~/notif.sh"

I'm getting different errors using any method and I'm not sure what exactly I'm doing wrong.

For the first one I inserted on the "Call this executable...." box the full path:

c:\bin\notifier.bat

and got the following error:

2017-10-03 21:53:22,035 (26b8) : ERROR (logkit:22) - Calling C:\bin\notifier.bat failed: Traceback (most recent call last):
File "C:\Users\sputnik\AppData\Local\Plex Media Server\Plug-ins\Sub-Zero.bundle\Contents\Code\support\helpers.py", line 308, in notify_executable
stderr=subprocess.STDOUT, shell=True, env=env)
File "C:\Program Files (x86)\Plex\Plex Media Server\python27.zip\subprocess.py", line 574, in check_output
raise CalledProcessError(retcode, cmd, output=output)
CalledProcessError: Command 'C:\bin\notifier.bat' returned non-zero exit status 1

For the third method I got:

2017-10-04 13:33:09,219 (d8) : ERROR (logkit:22) - Notify executable not existing or not executable: c:\Windows\System32\bash.exe

And for the notif.py it not even showed on logs, it's possible that I didn't waited to long before switching to bash.

Could you please detail what it isn't right on this setup. Executing any of this methods by myself it works as expected.

Thank you.

@joelteixeira
Copy link
Author

I'm sorry, finally got it working with python with:

c:\Python27\python.exe c:\bin\notif.py %(subtitle_filename)s

Thank you again!

@pannal
Copy link
Owner

pannal commented Oct 11, 2017

For the others who encounter this: What was the content of your bat and py files?

It may have been a permissions or more likely, a PATH issue that caused this.

@joelteixeira
Copy link
Author

joelteixeira commented Oct 27, 2017

@pannal

Here's the content of mine:

notif-share.zip

@pannal
Copy link
Owner

pannal commented Oct 27, 2017

Great, that may help some users. Any reason why you used urllib/httplib and not requests?

@joelteixeira
Copy link
Author

No special reason at all. I got the template searching on web and since it worked well I didn't look for any improved version.

@zucram
Copy link

zucram commented May 29, 2018

Hi! I'm getting the same problem. Even when adding c:\Python27\python.exe to the line... Any help appriciated!

@pannal
Copy link
Owner

pannal commented May 30, 2018

@zucram I'll need DEBUG logs in order to help you there.

@zucram
Copy link

zucram commented May 30, 2018

Here is what the LOGS say, let me know if you need the entire log @pannal ...

  File "C:\Users\Marcus\AppData\Local\Plex Media Server\Plug-ins\Sub-Zero.bundle\Contents\Code\support\helpers.py", line 311, in notify_executable
    stderr=subprocess.STDOUT, shell=True, env=env)
  File "C:\Program Files (x86)\Plex\Plex Media Server\python27.zip\subprocess.py", line 574, in check_output
    raise CalledProcessError(retcode, cmd, output=output)
CalledProcessError: Command 'c:\Python27\python.exe c:\Users\Marcus\Downloads\mytest.py' returned non-zero exit status 1

@pannal
Copy link
Owner

pannal commented May 30, 2018

Can you post the contents of mytest.py?

@zucram
Copy link

zucram commented May 30, 2018

Here it is @pannal. I've obviously removed some of the more sensitive stuff from the code with ****. It works if i open a command prompt and run python mytest.py. I'm on a windows machine.

import smtplib

gmail_user = '*******'  
gmail_password = '*******'

sent_from = gmail_user  
to = '********'  
subject = '#Sub-Zero'  
body = 'BODY HERE'

email_text = """    
Subject: %s

%s
""" % (subject, body)

try:  
    server = smtplib.SMTP_SSL('smtp.gmail.com', 465)
    server.ehlo()
    server.login(gmail_user, gmail_password)
    server.sendmail(sent_from, to, email_text)
    server.close()

    print 'Email sent!'
except:  
    print 'Something went wrong...'

@pannal
Copy link
Owner

pannal commented May 30, 2018

@zucram you don't handle any parameters in there, is that intended?

@zucram
Copy link

zucram commented May 30, 2018

@pannal i just wanted the email to work firstly and then handle the input parameters so that the body contains the movie and the subtitle found and such.

pannal added a commit that referenced this issue May 30, 2018
@pannal
Copy link
Owner

pannal commented May 30, 2018

@zucram interesting. I've pushed an updated version to the develop-2.5 branch, which tries to log the error and output streams of the called executable to further investigate this.

Could you install the develop-2.5 branch? (Restart PMS afterwards)

@pannal
Copy link
Owner

pannal commented May 30, 2018

Hmm no. You're not running the latest develop-2.5 branch. check_output isn't used anymore. Please follow this to properly install the branch.

@zucram
Copy link

zucram commented May 31, 2018

@pannal Hmm.. seem to have a problem then. I tried to follow the instructions but the path to sub-zero was wrong (seemed to be an osx path and i'm on windows) but i thought i unpacked develop-2.5 but the output is the same... Info.plist says that i'm on develop branch.

@zucram
Copy link

zucram commented May 31, 2018

@pannal Managed to get it working. Only thing i can find in the logs now is

2018-05-31 09:47:59,572 (7d0) : ERROR (logkit:22) - Notify executable not existing or not executable: c:\Python27\python.exe c:\Users\Marcus\Downloads\mytest.py 2018-05-31 09:48:01,390 (7d0) : ERROR (logkit:22) - Notify executable not existing or not executable: c:\Python27\python.exe c:\Users\Marcus\Downloads\mytest.py

@zucram
Copy link

zucram commented Jun 3, 2018

@pannal any update on this?

pannal added a commit that referenced this issue Jun 5, 2018
@pannal
Copy link
Owner

pannal commented Jun 5, 2018

@zucram please update to the latest develop branch again, I've improved the executable detection logic.

@zucram
Copy link

zucram commented Jun 5, 2018

Hey @pannal not sure i got it to work correctly but here are the latest logs...

2018-06-05 17:49:18,556 (818) : CRITICAL (core:574) - Exception in the update function of agent named 'Sub-Zero Subtitles (Movies, 2.5.4.2562 DEV)', called with guid 'com.plexapp.agents.imdb://tt1670345?lang=en' (most recent call last): File "C:\Program Files (x86)\Plex\Plex Media Server\Resources\Plug-ins-31d3c0c65\Framework.bundle\Contents\Resources\Versions\2\Python\Framework\api\agentkit.py", line 1076, in _update agent.update(obj, media, lang, **kwargs) File "C:\Users\Marcus\AppData\Local\Plex Media Server\Plug-ins\Sub-Zero.bundle\Contents\Code\__init__.py", line 194, in update update_local_media(metadata, media, media_type=self.agent_type) File "C:\Users\Marcus\AppData\Local\Plex Media Server\Plug-ins\Sub-Zero.bundle\Contents\Code\__init__.py", line 99, in update_local_media support.localmedia.find_subtitles(part) File "C:\Users\Marcus\AppData\Local\Plex Media Server\Plug-ins\Sub-Zero.bundle\Contents\Code\support\localmedia.py", line 73, in find_subtitles for file_path_listing in os.listdir(path.encode(sz_config.fs_encoding)): File "C:\Program Files (x86)\Plex\Plex Media Server\Resources\Plug-ins-31d3c0c65\Framework.bundle\Contents\Resources\Versions\2\Python\subsystem\ospathfix.py", line 111, in os_listdir return os._listdir(longpathify(uni(path))) WindowsError: [Error 3] The system cannot find the path specified: u'\\\\?\\Z:\\Movies\\Now.You.See.Me.2013.1080p.EXTENDED.BluRay.x264-BARC0DE\\*.*'

@pannal
Copy link
Owner

pannal commented Jun 5, 2018

@zucram that's unrelated to the original issue. Can we sort the executable thing out first? Also please attach the full log.

@zucram
Copy link

zucram commented Jun 6, 2018

@pannal Here is the full log

2018-06-05 17:45:23,812 (2fb4) :  DEBUG (core:361) - Using the elevated policy
2018-06-05 17:45:23,812 (2fb4) :  DEBUG (core:450) - Starting runtime component.
2018-06-05 17:45:23,815 (2fb4) :  DEBUG (core:450) - Starting caching component.
2018-06-05 17:45:23,815 (2fb4) :  DEBUG (core:450) - Starting data component.
2018-06-05 17:45:23,815 (2fb4) :  DEBUG (core:450) - Starting networking component.
2018-06-05 17:45:23,815 (2fb4) :  DEBUG (networking:284) - Loaded HTTP cookies
2018-06-05 17:45:23,823 (2fb4) :  DEBUG (networking:452) - Setting the default network timeout to 20.0
2018-06-05 17:45:23,825 (2fb4) :  DEBUG (core:450) - Starting localization component.
2018-06-05 17:45:23,825 (2fb4) :  INFO (localization:409) - Setting the default locale to en-us
2018-06-05 17:45:23,825 (2fb4) :  DEBUG (localization:427) - Loaded en strings
2018-06-05 17:45:23,825 (2fb4) :  DEBUG (core:450) - Starting messaging component.
2018-06-05 17:45:23,825 (2fb4) :  DEBUG (core:450) - Starting debugging component.
2018-06-05 17:45:23,826 (2fb4) :  DEBUG (core:450) - Starting services component.
2018-06-05 17:45:23,826 (1288) :  DEBUG (networking:166) - Requesting 'http://127.0.0.1:32400/system/messaging/clear_events/com.plexapp.agents.subzero'
2018-06-05 17:45:23,828 (2fb4) :  DEBUG (core:450) - Starting myplex component.
2018-06-05 17:45:23,828 (2fb4) :  DEBUG (core:450) - Starting notifications component.
2018-06-05 17:45:24,000 (2fb4) :  DEBUG (accessor:68) - Creating a new model access point for provider com.plexapp.agents.subzero in namespace 'metadata'
2018-06-05 17:45:24,009 (2fb4) :  DEBUG (networking:166) - Requesting 'http://127.0.0.1:32400/:/plugins/com.plexapp.system/resourceHashes'
2018-06-05 17:45:24,062 (2fb4) :  DEBUG (runtime:1117) - Created a thread named 'load_all_services'
2018-06-05 17:45:24,062 (1b94) :  DEBUG (services:265) - Plug-in is not daemonized - loading services from system
2018-06-05 17:45:24,065 (2fb4) :  DEBUG (runtime:1117) - Created a thread named 'get_server_info'
2018-06-05 17:45:24,065 (2fb4) :  DEBUG (core:150) - Finished starting framework core
2018-06-05 17:45:24,065 (1b94) :  DEBUG (networking:166) - Requesting 'http://127.0.0.1:32400/:/plugins/com.plexapp.system/messaging/function/X0J1bmRsZVNlcnZpY2U6QWxsU2VydmljZXM_/Y2VyZWFsMQoxCmxpc3QKMApyMAo_/Y2VyZWFsMQoxCmRpY3QKMApyMAo_'
2018-06-05 17:45:24,065 (244c) :  DEBUG (networking:166) - Requesting 'http://127.0.0.1:32400'
2018-06-05 17:45:24,066 (2fb4) :  DEBUG (core:560) - Loading plug-in code
2018-06-05 17:45:24,085 (244c) :  DEBUG (core:538) - Machine identifier is 9c76ca9ffe9563b7203aa70ec2542ab08495ab37
2018-06-05 17:45:24,086 (244c) :  DEBUG (core:539) - Server version is 1.13.0.5023-31d3c0c65
2018-06-05 17:45:24,289 (2fb4) :  DEBUG (core:566) - Finished loading plug-in code
2018-06-05 17:45:24,706 (1b94) :  DEBUG (services:362) - Loaded services
2018-06-05 17:45:24,723 (f24) :  DEBUG (services:438) - No shared code to load
2018-06-05 17:45:28,529 (2fb4) :  INFO (logkit:16) - Using UnRAR from: C:\Users\Marcus\AppData\Local\Plex Media Server\Plug-ins\Sub-Zero.bundle\Contents\Libraries\Windows\i386\UnRAR\UnRAR.exe
2018-06-05 17:45:28,533 (2fb4) :  DEBUG (preferences:258) - Loaded preferences from DefaultPrefs.json
2018-06-05 17:45:28,536 (2fb4) :  DEBUG (preferences:178) - Loaded the user preferences for com.plexapp.agents.subzero
2018-06-05 17:45:28,549 (2fb4) :  WARNING (logkit:19) - Did NOT find Preferences file - most likely Windows OS. Otherwise please check logfile and hierarchy.
2018-06-05 17:45:28,561 (2fb4) :  INFO (datakit:93) - Loaded the dictionary file
2018-06-05 17:45:28,604 (2fb4) :  DEBUG (networking:166) - Requesting 'http://127.0.0.1:32400/library/sections'
2018-06-05 17:45:28,612 (2fb4) :  DEBUG (networking:166) - Requesting 'http://127.0.0.1:32400/system/agents'
2018-06-05 17:45:28,631 (2fb4) :  DEBUG (networking:166) - Requesting 'http://127.0.0.1:32400/system/agents/com.plexapp.agents.none/config/1'
2018-06-05 17:45:28,650 (2fb4) :  DEBUG (networking:166) - Requesting 'http://127.0.0.1:32400/system/agents/com.plexapp.agents.none/config/2'
2018-06-05 17:45:28,671 (2fb4) :  DEBUG (networking:166) - Requesting 'http://127.0.0.1:32400/system/agents/com.plexapp.agents.imdb/config/1'
2018-06-05 17:45:28,688 (2fb4) :  DEBUG (networking:166) - Requesting 'http://127.0.0.1:32400/system/agents/com.plexapp.agents.thetvdb/config/2'
2018-06-05 17:45:28,707 (2fb4) :  DEBUG (networking:166) - Requesting 'http://127.0.0.1:32400/system/agents/com.plexapp.agents.themoviedb/config/1'
2018-06-05 17:45:28,729 (2fb4) :  DEBUG (networking:166) - Requesting 'http://127.0.0.1:32400/system/agents/com.plexapp.agents.themoviedb/config/2'
2018-06-05 17:45:28,740 (2fb4) :  DEBUG (logkit:13) - I'm enabled for: ['Movies', 'TV Shows']
2018-06-05 17:45:28,971 (2fb4) :  INFO (datakit:131) - Saved the dictionary file
2018-06-05 17:45:30,392 (2fb4) :  DEBUG (runtime:640) - Adding a prefix handler for 'Sub-Zero Subtitles DEV' ('/video/subzero')
2018-06-05 17:45:30,480 (2fb4) :  DEBUG (agentkit:1115) - Creating new agent class called SubZeroSubtitlesAgentMovies
2018-06-05 17:45:30,480 (2fb4) :  DEBUG (agentkit:933) - Updating agent information: [{'media_types': ['Movie'], 'accepts_from': None, 'fallback_agent': None, 'contributes_to': ['com.plexapp.agents.imdb', 'com.plexapp.agents.xbmcnfo', 'com.plexapp.agents.themoviedb', 'com.plexapp.agents.hama'], 'languages': ['en'], 'persist_stored_files': True, 'version': 0, 'primary_provider': False, 'prefs': True, 'name': 'Sub-Zero Subtitles (Movies, 2.5.4.2562 DEV)'}]
2018-06-05 17:45:30,480 (2fb4) :  DEBUG (networking:166) - Requesting 'http://127.0.0.1:32400/:/plugins/com.plexapp.system/messaging/function/X0FnZW50U2VydmljZTpVcGRhdGVJbmZv/Y2VyZWFsMQoxCmxpc3QKMApyMAo_/Y2VyZWFsMQo2CmRpY3QKbGlzdApkaWN0Cmxpc3QKbGlzdApsaXN0CjIKczI2CmNvbS5wbGV4YXBwLmFnZW50cy5zdWJ6ZXJvczEwCmlkZW50aWZpZXJyMQpzMTAKYWdlbnRfaW5mbzEKcjIKMTAKcjMKczExCm1lZGlhX3R5cGVzbnMxMgphY2NlcHRzX2Zyb21uczE0CmZhbGxiYWNrX2FnZW50cjQKczE0CmNvbnRyaWJ1dGVzX3RvcjUKczkKbGFuZ3VhZ2VzYjFzMjAKcGVyc2lzdF9zdG9yZWRfZmlsZXNpMApzNwp2ZXJzaW9uYjBzMTYKcHJpbWFyeV9wcm92aWRlcmIxczUKcHJlZnNzNDMKU3ViLVplcm8gU3VidGl0bGVzIChNb3ZpZXMsIDIuNS40LjI1NjIgREVWKXM0Cm5hbWUxCnM1Ck1vdmllNApzMjMKY29tLnBsZXhhcHAuYWdlbnRzLmltZGJzMjYKY29tLnBsZXhhcHAuYWdlbnRzLnhibWNuZm9zMjkKY29tLnBsZXhhcHAuYWdlbnRzLnRoZW1vdmllZGJzMjMKY29tLnBsZXhhcHAuYWdlbnRzLmhhbWExCnMyCmVucjAK'
2018-06-05 17:45:30,492 (2fb4) :  DEBUG (agentkit:1115) - Creating new agent class called SubZeroSubtitlesAgentTvShows
2018-06-05 17:45:30,493 (2fb4) :  DEBUG (agentkit:933) - Updating agent information: [{'media_types': ['Movie'], 'accepts_from': None, 'fallback_agent': None, 'contributes_to': ['com.plexapp.agents.imdb', 'com.plexapp.agents.xbmcnfo', 'com.plexapp.agents.themoviedb', 'com.plexapp.agents.hama'], 'languages': ['en'], 'persist_stored_files': True, 'version': 0, 'primary_provider': False, 'prefs': True, 'name': 'Sub-Zero Subtitles (Movies, 2.5.4.2562 DEV)'}, {'media_types': ['TV_Show'], 'accepts_from': None, 'fallback_agent': None, 'contributes_to': ['com.plexapp.agents.thetvdb', 'com.plexapp.agents.themoviedb', 'com.plexapp.agents.thetvdbdvdorder', 'com.plexapp.agents.xbmcnfotv', 'com.plexapp.agents.hama'], 'languages': ['en'], 'persist_stored_files': True, 'version': 0, 'primary_provider': False, 'prefs': True, 'name': 'Sub-Zero Subtitles (TV, 2.5.4.2562 DEV)'}]
2018-06-05 17:45:30,493 (2fb4) :  DEBUG (networking:166) - Requesting 'http://127.0.0.1:32400/:/plugins/com.plexapp.system/messaging/function/X0FnZW50U2VydmljZTpVcGRhdGVJbmZv/Y2VyZWFsMQoxCmxpc3QKMApyMAo_/Y2VyZWFsMQo5CmRpY3QKbGlzdApkaWN0Cmxpc3QKbGlzdApsaXN0CmRpY3QKbGlzdApsaXN0CjIKczI2CmNvbS5wbGV4YXBwLmFnZW50cy5zdWJ6ZXJvczEwCmlkZW50aWZpZXJyMQpzMTAKYWdlbnRfaW5mbzIKcjIKcjYKMTAKcjMKczExCm1lZGlhX3R5cGVzbnMxMgphY2NlcHRzX2Zyb21uczE0CmZhbGxiYWNrX2FnZW50cjQKczE0CmNvbnRyaWJ1dGVzX3RvcjUKczkKbGFuZ3VhZ2VzYjFzMjAKcGVyc2lzdF9zdG9yZWRfZmlsZXNpMApzNwp2ZXJzaW9uYjBzMTYKcHJpbWFyeV9wcm92aWRlcmIxczUKcHJlZnNzNDMKU3ViLVplcm8gU3VidGl0bGVzIChNb3ZpZXMsIDIuNS40LjI1NjIgREVWKXM0Cm5hbWUxCnM1Ck1vdmllNApzMjMKY29tLnBsZXhhcHAuYWdlbnRzLmltZGJzMjYKY29tLnBsZXhhcHAuYWdlbnRzLnhibWNuZm9zMjkKY29tLnBsZXhhcHAuYWdlbnRzLnRoZW1vdmllZGJzMjMKY29tLnBsZXhhcHAuYWdlbnRzLmhhbWExCnMyCmVuMTAKcjcKczExCm1lZGlhX3R5cGVzbnMxMgphY2NlcHRzX2Zyb21uczE0CmZhbGxiYWNrX2FnZW50cjgKczE0CmNvbnRyaWJ1dGVzX3RvcjUKczkKbGFuZ3VhZ2VzYjFzMjAKcGVyc2lzdF9zdG9yZWRfZmlsZXNpMApzNwp2ZXJzaW9uYjBzMTYKcHJpbWFyeV9wcm92aWRlcmIxczUKcHJlZnNzMzkKU3ViLVplcm8gU3VidGl0bGVzIChUViwgMi41LjQuMjU2MiBERVYpczQKbmFtZTEKczcKVFZfU2hvdzUKczI2CmNvbS5wbGV4YXBwLmFnZW50cy50aGV0dmRiczI5CmNvbS5wbGV4YXBwLmFnZW50cy50aGVtb3ZpZWRiczM0CmNvbS5wbGV4YXBwLmFnZW50cy50aGV0dmRiZHZkb3JkZXJzMjgKY29tLnBsZXhhcHAuYWdlbnRzLnhibWNuZm90dnMyMwpjb20ucGxleGFwcC5hZ2VudHMuaGFtYXIwCg__'
2018-06-05 17:45:30,515 (2fb4) :  INFO (logkit:16) - Using new style file based cache!
2018-06-05 17:45:30,523 (2fb4) :  INFO (datakit:131) - Saved the dictionary file
2018-06-05 17:45:30,532 (2fb4) :  INFO (datakit:131) - Saved the dictionary file
2018-06-05 17:45:30,533 (2fb4) :  DEBUG (logkit:13) - Clearing previous task data
2018-06-05 17:45:30,540 (2fb4) :  INFO (datakit:131) - Saved the dictionary file
2018-06-05 17:45:30,549 (2fb4) :  INFO (datakit:131) - Saved the dictionary file
2018-06-05 17:45:30,551 (2fb4) :  DEBUG (logkit:13) - Stop logging to console
2018-06-05 17:45:30,605 (2fb4) :  INFO (logkit:16) - Using UnRAR from: C:\Users\Marcus\AppData\Local\Plex Media Server\Plug-ins\Sub-Zero.bundle\Contents\Libraries\Windows\i386\UnRAR\UnRAR.exe
2018-06-05 17:45:30,615 (2fb4) :  WARNING (logkit:19) - Did NOT find Preferences file - most likely Windows OS. Otherwise please check logfile and hierarchy.
2018-06-05 17:45:30,628 (2fb4) :  DEBUG (networking:166) - Requesting 'http://127.0.0.1:32400/library/sections'
2018-06-05 17:45:30,635 (2fb4) :  DEBUG (networking:166) - Requesting 'http://127.0.0.1:32400/system/agents'
2018-06-05 17:45:30,655 (2fb4) :  DEBUG (networking:166) - Requesting 'http://127.0.0.1:32400/system/agents/com.plexapp.agents.none/config/1'
2018-06-05 17:45:30,668 (2fb4) :  DEBUG (networking:166) - Requesting 'http://127.0.0.1:32400/system/agents/com.plexapp.agents.none/config/2'
2018-06-05 17:45:30,681 (2fb4) :  DEBUG (networking:166) - Requesting 'http://127.0.0.1:32400/system/agents/com.plexapp.agents.imdb/config/1'
2018-06-05 17:45:30,696 (2fb4) :  DEBUG (networking:166) - Requesting 'http://127.0.0.1:32400/system/agents/com.plexapp.agents.thetvdb/config/2'
2018-06-05 17:45:30,710 (2fb4) :  DEBUG (networking:166) - Requesting 'http://127.0.0.1:32400/system/agents/com.plexapp.agents.themoviedb/config/1'
2018-06-05 17:45:30,723 (2fb4) :  DEBUG (networking:166) - Requesting 'http://127.0.0.1:32400/system/agents/com.plexapp.agents.themoviedb/config/2'
2018-06-05 17:45:30,737 (2fb4) :  DEBUG (logkit:13) - I'm enabled for: ['Movies', 'TV Shows']
2018-06-05 17:45:30,753 (2fb4) :  INFO (datakit:131) - Saved the dictionary file
2018-06-05 17:45:30,757 (2fb4) :  INFO (datakit:131) - Saved the dictionary file
2018-06-05 17:45:30,763 (2fb4) :  INFO (datakit:131) - Saved the dictionary file
2018-06-05 17:45:30,766 (2fb4) :  INFO (datakit:131) - Saved the dictionary file
2018-06-05 17:45:30,772 (2fb4) :  INFO (datakit:131) - Saved the dictionary file
2018-06-05 17:45:30,776 (2fb4) :  INFO (datakit:131) - Saved the dictionary file
2018-06-05 17:45:30,782 (2fb4) :  INFO (datakit:131) - Saved the dictionary file
2018-06-05 17:45:30,789 (2fb4) :  INFO (datakit:131) - Saved the dictionary file
2018-06-05 17:45:30,796 (2fb4) :  INFO (datakit:131) - Saved the dictionary file
2018-06-05 17:45:30,801 (2fb4) :  INFO (datakit:131) - Saved the dictionary file
2018-06-05 17:45:30,805 (2fb4) :  INFO (datakit:131) - Saved the dictionary file
2018-06-05 17:45:30,805 (2fb4) :  DEBUG (logkit:13) - Task data cleared: MissingSubtitles
2018-06-05 17:45:30,805 (2fb4) :  DEBUG (logkit:13) - Validate Prefs called.
2018-06-05 17:45:30,805 (2fb4) :  DEBUG (logkit:13) - --- SZ Config-Debug ---
2018-06-05 17:45:30,805 (2fb4) :  DEBUG (logkit:13) - config.version: 2.5.4.2562 DEV
2018-06-05 17:45:30,806 (2fb4) :  DEBUG (logkit:13) - config.app_support_path: C:\Users\Marcus\AppData\Local\Plex Media Server
2018-06-05 17:45:30,806 (2fb4) :  DEBUG (logkit:13) - config.data_path: C:\Users\Marcus\AppData\Local\Plex Media Server\Plug-in Support\Data\com.plexapp.agents.subzero
2018-06-05 17:45:30,806 (2fb4) :  DEBUG (logkit:13) - config.data_items_path: C:\Users\Marcus\AppData\Local\Plex Media Server\Plug-in Support\Data\com.plexapp.agents.subzero\DataItems
2018-06-05 17:45:30,806 (2fb4) :  DEBUG (logkit:13) - config.enable_agent: True
2018-06-05 17:45:30,806 (2fb4) :  DEBUG (logkit:13) - config.enable_channel: True
2018-06-05 17:45:30,806 (2fb4) :  DEBUG (logkit:13) - config.permissions_ok: True
2018-06-05 17:45:30,808 (2fb4) :  DEBUG (logkit:13) - config.missing_permissions: []
2018-06-05 17:45:30,808 (2fb4) :  DEBUG (logkit:13) - config.fs_encoding: utf-8
2018-06-05 17:45:30,808 (2fb4) :  DEBUG (logkit:13) - config.subtitle_destination_folder: None
2018-06-05 17:45:30,808 (2fb4) :  DEBUG (logkit:13) - config.new_style_cache: True
2018-06-05 17:45:30,808 (2fb4) :  DEBUG (logkit:13) - config.dbm_supported: False
2018-06-05 17:45:30,809 (2fb4) :  DEBUG (logkit:13) - config.lang_list: set([<Language [en]>])
2018-06-05 17:45:30,813 (2fb4) :  DEBUG (logkit:13) - config.providers: ['titlovi', 'podnapisi', 'tvsubtitles', 'opensubtitles', 'addic7ed']
2018-06-05 17:45:30,813 (2fb4) :  DEBUG (logkit:13) - config.plex_transcoder: C:\Program Files (x86)\Plex\Plex Media Server\plextranscoder.exe
2018-06-05 17:45:30,813 (2fb4) :  DEBUG (logkit:13) - config.refiner_settings: {'radarr': {'api_key': 'xxxxxxxxxxxxxxxxxxxxxxxxx', 'base_url': 'http://localhost:7878'}, 'sonarr': {'api_key': 'xxxxxxxxxxxxxxxxxxxxxxxxx', 'base_url': 'http://localhost:8989'}}
2018-06-05 17:45:30,813 (2fb4) :  DEBUG (logkit:13) - config.unrar: C:\Users\Marcus\AppData\Local\Plex Media Server\Plug-ins\Sub-Zero.bundle\Contents\Libraries\Windows\i386\UnRAR\UnRAR.exe
2018-06-05 17:45:30,813 (2fb4) :  DEBUG (logkit:13) - config.adv_cfg_path: None
2018-06-05 17:45:30,819 (2fb4) :  DEBUG (logkit:13) - config.plugin_log_path: C:\Users\Marcus\AppData\Local\Plex Media Server\Logs\PMS Plugin Logs\com.plexapp.agents.subzero.log (accessible: True)
2018-06-05 17:45:30,829 (2fb4) :  DEBUG (logkit:13) - config.server_log_path: C:\Users\Marcus\AppData\Local\Plex Media Server\Logs\Plex Media Server.log (accessible: True)
2018-06-05 17:45:30,829 (2fb4) :  DEBUG (logkit:13) - Pref.subtitles.save.filesystem: True
2018-06-05 17:45:30,831 (2fb4) :  DEBUG (logkit:13) - ----- Connections -----
2018-06-05 17:45:30,841 (2fb4) :  DEBUG (logkit:13) - Sonarr: OK - 2.0.0.5163
2018-06-05 17:45:30,848 (2fb4) :  DEBUG (logkit:13) - Radarr: OK - 0.2.0.1067
2018-06-05 17:45:30,848 (2fb4) :  DEBUG (logkit:13) - ----- Environment -----
2018-06-05 17:45:30,848 (2fb4) :  DEBUG (logkit:13) - Platform: Windows-i386
2018-06-05 17:45:30,848 (2fb4) :  DEBUG (logkit:13) - OS: Windows
2018-06-05 17:45:30,849 (2fb4) :  DEBUG (logkit:13) - Python: 2.7.12
2018-06-05 17:45:30,849 (2fb4) :  DEBUG (logkit:13) - PLEXSERVERPORT: 32400
2018-06-05 17:45:30,849 (2fb4) :  DEBUG (logkit:13) - PLEXLOCALAPPDATA: C:\Users\Marcus\AppData\Local\
2018-06-05 17:45:30,849 (2fb4) :  DEBUG (logkit:13) - SZ_USER_AGENT: Sub-Zero/2.5.4.2562-dev
2018-06-05 17:45:30,851 (2fb4) :  DEBUG (logkit:13) - PLEXTOKEN: xxxxxxxxxxxxxxxxxxx
2018-06-05 17:45:30,851 (2fb4) :  DEBUG (logkit:13) - PLEXBUNDLEDEXTS: 1
2018-06-05 17:45:30,851 (2fb4) :  DEBUG (logkit:13) - PLEXBUNDLEDPLUGINSPATH: C:\Program Files (x86)\Plex\Plex Media Server\Resources\Plug-ins-31d3c0c65
2018-06-05 17:45:30,851 (2fb4) :  DEBUG (logkit:13) - Locale: ('sv_SE', 'cp1252')
2018-06-05 17:45:30,851 (2fb4) :  DEBUG (logkit:13) - -----------------------
2018-06-05 17:45:30,851 (2fb4) :  DEBUG (logkit:13) - Setting log-level to WARNING
2018-06-05 17:45:30,852 (2fb4) :  DEBUG (logkit:13) - Registering LoggerHandler for dependency: subliminal
2018-06-05 17:45:30,852 (2fb4) :  DEBUG (logkit:13) - Registering LoggerHandler for dependency: subliminal_patch
2018-06-05 17:45:30,852 (2fb4) :  DEBUG (logkit:13) - Registering LoggerHandler for dependency: enzyme
2018-06-05 17:45:30,852 (2fb4) :  DEBUG (logkit:13) - Registering LoggerHandler for dependency: guessit
2018-06-05 17:45:30,854 (2fb4) :  DEBUG (logkit:13) - Registering LoggerHandler for dependency: subzero
2018-06-05 17:45:30,854 (2fb4) :  DEBUG (logkit:13) - Registering LoggerHandler for dependency: libfilebot
2018-06-05 17:45:49,979 (1b68) :  WARNING (runtime:1065) - Generating a callback path for a function with no route: <function inner at 0x065C3830>
2018-06-05 17:45:51,920 (1234) :  WARNING (runtime:1065) - Generating a callback path for a function with no route: <function inner at 0x065C3830>
2018-06-05 17:46:00,884 (244c) :  WARNING (logkit:19) - subliminal_patch.providers.tvsubtitles: No episode ids found
2018-06-05 17:46:00,884 (244c) :  ERROR (logkit:22) - subliminal_patch.providers.tvsubtitles: Episode 5 not found
2018-06-05 17:49:18,556 (818) :  CRITICAL (core:574) - Exception in the update function of agent named 'Sub-Zero Subtitles (Movies, 2.5.4.2562 DEV)', called with guid 'com.plexapp.agents.imdb://tt1670345?lang=en' (most recent call last):
  File "C:\Program Files (x86)\Plex\Plex Media Server\Resources\Plug-ins-31d3c0c65\Framework.bundle\Contents\Resources\Versions\2\Python\Framework\api\agentkit.py", line 1076, in _update
    agent.update(obj, media, lang, **kwargs)
  File "C:\Users\Marcus\AppData\Local\Plex Media Server\Plug-ins\Sub-Zero.bundle\Contents\Code\__init__.py", line 194, in update
    update_local_media(metadata, media, media_type=self.agent_type)
  File "C:\Users\Marcus\AppData\Local\Plex Media Server\Plug-ins\Sub-Zero.bundle\Contents\Code\__init__.py", line 99, in update_local_media
    support.localmedia.find_subtitles(part)
  File "C:\Users\Marcus\AppData\Local\Plex Media Server\Plug-ins\Sub-Zero.bundle\Contents\Code\support\localmedia.py", line 73, in find_subtitles
    for file_path_listing in os.listdir(path.encode(sz_config.fs_encoding)):
  File "C:\Program Files (x86)\Plex\Plex Media Server\Resources\Plug-ins-31d3c0c65\Framework.bundle\Contents\Resources\Versions\2\Python\subsystem\ospathfix.py", line 111, in os_listdir
    return os._listdir(longpathify(uni(path)))
WindowsError: [Error 3] The system cannot find the path specified: u'\\\\?\\Z:\\Movies\\Now.You.See.Me.2013.1080p.EXTENDED.BluRay.x264-BARC0DE\\*.*'

2018-06-05 21:06:14,611 (24b8) :  ERROR (logkit:22) - subliminal.refiners.tvdb: Multiple matches found
2018-06-05 21:06:14,713 (24b8) :  ERROR (logkit:22) - subliminal.refiners.tvdb: Multiple matches found
2018-06-05 21:06:14,838 (2d60) :  ERROR (logkit:22) - subliminal_patch.providers.tvsubtitles: Episode 1 not found
2018-06-05 21:06:15,017 (1bd0) :  WARNING (logkit:19) - subliminal.providers.addic7ed: Series So You Think You Can Dance not found in show ids
2018-06-05 21:06:15,063 (1bd0) :  WARNING (logkit:19) - subliminal.providers.addic7ed: Series So You Think You Can Dance not found in show ids
2018-06-05 21:06:15,066 (1bd0) :  ERROR (logkit:22) - subliminal.providers.addic7ed: No show id found for 'So You Think You Can Dance' ({'year': 2005})
2018-06-06 03:07:26,815 (16e8) :  ERROR (logkit:22) - subliminal.refiners.tvdb: Multiple matches found
2018-06-06 03:07:26,911 (16e8) :  ERROR (logkit:22) - subliminal.refiners.tvdb: Multiple matches found
2018-06-06 03:07:27,035 (2f40) :  ERROR (logkit:22) - subliminal_patch.providers.tvsubtitles: Episode 1 not found
2018-06-06 03:07:27,190 (26ac) :  WARNING (logkit:19) - subliminal.providers.addic7ed: Series So You Think You Can Dance not found in show ids
2018-06-06 03:07:27,229 (26ac) :  WARNING (logkit:19) - subliminal.providers.addic7ed: Series So You Think You Can Dance not found in show ids
2018-06-06 03:07:27,230 (26ac) :  ERROR (logkit:22) - subliminal.providers.addic7ed: No show id found for 'So You Think You Can Dance' ({'year': 2005})
2018-06-06 06:18:28,993 (2498) :  ERROR (logkit:22) - subliminal_patch.providers.tvsubtitles: Episode 10 not found
2018-06-06 09:08:01,746 (a28) :  ERROR (logkit:22) - subliminal.refiners.tvdb: Multiple matches found
2018-06-06 09:08:01,838 (a28) :  ERROR (logkit:22) - subliminal.refiners.tvdb: Multiple matches found
2018-06-06 09:08:01,966 (e8) :  ERROR (logkit:22) - subliminal_patch.providers.tvsubtitles: Episode 1 not found
2018-06-06 09:08:02,180 (2540) :  WARNING (logkit:19) - subliminal.providers.addic7ed: Series So You Think You Can Dance not found in show ids
2018-06-06 09:08:02,210 (2540) :  WARNING (logkit:19) - subliminal.providers.addic7ed: Series So You Think You Can Dance not found in show ids
2018-06-06 09:08:02,211 (2540) :  ERROR (logkit:22) - subliminal.providers.addic7ed: No show id found for 'So You Think You Can Dance' ({'year': 2005})
2018-06-06 09:08:33,217 (2a48) :  ERROR (logkit:22) - subliminal_patch.providers.tvsubtitles: Episode 10 not found
2018-06-06 09:32:20,197 (788) :  ERROR (model:205) - Cannot read model from C:\Users\Marcus\AppData\Local\Plex Media Server\Metadata\TV Shows\6\f68f4e16d55a25d5b422383c5a33f5fc8b2654c.bundle\Contents\com.plexapp.agents.subzero
2018-06-06 09:32:20,448 (2608) :  ERROR (logkit:22) - subliminal_patch.providers.tvsubtitles: Episode 10 not found

@pannal
Copy link
Owner

pannal commented Jun 7, 2018

@zucram this is still a different issue. Can you try refreshing the item that caused the notification executable error in the first place and see whether the issue still exists?

For WindowsError: [Error 3] The system cannot find the path specified: u'\\\\?\\Z:\\Movies\\Now.You.See.Me.2013.1080p.EXTENDED.BluRay.x264-BARC0DE\\*.*' please open a new ticket. Z:\ looks like a network share, is it?

Edit: Also, to post your log zip, please follow this.

@zucram
Copy link

zucram commented Jun 7, 2018

@pannal Sorry, i've fixed the network error now. Problem now is that when i force-find a subtitle it doesn't trigger the mytest.py error in the logs anymore. Not sure how to fix this.

@pannal
Copy link
Owner

pannal commented Jun 7, 2018

@zucram please post your log zip after an item refresh with SZ in DEBUG mode ("How verbose should the logging be?"-setting).

@zucram
Copy link

zucram commented Jun 7, 2018

Logs_180607_15-20-58.zip

Here you go, the logs seem better now! @pannal

pannal added a commit that referenced this issue Jun 7, 2018
@pannal
Copy link
Owner

pannal commented Jun 7, 2018

@zucram yep I had a typo. Please update to the current develop version and do that again, and post the log zip.

@zucram
Copy link

zucram commented Jun 7, 2018

Here's the new ones @pannal
Logs_180607_16-00-42.zip

pannal added a commit that referenced this issue Jun 7, 2018
@pannal
Copy link
Owner

pannal commented Jun 7, 2018

OK, now we've got a proper error:

\'\\\\?\\C:\\Users\\Marcus\\AppData\\Local\\Plex Media Server\\Plug-in Support\\Data\\com.plexapp.agents.subzero\'\r\nCMD.EXE was started with the above path as the current directory.\r\nUNC paths are not supported.  Defaulting to Windows directory.\r\nTraceback (most recent call last):\r\n  File "c:\\Users\\Marcus\\Downloads\\mytest.py", line 1, in <module>\r\n    import smtplib\r\n  File "c:\\python27\\lib\\smtplib.py", line 44, in <module>\r\n    import socket\r\n  File "c:\\python27\\lib\\socket.py", line 47, in <module>\r\n    import _socket\r\nImportError: DLL load failed: %1 is not a valid Win32 application.\r\n

I've updated the branch again and am setting a "proper" working directory now (the folder of the executable). If that doesn't fix it, there's something else wrong, probably with your python setup?

@zucram
Copy link

zucram commented Jun 7, 2018

Still not working. Here are the latest logs.. @pannal
Logs_180607_18-59-30.zip

@pannal
Copy link
Owner

pannal commented Jun 8, 2018

@zucram do you by any chance have Python 3 installed as well? Does the script run on its own from the command line?

Edit: Can you add this at the top of your script:

import os
print repr(os.environ)

@zucram
Copy link

zucram commented Jun 9, 2018

@pannal The script runs in python 2.7 from both cmd line and double clicking it...
Here is the print OS.environ
{ 'TMP': 'C:\\Users\\Marcus\\AppData\\Local\\Temp', 'COMPUTERNAME': 'NUC', 'VS140COMNTOOLS': 'C:\\Program Files (x86)\\Microsoft Visual Studio 14.0\\Common7\\Tools\\', 'USERDOMAIN': 'NUC', 'PSMODULEPATH': 'C:\\WINDOWS\\system32\\WindowsPowerShell\\v1.0\\Modules\\;C:\\Program Files\\Intel\\;C:\\Program Files\\Intel\\Wired Networking\\', 'COMMONPROGRAMFILES': 'C:\\Program Files\\Common Files', 'PROCESSOR_IDENTIFIER': 'Intel64 Family 6 Model 78 Stepping 3, GenuineIntel', 'PROGRAMFILES': 'C:\\Program Files', 'PROCESSOR_REVISION': '4e03', 'PATH': 'C:\\Python27\\;C:\\Python27\\Scripts;C:\\Program Files (x86)\\Intel\\iCLS Client\\;C:\\Program Files\\Intel\\iCLS Client\\;C:\\WINDOWS\\system32;C:\\WINDOWS;C:\\WINDOWS\\System32\\Wbem;C:\\WINDOWS\\System32\\WindowsPowerShell\\v1.0\\;C:\\Program Files (x86)\\Intel\\Intel(R) Management Engine Components\\DAL;C:\\Program Files\\Intel\\Intel(R) Management Engine Components\\DAL;C:\\Program Files (x86)\\Intel\\Intel(R) Management Engine Components\\IPT;C:\\Program Files\\Intel\\Intel(R) Management Engine Components\\IPT;C:\\WINDOWS\\system32\\config\\systemprofile\\.dnx\\bin;C:\\Program Files\\Microsoft DNX\\Dnvm\\;C:\\Program Files\\Microsoft SQL Server\\130\\Tools\\Binn\\;C:\\Program Files\\Git\\cmd;C:\\Program Files (x86)\\Windows Kits\\8.1\\Windows Performance Toolkit\\;C:\\Program Files (x86)\\nodejs\\;C:\\Program Files\\Intel\\WiFi\\bin\\;C:\\Program Files\\Common Files\\Intel\\WirelessCommon\\;C:\\WINDOWS\\System32\\OpenSSH\\;C:\\Users\\Marcus\\AppData\\Local\\Microsoft\\WindowsApps;C:\\Users\\Marcus\\AppData\\Roaming\\npm;C:\\Program Files\\Intel\\WiFi\\bin\\;C:\\Program Files\\Common Files\\Intel\\WirelessCommon\\;', 'SYSTEMROOT': 'C:\\WINDOWS', 'PROGRAMFILES(X86)': 'C:\\Program Files (x86)', 'BONJOUR_SDK_HOME': 'C:\\Program Files\\Bonjour SDK\\', 'COMSPEC': 'C:\\WINDOWS\\system32\\cmd.exe', 'DRIVERDATA': 'C:\\Windows\\System32\\Drivers\\DriverData', 'TEMP': 'C:\\Users\\Marcus\\AppData\\Local\\Temp', 'COMMONPROGRAMFILES(X86)': 'C:\\Program Files (x86)\\Common Files', 'PROCESSOR_ARCHITECTURE': 'AMD64', 'ALLUSERSPROFILE': 'C:\\ProgramData', 'LOCALAPPDATA': 'C:\\Users\\Marcus\\AppData\\Local', 'FPS_BROWSER_USER_PROFILE_STRING': 'Default', 'HOMEPATH': '\\Users\\Marcus', 'USERDOMAIN_ROAMINGPROFILE': 'NUC', 'PROGRAMW6432': 'C:\\Program Files', 'USERNAME': 'Marcus', 'LOGONSERVER': '\\\\NUC', 'PROMPT': '$P$G', 'SESSIONNAME': 'Console', 'PROGRAMDATA': 'C:\\ProgramData', 'ONEDRIVE': 'C:\\Users\\Marcus\\OneDrive', 'FPS_BROWSER_APP_PROFILE_STRING': 'Internet Explorer', 'PATHEXT': '.COM;.EXE;.BAT;.CMD;.VBS;.VBE;.JS;.JSE;.WSF;.WSH;.MSC', 'SNF': 'C:\\ProgramData\\UltimateSecurityPackages\\snp.sc', 'WINDIR': 'C:\\WINDOWS', 'OPENSSL_CONF': 'C:\\OpenSSL-Win32\\bin\\openssl.cfg', 'APPDATA': 'C:\\Users\\Marcus\\AppData\\Roaming', 'HOMEDRIVE': 'C:', 'SYSTEMDRIVE': 'C:', 'NUMBER_OF_PROCESSORS': '4', 'PROCESSOR_LEVEL': '6', 'SNP': 'http://%66%65%65%64.%73%6E%61%70%64%6F.%63%6F%6D?publisher=APSFAmonCM&co=SE&userid=6f70e015-d233-8258-8980-2c9a161f521b&searchtype=sc&installDate=30-04-2016&barcodeid=51229003&channelid=3&av=windows', 'COMMONPROGRAMW6432': 'C:\\Program Files\\Common Files', 'OS': 'Windows_NT', 'PUBLIC': 'C:\\Users\\Public', 'USERPROFILE': 'C:\\Users\\Marcus' }

@pannal
Copy link
Owner

pannal commented Jun 9, 2018

OK and when the script is executed by SZ? (Leave the os environ print in there please)

@zucram
Copy link

zucram commented Jun 10, 2018

Not sure how i check that, here are the logs when os.environ is still there and i do a force-find on an episode... @pannal
Logs_180610_09-38-45.zip

@pannal
Copy link
Owner

pannal commented Jun 10, 2018

@zucram create a dummy python file with just the os.environ stuff inside and use that as notification executable. Then I might get some insight.

@zucram
Copy link

zucram commented Jun 10, 2018

@pannal Here is the logs for that..
Logs_180610_21-59-00.zip

@pannal
Copy link
Owner

pannal commented Jun 10, 2018

OK, I guess this is the issue: 'PYTHONPATH': 'C:\\Program Files (x86)\\Plex\\Plex Media Server\\DLLs;C:\\Program Files (x86)\\Plex\\Plex Media Server\\Exts;C:\\Program Files (x86)\\Plex\\Plex Media Server\\Resources\\Plug-ins-fd05be322/Framework.bundle/Contents/Resources/Platforms/Shared/Libraries/'.

I've pushed an update that unsets the PYTHONPATH in the environment for the called executable.

Please report back if this fixes the issue. It might, but it also might not.

@zucram
Copy link

zucram commented Jun 11, 2018

@pannal That seems to have fixed it! Thanks a lot.

@pannal
Copy link
Owner

pannal commented Jun 12, 2018

@zucram I've pushed a better fix for the issue to the develop branch. Would you care to try whether the fix is still working? Thank you! Nope, ignore this :)

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

No branches or pull requests

3 participants