Broken update from MediaPortal? (2 Viewers)

[vpupkin]

Updating details works fine from within MovingPictures configuration (MovieImporter), but updating from within MediaPortal itself (such as Movie Options->Update Details from Online) doesn't work properly as it cannot find scraper options XML file, thus reverting to default options.

Here is how it looks like when running from the Configuration/MovieImporter - works properly, see custom options in effect (I removed non-relevant log lines):

27-Jan-2012 00:02:38 Info [ MovingPicturesCore]: Moving Pictures (1.2.3:1329)
27-Jan-2012 00:02:38 Info [ MovingPicturesCore]: Plugin Launched
27-Jan-2012 00:02:38 Info [ DataProviderManager]: Loading existing data sources...
27-Jan-2012 00:02:39 Info [ DataProviderManager]: Checking internal scripts for updates...
27-Jan-2012 00:02:39 Warn [ DataProviderManager]: Script version number already loaded. Reloading because in Debug Mode.
27-Jan-2012 00:02:39 Warn [ DataProviderManager]: Script version number already loaded. Reloading because in Debug Mode.
27-Jan-2012 00:02:39 Warn [ DataProviderManager]: Script version number already loaded. Reloading because in Debug Mode.
27-Jan-2012 00:02:39 Warn [ DataProviderManager]: Script version number already loaded. Reloading because in Debug Mode.
27-Jan-2012 00:02:39 Warn [ DataProviderManager]: Script version number already loaded. Reloading because in Debug Mode.
27-Jan-2012 00:02:39 Warn [ DataProviderManager]: Script version number already loaded. Reloading because in Debug Mode.
27-Jan-2012 00:02:39 Warn [ DataProviderManager]: Script version number already loaded. Reloading because in Debug Mode.
27-Jan-2012 00:02:39 Warn [ DataProviderManager]: Script version number already loaded. Reloading because in Debug Mode.
27-Jan-2012 00:02:39 Warn [ DataProviderManager]: Script version number already loaded. Reloading because in Debug Mode.
27-Jan-2012 00:02:39 Warn [ DataProviderManager]: Script version number already loaded. Reloading because in Debug Mode.
27-Jan-2012 00:02:39 Warn [ DataProviderManager]: Script version number already loaded. Reloading because in Debug Mode.
27-Jan-2012 00:02:39 Warn [ DataProviderManager]: Script version number already loaded. Reloading because in Debug Mode.
27-Jan-2012 00:02:39 Warn [ DataProviderManager]: Script version number already loaded. Reloading because in Debug Mode.
27-Jan-2012 00:02:39 Warn [ DataProviderManager]: Script version number already loaded. Reloading because in Debug Mode.
27-Jan-2012 00:02:39 Warn [ DataProviderManager]: Script version number already loaded. Reloading because in Debug Mode.
27-Jan-2012 00:02:39 Warn [ DataProviderManager]: Script version number already loaded. Reloading because in Debug Mode.
27-Jan-2012 00:02:39 Warn [ DataProviderManager]: Script version number already loaded. Reloading because in Debug Mode.
27-Jan-2012 00:02:39 Warn [ DataProviderManager]: Script version number already loaded. Reloading because in Debug Mode.
27-Jan-2012 00:02:39 Warn [ DataProviderManager]: Script version number already loaded. Reloading because in Debug Mode.
27-Jan-2012 00:02:41 Info [ MovieImporter]: Started MovieImporter
27-Jan-2012 00:12:01 Info [ MovieManagerPane]: Refreshing movie #1: Disciples of the 36th Chamber
27-Jan-2012 00:12:01 Info [ ScraperNode]: IMDb+ Scraper: Settings overruled via Options XML file
27-Jan-2012 00:12:10 Error [ WebGrabber]: Connection failed: URL=http://www.rottentomatoes.com/alias?type=imdbid&s=0089029, Status=NotFound, Description=Not Found.
27-Jan-2012 00:12:14 Info [ ScraperNode]: IMDb+ Scraper: Title adjusted via Custom Rename XML for: tt0089029
27-Jan-2012 00:12:14 Info [ ScraperNode]: IMDb+ Scraper: SortBy adjusted via Custom Rename XML for: tt0089029
27-Jan-2012 00:13:08 Info [ MovieImporter]: Stopped MovieImporter
27-Jan-2012 00:13:08 Info [ MovingPicturesCore]: Plugin Closed


Now here is how it looks like when running from within MediaPortal - does NOT work properly, see unable to find custom options and reverting to default, thus updating back to the default IMDb name (I removed non-relevant log lines):


