"Fix Incorrect Match" not working

ChuckPa · March 4, 2017, 9:24pm

Please check the IPV6 setting in PMS itself. See if it still thinks it’s enabled.

Amazon S3 (where the metadata servers are operating) only support IPv4. That’s an Amazon thing.

Cerebus2 · March 4, 2017, 10:47pm

IPv6 is disabled in PMS, always has been. I’m pretty sure PMS is smart enough to disable it if it can’t bind an IPv6 socket.

instereog · March 4, 2017, 10:57pm

Yeah, as per Cerebus2, my IPV6 has always been disabled in PMS and i still have this issue. Does it have to be disabled in Windows as well? I hope not

Cerebus2 · March 4, 2017, 11:09pm

Near as I can tell, IPv6 is irrelevant to this problem. Some agent appears to be bombing because it’s got an object it thinks should be a zip archive, but isn’t, and then it blocks. This could be a web service fetch error–which may or may not be widespread–or a web service interface change. I need PMS to dump me a stack trace to figure out more. I’ll probably have to turn on verbose logging and see if it shows up there, otherwise I’ll have to start modifying scripts so I can capture stderr for all processes.

ChuckPa · March 4, 2017, 11:09pm

I’m asking for your input because of what I’m seeing across several different 'nix platforms.

There is supposed to be a natural mapping of V6 on V4. This is seen in log files. What also must happen (where I’m focusing) is the pure v6 to v4 translation because of Amazon. IF there has been any kind of regression or , most likely, an incompatibility, this needs to be addressed ASAP.

That’s what I’m trying to resolve… a) what is it? b) capture it c) give it to engineering to finish.

ChuckPa · March 4, 2017, 11:37pm

Ok… Here’s our (myself and the Ninjas) scratching heads and trying to see which rabbit hole this is going down.

tcpdump get the actual traffic and log it
Make it it go for metadata

From that we can figure out what is either a) timing out at the v6 (which modern OS’s prefer) layer before falling back to v4 (which will always work) and/or what is coming back in the data packets (whether a zip or junk or whatever).

ChuckPa · March 5, 2017, 12:01am

@Cerebus2 said:
No effect. This still happens (on stderr) at startup:

2017-03-04T16:55:40.434760768Z Exception AttributeError: “‘ZipArchive’ object has no attribute ‘_zip’” in <bound method ZipArchive.del of <Framework.components.data.ZipArchive object at 0x7f594033ae10>> ignored

From there, when I add media to the library it fails to match and there’s no option to manually match (or fix match) for the new media entry. If I do a Refresh on that item, the Fix Match option reappears (with a stderr output: GUI: Requesting metadata for ‘The Lego Movie’), but the metadata is not loaded. If I run Fix Match from that point, the FIx Incorrect Match dialog comes up; there is an entry in the match list, but it’s empty (the mouseover highlight shows that there’s an entry there, but there’s no text). If I execute a manual search in the Fix Incorrect Match dialog, no data is returned (the “empty” match item is still present). If I select this “empty” item, all metadata is erased from the item, and stderr reports:

GUI: Matching ‘’
GUI: Score for ‘’ (-1) is -1
GUI: Requesting metadata for ‘’

I can see the relevant agents (com.plexapp.system, com.plexapp.agents.themoviedb, & com.plexapp.agents.imdb) in the process table, but clearly something is crashing at startup and it kills matching from there.

I should mention that I’m doing a clean install of PMS each time I test this. I also cleared out the entire plug-in cache. This didn’t help.

– T

What are you matching? I want to recreate the test case. There is the possibility, the data there is just bad. It wouldn’t be the first time we got bad data sent

Cerebus2 · March 5, 2017, 12:29am

OK, don’t try this at home. PMS Test removes your database.

I ran Plex Media Server Test. Only one failed:

[ FAILED ] 1 test, listed below:
[ FAILED ] LibraryHandlerFixtureBlank.TelevisionSectionHubs

However, these tests were interesting. Maybe they don’t mean anything:

[ RUN ] LibraryHandlerTest.MetadataItemRefresh
GUI: Matching ‘Movie A’
GUI: Score for ‘’ (-1) is -1
GUI: Requesting metadata for ‘Movie A’
[ OK ] LibraryHandlerTest.MetadataItemRefresh (5384 ms)

[ RUN ] LibraryHandlerTest.MetadataItemUnmatch
GUI: Matching ‘Movie A’
GUI: Score for ‘’ (-1) is -1
GUI: Requesting metadata for ‘Movie A’
[ OK ] LibraryHandlerTest.MetadataItemUnmatch (5432 ms)

[ RUN ] LibraryHandlerTestForPutLibrarySectionAll.PutLibrarySectionAll_ArtistTitleValue_Move_SingleAlbum_Into_NewArtist
GUI: Matching ‘New Artist’
GUI: Score for ‘’ (-1) is -1
GUI: Requesting metadata for ‘New Artist’
[ OK ] LibraryHandlerTestForPutLibrarySectionAll.PutLibrarySectionAll_ArtistTitleValue_Move_SingleAlbum_Into_NewArtist (5580 ms)

[ RUN ] LibraryHandlerTestForPutLibrarySectionAll.PutLibrarySectionAll_ArtistTitleValue_Move_AllAlbums_Into_NewArtist
GUI: Matching ‘New Artist’
GUI: Score for ‘’ (-1) is -1
GUI: Requesting metadata for ‘New Artist’

[ RUN ] LibraryHandlerTestForPutLibrarySectionAll.PutLibrarySectionAll_ArtistTitleValue_AlbumTitleValue_Move_SingleTrack_Into_NewArtist_NewAlbum
GUI: Matching ‘NewArtist’
GUI: Score for ‘’ (-1) is -1
GUI: Requesting metadata for ‘NewArtist’
[ OK ] LibraryHandlerTestForPutLibrarySectionAll.PutLibrarySectionAll_ArtistTitleValue_AlbumTitleValue_Move_SingleTrack_Into_NewArtist_NewAlbum (5730 ms)
[ RUN ] LibraryHandlerTestForPutLibrarySectionAll.PutLibrarySectionAll_ArtistTitleValue_AlbumTitleValue_Move_AllTracks_Into_NewArtist_NewAlbum
GUI: Matching ‘NewArtist’
GUI: Score for ‘’ (-1) is -1
GUI: Requesting metadata for ‘NewArtist’
[ OK ] LibraryHandlerTestForPutLibrarySectionAll.PutLibrarySectionAll_ArtistTitleValue_AlbumTitleValue_Move_AllTracks_Into_NewArtist_NewAlbum (6463 ms)

[ RUN ] LibraryHandlerTestForPutLibrarySectionAll.PutLibrarySectionAll_Reparenting_Track
GUI: Matching ‘art1’
GUI: Score for ‘’ (-1) is -1
GUI: Requesting metadata for ‘art1’
[ OK ] LibraryHandlerTestForPutLibrarySectionAll.PutLibrarySectionAll_Reparenting_Track (5573 ms)
[ RUN ] LibraryHandlerTestForPutLibrarySectionAll.PutLibrarySectionAll_Reparenting_Album
GUI: Matching ‘art2’
GUI: Score for ‘’ (-1) is -1
GUI: Requesting metadata for ‘art2’
[ OK ] LibraryHandlerTestForPutLibrarySectionAll.PutLibrarySectionAll_Reparenting_Album (5363 ms)
[ RUN ] LibraryHandlerTestForPutLibrarySectionAll.PutLibrarySectionAll_Reparenting_Track_FuzzyAlbumMatching
GUI: Matching ‘Cow Artist’
GUI: Score for ‘’ (-1) is -1
GUI: Requesting metadata for ‘Cow Artist’
[ OK ] LibraryHandlerTestForPutLibrarySectionAll.PutLibrarySectionAll_Reparenting_Track_FuzzyAlbumMatching (5617 ms)

dddjdlux · March 5, 2017, 12:35am

Been having the same metadata issues for a couple weeks now since the last update (not the most recent one). Attached my log files. My friends who have the same movies as me on their network seem to have no issue with metadata so this is all very strange.

ChuckPa · March 5, 2017, 12:51am

@Cerebus2

(All: Apologies for the long post)

As info, I tried “The Lego Movie” (i made a dummy file).

If you wish to compare this with your findings for agents?

Plex Media Scanner Analysis.log:Mar 04, 2017 19:48:56.666 [0x7fa79be54800] DEBUG - Analyzing media parts for item 28355 (The Lego Movie): 40834
Plex Media Scanner Analysis.log:Mar 04, 2017 19:48:56.666 [0x7fa79be54800] DEBUG - [ID 41005] Media part analysis: /syno/test/movies/The Lego Movie/The Lego Movie.mkv
Plex Media Scanner Analysis.log:Mar 04, 2017 19:48:56.666 [0x7fa79be54800] DEBUG - [MI] Opening input file: /syno/test/movies/The Lego Movie/The Lego Movie.mkv
Plex Media Scanner Analysis.log:Mar 04, 2017 19:48:56.667 [0x7fa79be54800] ERROR - Exception analyzing media file '/syno/test/movies/The Lego Movie/The Lego Movie.mkv' (Could not parse /syno/test/movies/The Lego Movie/The Lego Movie.mkv (error=-1094995529): Invalid data found when processing input)
Plex Media Scanner Analysis.log:Mar 04, 2017 19:48:56.668 [0x7fa79be54800] DEBUG - Updating part with ID=41005 [/syno/test/movies/The Lego Movie/The Lego Movie.mkv]
Plex Media Scanner Analysis.log:Mar 04, 2017 19:48:56.741 [0x7fa79be54800] DEBUG - [MI] Opening input file: /syno/test/movies/The Lego Movie/The Lego Movie.mkv
Plex Media Scanner Analysis.log:Mar 04, 2017 19:48:56.741 [0x7fa79be54800] ERROR - Exception extracting thumbnail from media file '/syno/test/movies/The Lego Movie/The Lego Movie.mkv' (Could not parse /syno/test/movies/The Lego Movie/The Lego Movie.mkv (error=-1094995529): Invalid data found when processing input)
Plex Media Scanner Analysis.log:Mar 04, 2017 19:48:56.741 [0x7fa79be54800] DEBUG - [MI] Opening input file: /syno/test/movies/The Lego Movie/The Lego Movie.mkv
Plex Media Scanner Analysis.log:Mar 04, 2017 19:48:56.741 [0x7fa79be54800] ERROR - Exception extracting thumbnail from media file '/syno/test/movies/The Lego Movie/The Lego Movie.mkv' (Could not parse /syno/test/movies/The Lego Movie/The Lego Movie.mkv (error=-1094995529): Invalid data found when processing input)
Plex Media Scanner Analysis.log:Mar 04, 2017 19:48:56.746 [0x7fa79be54800] DEBUG - Updating metadata item (save) (The Lego Movie) with ID 28355
Plex Media Scanner.log:Mar 04, 2017 19:48:29.678 [0x7fe167e8c700] INFO - /usr/lib/plexmediaserver/Plex Media Scanner --scan --refresh --section 12 --directory /syno/test/movies/The Lego Movie
Plex Media Scanner.log:Mar 04, 2017 19:48:30.149 [0x7fe1799d2800] DEBUG -   * Scanning /syno/test/movies/The Lego Movie
Plex Media Scanner.log:Mar 04, 2017 19:48:30.223 [0x7fe1799d2800] DEBUG -     * Scanning directory /syno/test/movies/The Lego Movie (parent: yes)
Plex Media Scanner.log:Mar 04, 2017 19:48:30.224 [0x7fe1799d2800] DEBUG - Adding file for scanner: /syno/test/movies/The Lego Movie/The Lego Movie.mkv
Plex Media Scanner.log:Mar 04, 2017 19:48:30.229 [0x7fe1799d2800] DEBUG -       * Scanning The Lego Movie
Plex Media Scanner.log:Mar 04, 2017 19:48:30.229 [0x7fe1799d2800] DEBUG - Looking for path match for [/syno/test/movies/The Lego Movie/The Lego Movie.mkv]
Plex Media Scanner.log:Mar 04, 2017 19:48:30.234 [0x7fe1799d2800] DEBUG - Added new metadata item (The Lego Movie) with ID 28355
Plex Media Scanner.log:Mar 04, 2017 19:48:30.248 [0x7fe1602e2700] DEBUG - Matching 'The Lego Movie' (ID 28355) with agent com.plexapp.agents.imdb
Plex Media Scanner.log:Mar 04, 2017 19:48:30.250 [0x7fe1602e2700] DEBUG - Issuing search query: http://127.0.0.1:32400/system/agents/search?mediaType=1&id=28355&identifier=com.plexapp.agents.imdb&duration=-1&filename=%252Fsyno%252Ftest%252Fmovies%252FThe%2520Lego%2520Movie%252FThe%2520Lego%2520Movie%252Emkv&lang=en&openSubtitlesHash=&plexHash=120dd6f76b75d752a4d214023536888be82d5f68608&name=The%20Lego%20Movie
Plex Media Scanner.log:Mar 04, 2017 19:48:30.250 [0x7fe1602e2700] DEBUG - HTTP requesting GET http://127.0.0.1:32400/system/agents/search?mediaType=1&id=28355&identifier=com.plexapp.agents.imdb&duration=-1&filename=%252Fsyno%252Ftest%252Fmovies%252FThe%2520Lego%2520Movie%252FThe%2520Lego%2520Movie%252Emkv&lang=en&openSubtitlesHash=&plexHash=120dd6f76b75d752a4d214023536888be82d5f68608&name=The%20Lego%20Movie
Plex Media Scanner.log:Mar 04, 2017 19:48:30.255 [0x7fe1799d2800] DEBUG - Updating directory 'The Lego Movie' (ID 2662) to time 2017-03-04 19:48:24.
Plex Media Scanner.log:Mar 04, 2017 19:48:36.435 [0x7fe1602e2700] DEBUG - HTTP 200 response from GET http://127.0.0.1:32400/system/agents/search?mediaType=1&id=28355&identifier=com.plexapp.agents.imdb&duration=-1&filename=%252Fsyno%252Ftest%252Fmovies%252FThe%2520Lego%2520Movie%252FThe%2520Lego%2520Movie%252Emkv&lang=en&openSubtitlesHash=&plexHash=120dd6f76b75d752a4d214023536888be82d5f68608&name=The%20Lego%20Movie
Plex Media Scanner.log:Mar 04, 2017 19:48:36.435 [0x7fe1602e2700] DEBUG -  99: The Lego Movie ()
Plex Media Scanner.log:Mar 04, 2017 19:48:36.435 [0x7fe1602e2700] DEBUG -  * Score: 99 (The Lego Movie)
Plex Media Scanner.log:Mar 04, 2017 19:48:36.435 [0x7fe1602e2700] DEBUG - Setting GUID for metadata item 28355 (title: The Lego Movie) to com.plexapp.agents.imdb://tt1490017?lang=en (thumb=)
Plex Media Scanner.log:Mar 04, 2017 19:48:36.440 [0x7fe1602e2700] DEBUG - Updating metadata item (save) (The Lego Movie) with ID 28355
Plex Media Scanner.log:Mar 04, 2017 19:48:36.497 [0x7fe1602e2700] DEBUG - Updating metadata item (save) (The Lego Movie) with ID 28355
Plex Media Scanner.log:Mar 04, 2017 19:48:36.509 [0x7fe1602e2700] DEBUG - Refreshing metadata for 'The Lego Movie' (agent: com.plexapp.agents.imdb)
Plex Media Scanner.log:Mar 04, 2017 19:48:36.523 [0x7fe1602e2700] DEBUG - Updating metadata item (save) (The Lego Movie) with ID 28355
Plex Media Scanner.log:Mar 04, 2017 19:48:36.563 [0x7fe1602e2700] DEBUG - [ID 41005] Media part analysis: /syno/test/movies/The Lego Movie/The Lego Movie.mkv
Plex Media Scanner.log:Mar 04, 2017 19:48:36.563 [0x7fe1602e2700] DEBUG - [MI] Opening input file: /syno/test/movies/The Lego Movie/The Lego Movie.mkv
Plex Media Scanner.log:Mar 04, 2017 19:48:36.614 [0x7fe1602e2700] ERROR - Exception analyzing media file '/syno/test/movies/The Lego Movie/The Lego Movie.mkv' (Could not parse /syno/test/movies/The Lego Movie/The Lego Movie.mkv (error=-1094995529): Invalid data found when processing input)
Plex Media Scanner.log:Mar 04, 2017 19:48:36.615 [0x7fe1602e2700] DEBUG - Updating part with ID=41005 [/syno/test/movies/The Lego Movie/The Lego Movie.mkv]
Plex Media Scanner.log:Mar 04, 2017 19:48:36.693 [0x7fe1602e2700] DEBUG - [MI] Opening input file: /syno/test/movies/The Lego Movie/The Lego Movie.mkv
Plex Media Scanner.log:Mar 04, 2017 19:48:36.694 [0x7fe1602e2700] ERROR - Exception extracting thumbnail from media file '/syno/test/movies/The Lego Movie/The Lego Movie.mkv' (Could not parse /syno/test/movies/The Lego Movie/The Lego Movie.mkv (error=-1094995529): Invalid data found when processing input)
Plex Media Scanner.log:Mar 04, 2017 19:48:36.694 [0x7fe1602e2700] DEBUG - [MI] Opening input file: /syno/test/movies/The Lego Movie/The Lego Movie.mkv
Plex Media Scanner.log:Mar 04, 2017 19:48:36.694 [0x7fe1602e2700] ERROR - Exception extracting thumbnail from media file '/syno/test/movies/The Lego Movie/The Lego Movie.mkv' (Could not parse /syno/test/movies/The Lego Movie/The Lego Movie.mkv (error=-1094995529): Invalid data found when processing input)
Plex Media Scanner.log:Mar 04, 2017 19:48:36.697 [0x7fe1602e2700] DEBUG - Updating metadata item (save) (The Lego Movie) with ID 28355
Plex Media Server.log:Mar 04, 2017 19:47:56.223 [0x7f56acbfe700] DEBUG - [Notify] New directory: /syno/test/movies/The Lego Movie, adding recursively.
Plex Media Server.log:Mar 04, 2017 19:47:56.223 [0x7f56acbfe700] DEBUG - [Notify] Now watching /syno/test/movies/The Lego Movie
Plex Media Server.log:Mar 04, 2017 19:48:24.508 [0x7f56acbfe700] INFO - Library section 12 (Test Movies) will be updated because of a change in /syno/test/movies/The Lego Movie
Plex Media Server.log:Mar 04, 2017 19:48:29.524 [0x7f56967fe700] DEBUG - Library Updater: Requested that section 12 be updated, force=0, deep=0, subdir=/syno/test/movies/The Lego Movie iTunes=0
Plex Media Server.log:Mar 04, 2017 19:48:29.525 [0x7f56bebff700] DEBUG - Job running: EAE_ROOT='/var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Cache/Transcode/Sessions/EasyAudioEncoder' FFMPEG_EXTERNAL_LIBS='/var/lib/plexmediaserver/Library/Application\ Support/Plex\ Media\ Server/Codecs/584154a-1188-linux-ubuntu-x86_64/' X_PLEX_TOKEN='xxxxxxxxxxxxxxxxxxxx' '/usr/lib/plexmediaserver/Plex Media Scanner' '--scan' '--refresh' '--section' '12' '--directory' '/syno/test/movies/The Lego Movie'
Plex Media Server.log:Mar 04, 2017 19:48:30.251 [0x7f56b47ff700] DEBUG - Request: [127.0.0.1:59044 (Loopback)] GET /system/agents/search?mediaType=1&id=28355&identifier=com.plexapp.agents.imdb&duration=-1&filename=%252Fsyno%252Ftest%252Fmovies%252FThe%2520Lego%2520Movie%252FThe%2520Lego%2520Movie%252Emkv&lang=en&openSubtitlesHash=&plexHash=120dd6f76b75d752a4d214023536888be82d5f68608&name=The%20Lego%20Movie (5 live) GZIP Signed-in
Plex Media Server.log:Mar 04, 2017 19:48:30.251 [0x7f56b47ff700] DEBUG - [com.plexapp.system] Sending command over HTTP (GET): /system/agents/search?mediaType=1&id=28355&identifier=com.plexapp.agents.imdb&duration=-1&filename=%252Fsyno%252Ftest%252Fmovies%252FThe%2520Lego%2520Movie%252FThe%2520Lego%2520Movie%252Emkv&lang=en&openSubtitlesHash=&plexHash=120dd6f76b75d752a4d214023536888be82d5f68608&name=The%20Lego%20Movie
Plex Media Server.log:Mar 04, 2017 19:48:30.252 [0x7f56b47ff700] DEBUG - HTTP requesting GET http://127.0.0.1:44605/system/agents/search?mediaType=1&id=28355&identifier=com.plexapp.agents.imdb&duration=-1&filename=%252Fsyno%252Ftest%252Fmovies%252FThe%2520Lego%2520Movie%252FThe%2520Lego%2520Movie%252Emkv&lang=en&openSubtitlesHash=&plexHash=120dd6f76b75d752a4d214023536888be82d5f68608&name=The%20Lego%20Movie
Plex Media Server.log:Mar 04, 2017 19:48:36.434 [0x7f56b47ff700] DEBUG - HTTP 200 response from GET http://127.0.0.1:44605/system/agents/search?mediaType=1&id=28355&identifier=com.plexapp.agents.imdb&duration=-1&filename=%252Fsyno%252Ftest%252Fmovies%252FThe%2520Lego%2520Movie%252FThe%2520Lego%2520Movie%252Emkv&lang=en&openSubtitlesHash=&plexHash=120dd6f76b75d752a4d214023536888be82d5f68608&name=The%20Lego%20Movie
Plex Media Server.log:Mar 04, 2017 19:48:36.435 [0x7f56c83fe700] DEBUG - Completed: [127.0.0.1:59044] 200 GET /system/agents/search?mediaType=1&id=28355&identifier=com.plexapp.agents.imdb&duration=-1&filename=%252Fsyno%252Ftest%252Fmovies%252FThe%2520Lego%2520Movie%252FThe%2520Lego%2520Movie%252Emkv&lang=en&openSubtitlesHash=&plexHash=120dd6f76b75d752a4d214023536888be82d5f68608&name=The%20Lego%20Movie (8 live) GZIP 6183ms 547 bytes
Plex Media Server.log:Mar 04, 2017 19:48:44.637 [0x7f56967fe700] DEBUG - Loading Movie 'The Lego Movie' XML from /var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Metadata/Movies/e/e9006a44583d79311312c9999657244780682a4.bundle/Contents/_combined/
Plex Media Server.log:Mar 04, 2017 19:48:44.638 [0x7f56967fe700] DEBUG - Item 28355 (The Lego Movie) Scanning metadata graphic elements in XML file /Info.xml
Plex Media Server.log:Mar 04, 2017 19:48:44.987 [0x7f56967fe700] DEBUG - Item 28355 (The Lego Movie) Scanning metadata graphic elements in XML file /Info.xml
Plex Media Server.log:Mar 04, 2017 19:48:45.299 [0x7f56967fe700] DEBUG - Doing expensive tags write for 'The Lego Movie' because something changed.
Plex Media Server.log:Mar 04, 2017 19:48:45.334 [0x7f56967fe700] DEBUG - Doing expensive tags write for 'The Lego Movie' because something changed.
Plex Media Server.log:Mar 04, 2017 19:48:45.384 [0x7f56967fe700] DEBUG - Doing expensive tags write for 'The Lego Movie' because something changed.
Plex Media Server.log:Mar 04, 2017 19:48:45.470 [0x7f56967fe700] DEBUG - Doing expensive tags write for 'The Lego Movie' because something changed.
Plex Media Server.log:Mar 04, 2017 19:48:45.505 [0x7f56967fe700] DEBUG - Doing expensive tags write for 'The Lego Movie' because something changed.
Plex Media Server.log:Mar 04, 2017 19:48:45.520 [0x7f56967fe700] DEBUG - Doing expensive tags write for 'The Lego Movie' because something changed.
Plex Media Server.log:Mar 04, 2017 19:48:45.529 [0x7f56967fe700] DEBUG - Doing expensive tags write for 'The Lego Movie' because something changed.
Plex Media Server.log:Mar 04, 2017 19:48:45.545 [0x7f56967fe700] DEBUG - Updating metadata item (save) (The Lego Movie) with ID 28355
Plex Media Server.log:Mar 04, 2017 19:48:45.554 [0x7f56967fe700] DEBUG - Doing expensive tags write for 'The Lego Movie' because something changed.
Plex Media Server.log:Mar 04, 2017 19:48:45.562 [0x7f56967fe700] DEBUG - Updating metadata item (save) (The Lego Movie) with ID 28355
Plex Media Server.log:Mar 04, 2017 19:48:45.574 [0x7f56967fe700] DEBUG - Extras: Checked extra 'The Lego Movie' and found matched: 0 Media matched: 0
Plex Media Server.log:Mar 04, 2017 19:48:45.574 [0x7f56967fe700] DEBUG - Added new metadata item (The Lego Movie) with ID 28356
Plex Media Server.log:Mar 04, 2017 19:48:45.575 [0x7f56967fe700] DEBUG - Updating metadata item (save) (The Lego Movie) with ID 28356
Plex Media Server.log:Mar 04, 2017 19:48:45.588 [0x7f56967fe700] DEBUG - Extras: Checked extra 'Will Arnett On the lego Batman' and found matched: 0 Media matched: 0
Plex Media Server.log:Mar 04, 2017 19:48:45.589 [0x7f56967fe700] DEBUG - Added new metadata item (Will Arnett On the lego Batman) with ID 28359
Plex Media Server.log:Mar 04, 2017 19:48:45.589 [0x7f56967fe700] DEBUG - Updating metadata item (save) (Will Arnett On the lego Batman) with ID 28359
Plex Media Server.log:Mar 04, 2017 19:48:46.303 [0x7f56967fe700] DEBUG - Loaded metadata for The Lego Movie (ID 28355) in 580.000000 ms
Plex Media Server.log:Mar 04, 2017 19:48:46.303 [0x7f56967fe700] DEBUG - There was a change for metadata item 28355 (The Lego Movie), saving.
Plex Media Server.log:Mar 04, 2017 19:48:46.303 [0x7f56967fe700] DEBUG - Updating metadata item (save) (The Lego Movie) with ID 28355
PMS Plugin Logs/com.plexapp.system.log:2017-03-04 19:48:30,252 (7f29c8fb9700) :  DEBUG (runtime:717) - Handling request GET /system/agents/search?mediaType=1&id=28355&identifier=com.plexapp.agents.imdb&duration=-1&filename=%252Fsyno%252Ftest%252Fmovies%252FThe%2520Lego%2520Movie%252FThe%2520Lego%2520Movie%252Emkv&lang=en&openSubtitlesHash=&plexHash=120dd6f76b75d752a4d214023536888be82d5f68608&name=The%20Lego%20Movie
PMS Plugin Logs/com.plexapp.system.log:2017-03-04 19:48:30,257 (7f29c8fb9700) :  INFO (agentservice:220) - Searching for Movie in com.plexapp.agents.imdb ({'openSubtitlesHash': None, 'name': 'The Lego Movie', 'filename': '%2Fsyno%2Ftest%2Fmovies%2FThe%20Lego%20Movie%2FThe%20Lego%20Movie%2Emkv', 'plexHash': '120dd6f76b75d752a4d214023536888be82d5f68608', 'duration': '-1', 'id': '28355'})
PMS Plugin Logs/com.plexapp.agents.localmedia.log:2017-03-04 19:48:44,605 (7f8807fff700) :  INFO (localmedia:198) - Looking for local extras in path: /syno/test/movies/The Lego Movie
PMS Plugin Logs/com.plexapp.agents.localmedia.log:2017-03-04 19:48:44,606 (7f8807fff700) :  INFO (localmedia:198) - Looking for movie media (The Lego Movie) in 1 paths (root file: The Lego Movie) with 1 media files.
PMS Plugin Logs/com.plexapp.agents.localmedia.log:2017-03-04 19:48:44,606 (7f8807fff700) :  INFO (localmedia:198) - Paths: /syno/test/movies/The Lego Movie
PMS Plugin Logs/com.plexapp.agents.localmedia.log:2017-03-04 19:48:44,608 (7f8807fff700) :  INFO (localmedia:225) - Found 0 valid things for pattern (poster|default|cover|movie|folder|The\ Lego\ Movie)-?[0-9]? (ext: ['jpg', 'png', 'jpeg', 'tbn'])
PMS Plugin Logs/com.plexapp.agents.localmedia.log:2017-03-04 19:48:44,609 (7f8807fff700) :  INFO (localmedia:225) - Found 0 valid things for pattern (fanart|art|background|backdrop|The\ Lego\ Movie-fanart)-?[0-9]? (ext: ['jpg', 'png', 'jpeg', 'tbn'])
PMS Plugin Logs/com.plexapp.agents.localmedia.log:2017-03-04 19:48:44,609 (7f8807fff700) :  INFO (localmedia:276) - Paths: /syno/test/movies/The Lego Movie
PMS Plugin Logs/com.plexapp.agents.imdb.log:2017-03-04 19:48:33,341 (7fb03e7fc700) :  INFO (agentkit:957) - Searching for matches for {'openSubtitlesHash': None, 'name': 'The Lego Movie', 'filename': '%2Fsyno%2Ftest%2Fmovies%2FThe%20Lego%20Movie%2FThe%20Lego%20Movie%2Emkv', 'plexHash': '120dd6f76b75d752a4d214023536888be82d5f68608', 'duration': '-1', 'id': '28355'}
PMS Plugin Logs/com.plexapp.agents.imdb.log:2017-03-04 19:48:33,667 (7fb03e7fc700) :  INFO (__init__:182) - Scoring {'tt1490017': [0, u'The Lego Movie', u'2014', 99, 182169, 0], 'tt2465238': [6, u'Lego: Batman', u'2013', 0, 34, 0]}
PMS Plugin Logs/com.plexapp.agents.imdb.log:2017-03-04 19:48:33,667 (7fb03e7fc700) :  INFO (__init__:486) - {'tt1490017': [0, u'The Lego Movie', u'2014', 99, 182169, 99], 'tt2465238': [6, u'Lego: Batman', u'2013', 0, 34, 64]}
PMS Plugin Logs/com.plexapp.agents.imdb.log:2017-03-04 19:48:35,847 (7fb03e7fc700) :  INFO (__init__:494) - Adding title_year match: The Lego Movie (2014) score=99, key=tt1490017
PMS Plugin Logs/com.plexapp.agents.imdb.log:2017-03-04 19:48:35,848 (7fb03e7fc700) :  INFO (__init__:500) - Skipping title/year match (doesn't meet percentage threshold): Lego: Batman (2013) percentage=0
PMS Plugin Logs/com.plexapp.agents.imdb.log:2017-03-04 19:48:42,700 (7fb03e7fc700) :  DEBUG (networking:166) - Requesting 'https://chapterdb.plex.tv/chapters/search?title=The%20Lego%20Movie'
[chuck@lizum Logs.123]$ ```

Cerebus2 · March 5, 2017, 12:52am

Since PMS Test deleted my database, I started with a clean 1.4.3 server–new install, no database, no media in any libraries. 1.4.3 fails to match any media, including any media that had previously matched with no problem.

Then I rolled back to 1.3.4–again, new install, no database, no libraries. 1.3.4 fails to match any media.

In both cases I’m still getting that zip archive exception on PMS’ stderr.

Attached is the PMS logs for 1.4.3 where I add a single item (the movie Zulu) and it fails to match. All behavior is exactly as described in previous posts.

Damnfino what’s going on. A clean install eliminates any possible local database issue. I’m adding a single item that was previously matched to the clean database and it fails. This has got to be a change in one of the services PMS depends on for metadata because it happens in 1.3.4 but didn’t occur in 1.3.4 a back on 20 Feb (the last time I added anything to the media library, which successfully matched).

(edited to actually attach the logs. Duh.)

Cerebus2 · March 5, 2017, 1:01am

Post seems to have gone bye-bye, so sorry of this duplicates.

Attached are logs for a clean 1.4.3 install (no database, new empty library) where I added a new media item (Zulu) which had previously matched metadata without issues.

The same behavior happens with a clean 1.3.4 install with the same file. I didn’t bother to attach the log for that, but if you want it I can generate one.

Whatever problem this is dates from some time after 20 Feb. On 20 Feb I added a batch of media items, and they matched metadata without any problems. These items now fail to match. I don’t recall when I updated PMS to 1.3.4, so it’s possible that on 20 Feb I was running an even older version. I tend to slack on PMS updates.

Cerebus2 · March 5, 2017, 1:33am

@ChuckPA said:
@Cerebus2

(All: Apologies for the long post)

As info, I tried “The Lego Movie” (i made a dummy file).

If you wish to compare this with your findings for agents?

Yeah, well, I found this in my log:

Mar 04, 2017 18:46:09.728 [0x7feb543ff700] DEBUG - HTTP 401 response from GET http://127.0.0.1:32400/system/agents/search?mediaType=1&id=1&identifier=com.plexapp.agents.imdb&duration=8303896&filename=%252Fdata%252FMovies%252FZulu%2520(1964)%252FZulu%2520(1964)%252Emp4&lang=en&openSubtitlesHash=4ddd3aec38407bbe&plexHash=975988c485b8056d4e1de4347d5f54a364003ac0&name=Zulu&year=1964&manual=1
Mar 04, 2017 18:46:09.728 [0x7feb543ff700] DEBUG - -1: ()
Mar 04, 2017 18:46:09.728 [0x7feb543ff700] DEBUG - -1: ()
Mar 04, 2017 18:46:09.728 [0x7feb543ff700] DEBUG - It took 0.0 sec to serialize a list with 2 elements.
Mar 04, 2017 18:46:09.729 [0x7feb56bff700] DEBUG - Completed: [192.168.86.101:40280] 200 GET /library/metadata/1/matches?manual=1 (4 live) GZIP 4ms 514 bytes (pipelined: 16)

So near as I can tell–and lacking knowledge of PMS and plugin internals, I’m just guessing–PMS issues the search command, gets a 401 (unauthorized) response, then the plugin wipes the metadata. Subsequent queries have no actual search string, so they all fail.

What’s unauthorized and where is anyone’s guess. The GET is to localhost, so that should be PMS components talking to one another, so a 401 should never happen.

Cerebus2 · March 5, 2017, 1:37am

BTW, I just noticed that none of my Agent settings are sticking.

This is a clean damn install. WTF is going on?

Cerebus2 · March 5, 2017, 3:02am

OK, as far as I can tell, this is the root cause, or damn close to it. The metadata plugin isn’t authorized. Every time the plugin tells the server to fetch metadata, PMS returns 401 Unauthorized. The snipped below is a manual match invocation on the movie Zulu.

On a lark, I signed the server out, signed out at the plex.tv site, then signed back in and reclaimed the server. This had no effect.

– T

Mar 04, 2017 20:33:07.422 [0x7fd57a7ff700] DEBUG - Auth: We found auth token (xxxxxxxxxxxxxxxxxxxx), enabling token-based authentication.
Mar 04, 2017 20:33:07.422 [0x7fd57a7ff700] DEBUG - Auth: authenticated user 1 as Cerebus2
Mar 04, 2017 20:33:07.422 [0x7fd57a7ff700] DEBUG - Auth: Came in with a super-token, authorization succeeded.
Mar 04, 2017 20:33:07.422 [0x7fd55fffe700] DEBUG - Request: [192.168.86.101:41269 (Subnet)] PUT /library/metadata/1/match?guid=&name= (4 live) GZIP Signed-in Token (Cerebus2)
Mar 04, 2017 20:33:07.423 [0x7fd55fffe700] DEBUG - Setting GUID for metadata item 1 (title: ) to (thumb=)
Mar 04, 2017 20:33:07.425 [0x7fd55fffe700] DEBUG - Migrating metadata settings from local://1 ->
Mar 04, 2017 20:33:07.425 [0x7fd55fffe700] DEBUG - Updating metadata item (save) (Zulu) with ID 1
Mar 04, 2017 20:33:07.461 [0x7fd55fffe700] DEBUG - No match for item 1’s GUID , we’re just changing its identity.
Mar 04, 2017 20:33:07.462 [0x7fd55fffe700] DEBUG - Updating metadata item (save) () with ID 1
Mar 04, 2017 20:33:07.472 [0x7fd55fffe700] DEBUG - Matching ‘’ (ID 1) with agent
Mar 04, 2017 20:33:07.475 [0x7fd55fffe700] DEBUG - Issuing search query: http://127.0.0.1:32400/system/agents/search?mediaType=1&id=1&identifier=com.plexapp.agents.imdb&duration=8303896&filename=%2Fhome%2Fcerebus%2Fplexdata%2Fdata%2FMovies%2FZulu%20(1964)%2FZulu%20(1964)%2Emp4&lang=en&openSubtitlesHash=4ddd3aec38407bbe&plexHash=975988c485b8056d4e1de4347d5f54a364003ac0&name=Zulu&year=1964
Mar 04, 2017 20:33:07.475 [0x7fd55fffe700] DEBUG - HTTP requesting GET http://127.0.0.1:32400/system/agents/search?mediaType=1&id=1&identifier=com.plexapp.agents.imdb&duration=8303896&filename=%2Fhome%2Fcerebus%2Fplexdata%2Fdata%2FMovies%2FZulu%20(1964)%2FZulu%20(1964)%2Emp4&lang=en&openSubtitlesHash=4ddd3aec38407bbe&plexHash=975988c485b8056d4e1de4347d5f54a364003ac0&name=Zulu&year=1964
Mar 04, 2017 20:33:07.475 [0x7fd579ffe700] DEBUG - Request: [192.168.86.254:38698 (WAN)] GET /system/agents/search?mediaType=1&id=1&identifier=com.plexapp.agents.imdb&duration=8303896&filename=%252Fhome%252Fcerebus%252Fplexdata%252Fdata%252FMovies%252FZulu%2520(1964)%252FZulu%2520(1964)%252Emp4&lang=en&openSubtitlesHash=4ddd3aec38407bbe&plexHash=975988c485b8056d4e1de4347d5f54a364003ac0&name=Zulu&year=1964 (5 live) GZIP Signed-in
Mar 04, 2017 20:33:07.476 [0x7fd579ffe700] DEBUG - Completed: [192.168.86.254:38698] 401 GET /system/agents/search?mediaType=1&id=1&identifier=com.plexapp.agents.imdb&duration=8303896&filename=%252Fhome%252Fcerebus%252Fplexdata%252Fdata%252FMovies%252FZulu%2520(1964)%252FZulu%2520(1964)%252Emp4&lang=en&openSubtitlesHash=4ddd3aec38407bbe&plexHash=975988c485b8056d4e1de4347d5f54a364003ac0&name=Zulu&year=1964 (5 live) GZIP 0ms 338 bytes
Mar 04, 2017 20:33:07.476 [0x7fd55fffe700] DEBUG - HTTP 401 response from GET http://127.0.0.1:32400/system/agents/search?mediaType=1&id=1&identifier=com.plexapp.agents.imdb&duration=8303896&filename=%2Fhome%2Fcerebus%2Fplexdata%2Fdata%2FMovies%2FZulu%20(1964)%2FZulu%20(1964)%2Emp4&lang=en&openSubtitlesHash=4ddd3aec38407bbe&plexHash=975988c485b8056d4e1de4347d5f54a364003ac0&name=Zulu&year=1964
Mar 04, 2017 20:33:07.476 [0x7fd55fffe700] DEBUG - -1: ()
Mar 04, 2017 20:33:07.476 [0x7fd55fffe700] DEBUG - -1: ()
Mar 04, 2017 20:33:07.476 [0x7fd55fffe700] DEBUG - * Score: -1 ()
Mar 04, 2017 20:33:07.476 [0x7fd55fffe700] DEBUG - Refreshing metadata for ‘’ (agent: )
Mar 04, 2017 20:33:07.476 [0x7fd55fffe700] DEBUG - Refreshing GUID: ‘’
Mar 04, 2017 20:33:07.476 [0x7fd55fffe700] DEBUG - HTTP requesting GET http://127.0.0.1:32400/system/agents/update?mediaType=1&force=1&guid=&id=1
Mar 04, 2017 20:33:07.477 [0x7fd579ffe700] DEBUG - Request: [192.168.86.254:38700 (WAN)] GET /system/agents/update?mediaType=1&force=1&guid=&id=1 (5 live) GZIP Signed-in
Mar 04, 2017 20:33:07.477 [0x7fd579ffe700] DEBUG - Completed: [192.168.86.254:38700] 401 GET /system/agents/update?mediaType=1&force=1&guid=&id=1 (5 live) GZIP 0ms 338 bytes
Mar 04, 2017 20:33:07.477 [0x7fd55fffe700] DEBUG - HTTP 401 response from GET http://127.0.0.1:32400/system/agents/update?mediaType=1&force=1&guid=&id=1
Mar 04, 2017 20:33:07.478 [0x7fd55fffe700] ERROR - Error response for update: ().

ChuckPa · March 5, 2017, 3:57am

I repeated with your title name. The results are as follows . Now to find out what is different between your machine and mine. (My next post).

[chuck@lizum Logs.148]$ grep -iR zulu *
Plex Media Scanner Analysis.log:Mar 04, 2017 22:54:11.289 [0x7fe2eb144800] DEBUG - Analyzing media parts for item 28368 (Zulu): 40884
Plex Media Scanner Analysis.log:Mar 04, 2017 22:54:11.289 [0x7fe2eb144800] DEBUG - [ID 41055] Media part analysis: /syno/test/movies/Zulu (1964)/Zulu (1964).mkv
Plex Media Scanner Analysis.log:Mar 04, 2017 22:54:11.289 [0x7fe2eb144800] DEBUG - [MI] Opening input file: /syno/test/movies/Zulu (1964)/Zulu (1964).mkv
Plex Media Scanner Analysis.log:Mar 04, 2017 22:54:11.290 [0x7fe2eb144800] ERROR - Exception analyzing media file '/syno/test/movies/Zulu (1964)/Zulu (1964).mkv' (Could not parse /syno/test/movies/Zulu (1964)/Zulu (1964).mkv (error=-1094995529): Invalid data found when processing input)
Plex Media Scanner Analysis.log:Mar 04, 2017 22:54:11.291 [0x7fe2eb144800] DEBUG - Updating part with ID=41055 [/syno/test/movies/Zulu (1964)/Zulu (1964).mkv]
Plex Media Scanner Analysis.log:Mar 04, 2017 22:54:11.841 [0x7fe2eb144800] DEBUG - [MI] Opening input file: /syno/test/movies/Zulu (1964)/Zulu (1964).mkv
Plex Media Scanner Analysis.log:Mar 04, 2017 22:54:11.842 [0x7fe2eb144800] ERROR - Exception extracting thumbnail from media file '/syno/test/movies/Zulu (1964)/Zulu (1964).mkv' (Could not parse /syno/test/movies/Zulu (1964)/Zulu (1964).mkv (error=-1094995529): Invalid data found when processing input)
Plex Media Scanner Analysis.log:Mar 04, 2017 22:54:11.842 [0x7fe2eb144800] DEBUG - [MI] Opening input file: /syno/test/movies/Zulu (1964)/Zulu (1964).mkv
Plex Media Scanner Analysis.log:Mar 04, 2017 22:54:11.843 [0x7fe2eb144800] ERROR - Exception extracting thumbnail from media file '/syno/test/movies/Zulu (1964)/Zulu (1964).mkv' (Could not parse /syno/test/movies/Zulu (1964)/Zulu (1964).mkv (error=-1094995529): Invalid data found when processing input)
Plex Media Scanner Analysis.log:Mar 04, 2017 22:54:11.851 [0x7fe2eb144800] DEBUG - Updating metadata item (save) (Zulu) with ID 28368
Plex Media Scanner.log:Mar 04, 2017 22:52:30.891 [0x7fc14628c700] INFO - /usr/lib/plexmediaserver/Plex Media Scanner --scan --refresh --section 12 --directory /syno/test/movies/Zulu (1964)
Plex Media Scanner.log:Mar 04, 2017 22:52:31.769 [0x7fc157ecf800] DEBUG -   * Scanning /syno/test/movies/Zulu (1964)
Plex Media Scanner.log:Mar 04, 2017 22:52:31.807 [0x7fc157ecf800] DEBUG -     * Scanning directory /syno/test/movies/Zulu (1964) (parent: yes)
Plex Media Scanner.log:Mar 04, 2017 22:52:31.809 [0x7fc157ecf800] DEBUG - Adding file for scanner: /syno/test/movies/Zulu (1964)/Zulu (1964).mkv
Plex Media Scanner.log:Mar 04, 2017 22:52:31.820 [0x7fc157ecf800] DEBUG -       * Scanning Zulu (1964)
Plex Media Scanner.log:Mar 04, 2017 22:52:31.820 [0x7fc157ecf800] DEBUG - Looking for path match for [/syno/test/movies/Zulu (1964)/Zulu (1964).mkv]
Plex Media Scanner.log:Mar 04, 2017 22:52:31.841 [0x7fc157ecf800] DEBUG - Added new metadata item (Zulu) with ID 28368
Plex Media Scanner.log:Mar 04, 2017 22:52:31.903 [0x7fc13e98c700] DEBUG - Matching 'Zulu' (ID 28368) with agent com.plexapp.agents.imdb
Plex Media Scanner.log:Mar 04, 2017 22:52:31.908 [0x7fc13e98c700] DEBUG - Issuing search query: http://127.0.0.1:32400/system/agents/search?mediaType=1&id=28368&identifier=com.plexapp.agents.imdb&duration=-1&filename=%252Fsyno%252Ftest%252Fmovies%252FZulu%2520(1964)%252FZulu%2520(1964)%252Emkv&lang=en&openSubtitlesHash=&plexHash=73587982becf1ba78faca61c57d48fe9e50070ac08&name=Zulu&year=1964
Plex Media Scanner.log:Mar 04, 2017 22:52:31.908 [0x7fc13e98c700] DEBUG - HTTP requesting GET http://127.0.0.1:32400/system/agents/search?mediaType=1&id=28368&identifier=com.plexapp.agents.imdb&duration=-1&filename=%252Fsyno%252Ftest%252Fmovies%252FZulu%2520(1964)%252FZulu%2520(1964)%252Emkv&lang=en&openSubtitlesHash=&plexHash=73587982becf1ba78faca61c57d48fe9e50070ac08&name=Zulu&year=1964
Plex Media Scanner.log:Mar 04, 2017 22:52:31.908 [0x7fc157ecf800] DEBUG - Updating directory 'Zulu (1964)' (ID 2663) to time 2017-03-04 22:52:25.
Plex Media Scanner.log:Mar 04, 2017 22:52:37.944 [0x7fc13e98c700] DEBUG - HTTP 200 response from GET http://127.0.0.1:32400/system/agents/search?mediaType=1&id=28368&identifier=com.plexapp.agents.imdb&duration=-1&filename=%252Fsyno%252Ftest%252Fmovies%252FZulu%2520(1964)%252FZulu%2520(1964)%252Emkv&lang=en&openSubtitlesHash=&plexHash=73587982becf1ba78faca61c57d48fe9e50070ac08&name=Zulu&year=1964
Plex Media Scanner.log:Mar 04, 2017 22:52:37.944 [0x7fc13e98c700] DEBUG -  99: Zulu ()
Plex Media Scanner.log:Mar 04, 2017 22:52:37.944 [0x7fc13e98c700] DEBUG -  * Score: 99 (Zulu)
Plex Media Scanner.log:Mar 04, 2017 22:52:37.944 [0x7fc13e98c700] DEBUG - Setting GUID for metadata item 28368 (title: Zulu) to com.plexapp.agents.imdb://tt0058777?lang=en (thumb=)
Plex Media Scanner.log:Mar 04, 2017 22:52:37.949 [0x7fc13e98c700] DEBUG - Updating metadata item (save) (Zulu) with ID 28368
Plex Media Scanner.log:Mar 04, 2017 22:52:38.022 [0x7fc13e98c700] DEBUG - Updating metadata item (save) (Zulu) with ID 28368
Plex Media Scanner.log:Mar 04, 2017 22:52:38.036 [0x7fc13e98c700] DEBUG - Refreshing metadata for 'Zulu' (agent: com.plexapp.agents.imdb)
Plex Media Scanner.log:Mar 04, 2017 22:52:38.049 [0x7fc13e98c700] DEBUG - Updating metadata item (save) (Zulu) with ID 28368
Plex Media Scanner.log:Mar 04, 2017 22:52:38.065 [0x7fc13e98c700] DEBUG - [ID 41055] Media part analysis: /syno/test/movies/Zulu (1964)/Zulu (1964).mkv
Plex Media Scanner.log:Mar 04, 2017 22:52:38.065 [0x7fc13e98c700] DEBUG - [MI] Opening input file: /syno/test/movies/Zulu (1964)/Zulu (1964).mkv
Plex Media Scanner.log:Mar 04, 2017 22:52:38.101 [0x7fc13e98c700] ERROR - Exception analyzing media file '/syno/test/movies/Zulu (1964)/Zulu (1964).mkv' (Could not parse /syno/test/movies/Zulu (1964)/Zulu (1964).mkv (error=-1094995529): Invalid data found when processing input)
Plex Media Scanner.log:Mar 04, 2017 22:52:38.102 [0x7fc13e98c700] DEBUG - Updating part with ID=41055 [/syno/test/movies/Zulu (1964)/Zulu (1964).mkv]
Plex Media Scanner.log:Mar 04, 2017 22:52:38.133 [0x7fc13e98c700] DEBUG - [MI] Opening input file: /syno/test/movies/Zulu (1964)/Zulu (1964).mkv
Plex Media Scanner.log:Mar 04, 2017 22:52:38.134 [0x7fc13e98c700] ERROR - Exception extracting thumbnail from media file '/syno/test/movies/Zulu (1964)/Zulu (1964).mkv' (Could not parse /syno/test/movies/Zulu (1964)/Zulu (1964).mkv (error=-1094995529): Invalid data found when processing input)
Plex Media Scanner.log:Mar 04, 2017 22:52:38.134 [0x7fc13e98c700] DEBUG - [MI] Opening input file: /syno/test/movies/Zulu (1964)/Zulu (1964).mkv
Plex Media Scanner.log:Mar 04, 2017 22:52:38.134 [0x7fc13e98c700] ERROR - Exception extracting thumbnail from media file '/syno/test/movies/Zulu (1964)/Zulu (1964).mkv' (Could not parse /syno/test/movies/Zulu (1964)/Zulu (1964).mkv (error=-1094995529): Invalid data found when processing input)
Plex Media Scanner.log:Mar 04, 2017 22:52:38.137 [0x7fc13e98c700] DEBUG - Updating metadata item (save) (Zulu) with ID 28368
Plex Media Server.log:Mar 04, 2017 22:51:40.420 [0x7f56acbfe700] DEBUG - [Notify] New directory: /syno/test/movies/Zulu (1964), adding recursively.
Plex Media Server.log:Mar 04, 2017 22:51:40.420 [0x7f56acbfe700] DEBUG - [Notify] Now watching /syno/test/movies/Zulu (1964)
Plex Media Server.log:Mar 04, 2017 22:52:25.524 [0x7f56acbfe700] INFO - Library section 12 (Test Movies) will be updated because of a change in /syno/test/movies/Zulu (1964)
Plex Media Server.log:Mar 04, 2017 22:52:30.553 [0x7f56b0bff700] DEBUG - Library Updater: Requested that section 12 be updated, force=0, deep=0, subdir=/syno/test/movies/Zulu (1964) iTunes=0
Plex Media Server.log:Mar 04, 2017 22:52:30.555 [0x7f569b3fe700] DEBUG - Job running: EAE_ROOT='/var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Cache/Transcode/Sessions/EasyAudioEncoder' FFMPEG_EXTERNAL_LIBS='/var/lib/plexmediaserver/Library/Application\ Support/Plex\ Media\ Server/Codecs/584154a-1188-linux-ubuntu-x86_64/' X_PLEX_TOKEN='xxxxxxxxxxxxxxxxxxxx' '/usr/lib/plexmediaserver/Plex Media Scanner' '--scan' '--refresh' '--section' '12' '--directory' '/syno/test/movies/Zulu (1964)'
Plex Media Server.log:Mar 04, 2017 22:52:31.909 [0x7f569bbff700] DEBUG - Request: [127.0.0.1:39278 (Loopback)] GET /system/agents/search?mediaType=1&id=28368&identifier=com.plexapp.agents.imdb&duration=-1&filename=%252Fsyno%252Ftest%252Fmovies%252FZulu%2520(1964)%252FZulu%2520(1964)%252Emkv&lang=en&openSubtitlesHash=&plexHash=73587982becf1ba78faca61c57d48fe9e50070ac08&name=Zulu&year=1964 (13 live) GZIP Signed-in
Plex Media Server.log:Mar 04, 2017 22:52:31.910 [0x7f569bbff700] DEBUG - [com.plexapp.system] Sending command over HTTP (GET): /system/agents/search?mediaType=1&id=28368&identifier=com.plexapp.agents.imdb&duration=-1&filename=%252Fsyno%252Ftest%252Fmovies%252FZulu%2520(1964)%252FZulu%2520(1964)%252Emkv&lang=en&openSubtitlesHash=&plexHash=73587982becf1ba78faca61c57d48fe9e50070ac08&name=Zulu&year=1964
Plex Media Server.log:Mar 04, 2017 22:52:31.910 [0x7f569bbff700] DEBUG - HTTP requesting GET http://127.0.0.1:44605/system/agents/search?mediaType=1&id=28368&identifier=com.plexapp.agents.imdb&duration=-1&filename=%252Fsyno%252Ftest%252Fmovies%252FZulu%2520(1964)%252FZulu%2520(1964)%252Emkv&lang=en&openSubtitlesHash=&plexHash=73587982becf1ba78faca61c57d48fe9e50070ac08&name=Zulu&year=1964
Plex Media Server.log:Mar 04, 2017 22:52:37.943 [0x7f569bbff700] DEBUG - HTTP 200 response from GET http://127.0.0.1:44605/system/agents/search?mediaType=1&id=28368&identifier=com.plexapp.agents.imdb&duration=-1&filename=%252Fsyno%252Ftest%252Fmovies%252FZulu%2520(1964)%252FZulu%2520(1964)%252Emkv&lang=en&openSubtitlesHash=&plexHash=73587982becf1ba78faca61c57d48fe9e50070ac08&name=Zulu&year=1964
Plex Media Server.log:Mar 04, 2017 22:52:37.944 [0x7f56c8bff700] DEBUG - Completed: [127.0.0.1:39278] 200 GET /system/agents/search?mediaType=1&id=28368&identifier=com.plexapp.agents.imdb&duration=-1&filename=%252Fsyno%252Ftest%252Fmovies%252FZulu%2520(1964)%252FZulu%2520(1964)%252Emkv&lang=en&openSubtitlesHash=&plexHash=73587982becf1ba78faca61c57d48fe9e50070ac08&name=Zulu&year=1964 (13 live) GZIP 6034ms 540 bytes
Plex Media Server.log:Mar 04, 2017 22:52:44.412 [0x7f56957fc700] DEBUG - Loading Movie 'Zulu' XML from /var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Metadata/Movies/9/567bca40eac383f3aa3c50f113c05d0fc49a690.bundle/Contents/_combined/
Plex Media Server.log:Mar 04, 2017 22:52:44.412 [0x7f56957fc700] DEBUG - Item 28368 (Zulu) Scanning metadata graphic elements in XML file /Info.xml
Plex Media Server.log:Mar 04, 2017 22:52:44.642 [0x7f56957fc700] DEBUG - Item 28368 (Zulu) Scanning metadata graphic elements in XML file /Info.xml
Plex Media Server.log:Mar 04, 2017 22:52:44.920 [0x7f56957fc700] DEBUG - Doing expensive tags write for 'Zulu' because something changed.
Plex Media Server.log:Mar 04, 2017 22:52:44.937 [0x7f56957fc700] DEBUG - Doing expensive tags write for 'Zulu' because something changed.
Plex Media Server.log:Mar 04, 2017 22:52:44.946 [0x7f56957fc700] DEBUG - Doing expensive tags write for 'Zulu' because something changed.
Plex Media Server.log:Mar 04, 2017 22:52:44.981 [0x7f56957fc700] DEBUG - Doing expensive tags write for 'Zulu' because something changed.
Plex Media Server.log:Mar 04, 2017 22:52:44.989 [0x7f56957fc700] DEBUG - Doing expensive tags write for 'Zulu' because something changed.
Plex Media Server.log:Mar 04, 2017 22:52:44.998 [0x7f56957fc700] DEBUG - Doing expensive tags write for 'Zulu' because something changed.
Plex Media Server.log:Mar 04, 2017 22:52:45.007 [0x7f56957fc700] DEBUG - Doing expensive tags write for 'Zulu' because something changed.
Plex Media Server.log:Mar 04, 2017 22:52:45.014 [0x7f56957fc700] DEBUG - Updating metadata item (save) (Zulu) with ID 28368
Plex Media Server.log:Mar 04, 2017 22:52:45.023 [0x7f56957fc700] DEBUG - Doing expensive tags write for 'Zulu' because something changed.
Plex Media Server.log:Mar 04, 2017 22:52:45.039 [0x7f56957fc700] DEBUG - Updating metadata item (save) (Zulu) with ID 28368
Plex Media Server.log:Mar 04, 2017 22:52:45.049 [0x7f56957fc700] DEBUG - Extras: Checked extra 'Zulu' and found matched: 0 Media matched: 0
Plex Media Server.log:Mar 04, 2017 22:52:45.049 [0x7f56957fc700] DEBUG - Added new metadata item (Zulu) with ID 28369
Plex Media Server.log:Mar 04, 2017 22:52:45.050 [0x7f56957fc700] DEBUG - Updating metadata item (save) (Zulu) with ID 28369
Plex Media Server.log:Mar 04, 2017 22:52:45.065 [0x7f56957fc700] DEBUG - Loaded metadata for Zulu (ID 28368) in 80.000000 ms
Plex Media Server.log:Mar 04, 2017 22:52:45.065 [0x7f56957fc700] DEBUG - There was a change for metadata item 28368 (Zulu), saving.
Plex Media Server.log:Mar 04, 2017 22:52:45.065 [0x7f56957fc700] DEBUG - Updating metadata item (save) (Zulu) with ID 28368
PMS Plugin Logs/com.plexapp.system.log:2017-03-04 22:52:31,912 (7f29c97ba700) :  DEBUG (runtime:717) - Handling request GET /system/agents/search?mediaType=1&id=28368&identifier=com.plexapp.agents.imdb&duration=-1&filename=%252Fsyno%252Ftest%252Fmovies%252FZulu%2520(1964)%252FZulu%2520(1964)%252Emkv&lang=en&openSubtitlesHash=&plexHash=73587982becf1ba78faca61c57d48fe9e50070ac08&name=Zulu&year=1964
PMS Plugin Logs/com.plexapp.system.log:2017-03-04 22:52:31,937 (7f29c97ba700) :  INFO (agentservice:220) - Searching for Movie in com.plexapp.agents.imdb ({'openSubtitlesHash': None, 'name': 'Zulu', 'year': '1964', 'filename': '%2Fsyno%2Ftest%2Fmovies%2FZulu%20(1964)%2FZulu%20(1964)%2Emkv', 'plexHash': '73587982becf1ba78faca61c57d48fe9e50070ac08', 'duration': '-1', 'id': '28368'})
PMS Plugin Logs/com.plexapp.agents.localmedia.log:2017-03-04 22:52:44,384 (7f17dffff700) :  INFO (localmedia:198) - Looking for local extras in path: /syno/test/movies/Zulu (1964)
PMS Plugin Logs/com.plexapp.agents.localmedia.log:2017-03-04 22:52:44,384 (7f17dffff700) :  INFO (localmedia:198) - Looking for movie media (Zulu) in 1 paths (root file: Zulu (1964)) with 1 media files.
PMS Plugin Logs/com.plexapp.agents.localmedia.log:2017-03-04 22:52:44,384 (7f17dffff700) :  INFO (localmedia:198) - Paths: /syno/test/movies/Zulu (1964)
PMS Plugin Logs/com.plexapp.agents.localmedia.log:2017-03-04 22:52:44,386 (7f17dffff700) :  INFO (localmedia:225) - Found 0 valid things for pattern (poster|default|cover|movie|folder|Zulu\ \(1964\))-?[0-9]? (ext: ['jpg', 'png', 'jpeg', 'tbn'])
PMS Plugin Logs/com.plexapp.agents.localmedia.log:2017-03-04 22:52:44,387 (7f17dffff700) :  INFO (localmedia:225) - Found 0 valid things for pattern (fanart|art|background|backdrop|Zulu\ \(1964\)-fanart)-?[0-9]? (ext: ['jpg', 'png', 'jpeg', 'tbn'])
PMS Plugin Logs/com.plexapp.agents.localmedia.log:2017-03-04 22:52:44,388 (7f17dffff700) :  INFO (localmedia:276) - Paths: /syno/test/movies/Zulu (1964)
PMS Plugin Logs/com.plexapp.agents.imdb.log:2017-03-04 22:52:34,691 (7fc8a17fa700) :  INFO (agentkit:957) - Searching for matches for {'openSubtitlesHash': None, 'name': 'Zulu', 'year': '1964', 'filename': '%2Fsyno%2Ftest%2Fmovies%2FZulu%20(1964)%2FZulu%20(1964)%2Emkv', 'plexHash': '73587982becf1ba78faca61c57d48fe9e50070ac08', 'duration': '-1', 'id': '28368'}
PMS Plugin Logs/com.plexapp.agents.imdb.log:2017-03-04 22:52:35,075 (7fc8a17fa700) :  INFO (__init__:182) - Scoring {'tt1426352': [4, u'Amer', u'2009', 0, 41, 0], 'tt2249221': [0, u'Zulu', u'2013', 0, 27, 0], 'tt0058777': [0, u'Zulu', u'1964', 99, 23257, 0]}
PMS Plugin Logs/com.plexapp.agents.imdb.log:2017-03-04 22:52:35,075 (7fc8a17fa700) :  INFO (__init__:486) - {'tt1426352': [4, u'Amer', u'2009', 0, 41, 56], 'tt2249221': [0, u'Zulu', u'2013', 0, 27, 60], 'tt0058777': [0, u'Zulu', u'1964', 99, 23257, 99]}
PMS Plugin Logs/com.plexapp.agents.imdb.log:2017-03-04 22:52:35,076 (7fc8a17fa700) :  INFO (__init__:500) - Skipping title/year match (doesn't meet percentage threshold): Zulu (2013) percentage=0
PMS Plugin Logs/com.plexapp.agents.imdb.log:2017-03-04 22:52:37,305 (7fc8a17fa700) :  INFO (__init__:494) - Adding title_year match: Zulu (1964) score=99, key=tt0058777
PMS Plugin Logs/com.plexapp.agents.imdb.log:2017-03-04 22:52:42,616 (7fc8a17fa700) :  DEBUG (networking:166) - Requesting 'https://chapterdb.plex.tv/chapters/search?title=Zulu'
[chuck@lizum Logs.149]$

ChuckPa · March 5, 2017, 4:00am

First, The Agent settings Left -> Right

Are there differences and do they effect changes if you use mine?

ChuckPa · March 5, 2017, 4:06am

This agent setting itself would be the most important since it has the most options.

ChuckPa · March 5, 2017, 4:09am

Keep grabbing your log files (ZIP archives of the entire Logs directory if you need to). Let’s build up a chronology to get Engineering involved with if we need to.

ChuckPa · March 5, 2017, 5:13am

@Cerebus2 said:
BTW, I just noticed that none of my Agent settings are sticking.

This is a clean damn install. WTF is going on?

I missed this. I apologize.

If Agent settings aren’t sticking, that’s the database. If you try to change preferences and they don’t stick either or can’t save, we can fix the whole bunch

Stop PMS.
sudo sh Get out the big gun
cd /var/lib/plexmediaserver
find . -type d -exec chmod 755 {} \;
find . -type f -exec chmod 644 {} \;
chown -R plex:plex .
Start PMS

Topic		Replies	Views
Unable to match anything Metadata & Adding Files server-windows	22	417	October 21, 2020
No matches found on all scans/manual Metadata & Adding Files server-linux	78	2980	September 12, 2020
Plex Agent no longer working and Add to Watchlist option is also now gone Metadata & Adding Files server-linux	282	7080	February 2, 2026
Plex Movie agent not working Metadata & Adding Files server-linux	20	893	June 28, 2021
Why my plex server wont download any metadata and won't add any subtitles General Discussions	40	617	January 7, 2020

"Fix Incorrect Match" not working

Related topics