27-Jan-2012 00:13:24 Info [ SettingsManager]: SettingsManager Created
27-Jan-2012 00:13:25 Info [ MovingPicturesGUI]: Initializing GUI...
27-Jan-2012 00:13:25 Info [ MovingPicturesCore]: Moving Pictures (1.2.3:1329)
27-Jan-2012 00:13:25 Info [ MovingPicturesCore]: Plugin Launched
27-Jan-2012 00:13:29 Info [ DataProviderManager]: DataProviderManager Starting
27-Jan-2012 00:13:29 Info [ DataProviderManager]: Loading existing data sources...
27-Jan-2012 00:13:29 Info [ DataProviderManager]: Checking internal scripts for updates...
27-Jan-2012 00:13:29 Warn [ DataProviderManager]: Script version number already loaded. Reloading because in Debug Mode.
27-Jan-2012 00:13:29 Warn [ DataProviderManager]: Script version number already loaded. Reloading because in Debug Mode.
27-Jan-2012 00:13:29 Warn [ DataProviderManager]: Script version number already loaded. Reloading because in Debug Mode.
27-Jan-2012 00:13:29 Warn [ DataProviderManager]: Script version number already loaded. Reloading because in Debug Mode.
27-Jan-2012 00:13:29 Warn [ DataProviderManager]: Script version number already loaded. Reloading because in Debug Mode.
27-Jan-2012 00:13:29 Warn [ DataProviderManager]: Script version number already loaded. Reloading because in Debug Mode.
27-Jan-2012 00:13:29 Warn [ DataProviderManager]: Script version number already loaded. Reloading because in Debug Mode.
27-Jan-2012 00:13:29 Warn [ DataProviderManager]: Script version number already loaded. Reloading because in Debug Mode.
27-Jan-2012 00:13:29 Warn [ DataProviderManager]: Script version number already loaded. Reloading because in Debug Mode.
27-Jan-2012 00:13:29 Warn [ DataProviderManager]: Script version number already loaded. Reloading because in Debug Mode.
27-Jan-2012 00:13:29 Warn [ DataProviderManager]: Script version number already loaded. Reloading because in Debug Mode.
27-Jan-2012 00:13:29 Warn [ DataProviderManager]: Script version number already loaded. Reloading because in Debug Mode.
27-Jan-2012 00:13:29 Warn [ DataProviderManager]: Script version number already loaded. Reloading because in Debug Mode.
27-Jan-2012 00:13:29 Warn [ DataProviderManager]: Script version number already loaded. Reloading because in Debug Mode.
27-Jan-2012 00:13:29 Warn [ DataProviderManager]: Script version number already loaded. Reloading because in Debug Mode.
27-Jan-2012 00:13:29 Warn [ DataProviderManager]: Script version number already loaded. Reloading because in Debug Mode.
27-Jan-2012 00:13:29 Warn [ DataProviderManager]: Script version number already loaded. Reloading because in Debug Mode.
27-Jan-2012 00:13:29 Warn [ DataProviderManager]: Script version number already loaded. Reloading because in Debug Mode.
27-Jan-2012 00:13:29 Warn [ DataProviderManager]: Script version number already loaded. Reloading because in Debug Mode.
27-Jan-2012 00:13:30 Info [ MovieImporter]: Started MovieImporter
27-Jan-2012 00:13:30 Info [ SkinSettings]: Loading defines from skin.
27-Jan-2012 00:13:30 Info [ MoviePlayer]: Movie Player initialized.
27-Jan-2012 00:13:30 Info [ MovingPicturesGUI]: GUI Initialization Complete
27-Jan-2012 00:13:31 Warn [ DataProviderManager]: Script version number already loaded. Reloading because in Debug Mode.
27-Jan-2012 00:14:01 Info [GUIListItemMovieComp]: Sort Field: Title Sort Direction: Ascending
27-Jan-2012 00:14:55 Info [ MovingPicturesGUI]: Updating movie details for 'The 36th Chamber III: Disciples of ... (Pi li shi jie)'
27-Jan-2012 00:14:55 Warn [ ScraperNode]: IMDb+ Scraper Notice: No XML file found for options, default values are used
27-Jan-2012 00:15:04 Error [ WebGrabber]: Connection failed: URL=http://www.rottentomatoes.com/alias?type=imdbid&s=0089029, Status=NotFound, Description=Not Found.
27-Jan-2012 00:15:11 Info [ MovingPicturesGUI]: Finished updating details for 'Disciples of the 36th Chamber'
27-Jan-2012 00:15:11 Info [GUIListItemMovieComp]: Sort Field: Title Sort Direction: Ascending

 

[RoChess]

You must have removed too much because I do not see the lines normally shown:

MovPic config refresh:

27-Jan-2012 04:34:22 Info [ MovieManagerPane]: Refreshing movie #1: 3:10 to Yuma
27-Jan-2012 04:34:22 Info [ ScraperNode]: IMDb+ Scraper: Settings overruled via Options XML file
27-Jan-2012 04:34:29 Debug [ DataProviderManager]: UPDATE: Title='3:10 to Yuma', Provider='IMDb+', Version=4.2.1, Result=SUCCESS
​

MePo GUI -> MovPic GUI refresh:

27-Jan-2012 04:37:58 Info [ MovingPicturesGUI]: Updating movie details for '3:10 to Yuma'
27-Jan-2012 04:37:58 Info [ ScraperNode]: IMDb+ Scraper: Settings overruled via Options XML file
27-Jan-2012 04:38:06 Debug [ DataProviderManager]: UPDATE: Title='3:10 to Yuma', Provider='IMDb+', Version=4.2.1, Result=SUCCESS
27-Jan-2012 04:38:06 Debug [ DatabaseManager]: UPDATING: 3:10 to Yuma
27-Jan-2012 04:38:06 Debug [ DBLocalMedia]: Updating media info for 'C:\MovPic\3;10 To Yuma (2007).avi'
27-Jan-2012 04:38:06 Debug [ MediaInfoWrapper]: MediaInfoWrapper: inspecting media : C:\MovPic\3;10 To Yuma (2007).avi
27-Jan-2012 04:38:06 Debug [ MediaInfoWrapper]: MediaInfoWrapper: FrameRate : 0
27-Jan-2012 04:38:06 Debug [ MediaInfoWrapper]: MediaInfoWrapper: VideoCodec :
27-Jan-2012 04:38:06 Debug [ MediaInfoWrapper]: MediaInfoWrapper: HasSubtitles : False
27-Jan-2012 04:38:06 Debug [ MediaInfoWrapper]: MediaInfoWrapper: NumSubtitles : 0
27-Jan-2012 04:38:06 Debug [ MediaInfoWrapper]: MediaInfoWrapper: Scan type :
27-Jan-2012 04:38:06 Debug [ MediaInfoWrapper]: MediaInfoWrapper: IsInterlaced: False
27-Jan-2012 04:38:06 Debug [ MediaInfoWrapper]: MediaInfoWrapper: Width : 0
27-Jan-2012 04:38:06 Debug [ MediaInfoWrapper]: MediaInfoWrapper: Height : 0
27-Jan-2012 04:38:06 Debug [ MediaInfoWrapper]: MediaInfoWrapper: Audiochannels : 0
27-Jan-2012 04:38:06 Debug [ MediaInfoWrapper]: MediaInfoWrapper: Audiorate : 0
27-Jan-2012 04:38:06 Debug [ MediaInfoWrapper]: MediaInfoWrapper: AspectRatio : widescreen
27-Jan-2012 04:38:06 Debug [ MediaInfoWrapper]: MediaInfoWrapper: AudioCodec :
27-Jan-2012 04:38:06 Debug [ DatabaseManager]: UPDATING: 3;10 To Yuma (2007).avi
27-Jan-2012 04:38:06 Info [ MovingPicturesGUI]: Finished updating details for '3:10 to Yuma'
​

MovingPictures in both cases uses IMDb+ scraper-script v4.2.1 which is modified during install by IMDb+ plugin to point to the XML files via hardcoded modifications for options/rename/etc. So if you are experiencing differences between MovPic config and MovPic GUI, then you have a MovPic database corruption going on that is causing it to use a different scraper-script from database or something else.

Would need to see scraper-debug mode enabled *FULL* log files to debug that problem then.

 

[vpupkin]

Here are the full logs. In both cases 4.2.1 is used, but instead of C:\ProgramData\Team MediaPortal\MediaPortal\IMDb+\Options IMDb+ Scraper.xml (used in Configuration mode), IMDb+ running under MePo tries to load C:\Options IMDb+ Scraper.xml and naturally fails as there is no such file in there. I checked the scripts table in the DB, there is only one entry for IMDb+ (4.2.1).

 

[RoChess]

Here are the full logs. In both cases 4.2.1 is used, but instead of C:\ProgramData\Team MediaPortal\MediaPortal\IMDb+\Options IMDb+ Scraper.xml (used in Configuration mode), IMDb+ running under MePo tries to load C:\Options IMDb+ Scraper.xml and naturally fails as there is no such file in there. I checked the scripts table in the DB, there is only one entry for IMDb+ (4.2.1).

Totally stunned, so would have to see the 'scripts' table of your movingpictures.db3 database for myself.

Can you make a copy of your db3 and delete all the other tables and then attach it here please?

 

[vpupkin]

Here you go... let me know if I can help, but I just dumped all the strings from the .db3 file, and there are no references to C:\Options... anywhere...

 

[RoChess]

Ok, located the problem.

The IMDb+ plugin, downloads the latest scraper-script version from Google website. It then inserts this version (which has the wrong C:\ paths) into MovingPictures database and then adjusts paths.

It seems MovingPictures GUI has some cache/memory or other race-condition issue with that, so it ends up using the pure SVN version of the IMDb+ scraper-script which leads to the problems you experience.

I was able to locate the problem and identify it, but my C# knowledge is not good enough yet to actually put it down in working code without breaking anything else. But I've got some awesome help, so hopefully it will be fixed soon and you can expect a new IMDb+ plugin to be released containing the fix shortly after.

In the meantime, a dumb workaround would be to close MediaPortal GUI when you get an IMDb+ scraper-script update notification. A restart of MovPic GUI should force it to re-read the database (which has the proper updated IMDb+ version as verified in the DB3 file you sent), which will make it use the version with the correct path.

It could be that the .NET framework does some wierd caching as well, in which case in worst case scenario you would have to reboot system. But considering that this is the first time ever that this issue has been brought to my attention and that the same code has been in place for a long time, I think it is safe to say that it is a very random bug that does not happen often.

 

[vpupkin]

The bug could have been there for a while - it is just that with default settings this is not likely to be triggered. I have scraper debug mode enabled, and check for updates on startup - this means that for this setup updating from within MePo NEVER worked as in scraper-debug scraper reinstall happens every time, no matter if the version is the same. But even if it was triggered in other cases, it is only noticeable if you have foreign movie, with non-default convention for naming and / or rename. Only then you can notice it. So quite a few things need to align, and I have to be the lucky one

Disabling scraper debug-mode and restarting MePo worked... almost. There might be some other caching going around, probably in MePo itself. When the title gets renamed, it is not updated in the MovPic list until MePo restart. So if I have "Original Title" movie that's custom-renamed to "Renamed Title", and I run an update from MovPic, then info is clearly updated - that is I can see the new title in the top of the window with movie info ("Renamed Title"), it is properly sorted (with R), but the list still shows "Original Title", and it doesn't change until MePo restarted. Actually, the same behavior exists in Config movie importer.

In any case - , and hope the issue will be resolved soon.

 

[RoChess]

The bug could have been there for a while - it is just that with default settings this is not likely to be triggered. I have scraper debug mode enabled, and check for updates on startup - this means that for this setup updating from within MePo NEVER worked as in scraper-debug scraper reinstall happens every time, no matter if the version is the same. But even if it was triggered in other cases, it is only noticeable if you have foreign movie, with non-default convention for naming and / or rename. Only then you can notice it. So quite a few things need to align, and I have to be the lucky one

Disabling scraper debug-mode and restarting MePo worked... almost. There might be some other caching going around, probably in MePo itself. When the title gets renamed, it is not updated in the MovPic list until MePo restart. So if I have "Original Title" movie that's custom-renamed to "Renamed Title", and I run an update from MovPic, then info is clearly updated - that is I can see the new title in the top of the window with movie info ("Renamed Title"), it is properly sorted (with R), but the list still shows "Original Title", and it doesn't change until MePo restarted. Actually, the same behavior exists in Config movie importer.

In any case - , and hope the issue will be resolved soon.

I'm working on testing the fix right as we speak, and I'm also testing the foreign title seperation in default rename database. Expect an update on both plugin, scraper-script and rename dbase within the next hour.

The other issue is known, the 'list' is only loaded once when MovPic initializes.

This has however been fixed for MovPic config (with GUI just having to wait a little bit longer) via: Issue 979 - moving-pictures - Movie Manager list does not refresh on a title/sortby edit - A movies plugin for the MediaPortal media center application. - Google Project Hosting

 

[RoChess]

Fixed in IMDb+ plugin v1.5.0.250

Please let me know if you find any other issues

 

[vpupkin]

Awesome, we are almost there... almost Couple of things:

- separation for title / foreign fields works only in the main rename db, it doesn't work at all in custom db (I think the line is ignored completely); don't know if it's by design or not. For me it makes sense to keep formats the same.

- For Avatar, special tags are not added to sortby (I guess because there is an override on the sortby, why?), so "Avatar ([2D Special Extended Edition])" and "Avatar ([3D])" are sorted on "Avatar I"; for renames without sortby override (e.g. The Butterfly Effect) it works fine

- Different editions are not updated, see this code:

                    // skip over previous refreshed
                    if (PluginSettings.MoviesRefreshed.Contains(movie.ImdbID)) continue;

So when I have different editions of the same movie (same tt-id), only the first one gets updated. E.g.

2012-01-28 16:18:04[Refresh Movies][39][Info] Refreshing movie information [5/11] 'The Vengeance III: Lady Vengeance (Chinjeolhan geumjassi) [Fade to Black & White]'
2012-01-28 16:18:08[Refresh Movies][39][Info] Refreshing movie information [6/11] 'The Vengeance III: Lady Vengeance (Chinjeolhan geumjassi) [Color]'

the second one doesn't get updated.

Apart from these fairly minor issues, great job RoChess, much appreciated!