ongoinglLibrary scan hangs when new library scan triggers

[Ryex 0]

Hello Emby community,

 

I recently install Emby along side Kodi on our living room raspi running ArchARM. We have a nas with a good 3TB of media on it that we were previously using kodi to browse. However I want to have more power than that so in put Emby along side it. it APPEARS to work beautify Emby and Kodi get along very well and playback is near instant and smooth. the problem is that I can; not for the life of me get the library scan to finish. I finally broke down and cleared the database enabled debug logging  and let it run.

 

about 18 hours in it broke again at 46.4% completion (actually the farthest it's ever gotten)

 

Here is the relavent part of the log

2015-12-07 08:19:10.8521 Debug - App: Running FFProbeProvider for /mnt/treebrary_public/Storage/Videos/TV Shows/MLP ISOs/Season 1/MLP_DISC_4.ISO0.8529 Debug - App: Creating mount point /tmp/mediabrowser/783bf595-70a0-4eb1-87c2-bf028558efd7
2015-12-07 08:19:10.8538 Info - App: Mounting /mnt/treebrary_public/Storage/Videos/TV Shows/MLP ISOs/Season 1/MLP_DISC_4.ISO...015-12-07 08:19:15.7975 Debug - App: Emby.Kodi.SyncQueue:  User: pinkie - 45f29f45-00ed-4643-ba3a-318d48166790
2015-12-07 08:19:15.7978 Debug - App: Emby.Kodi.SyncQueue:  Items Added:          0
2015-12-07 08:19:15.7978 Debug - App: Emby.Kodi.SyncQueue:  Items Updated:        10
2015-12-07 08:19:15.7978 Debug - App: Emby.Kodi.SyncQueue:  Items Removed:        0
2015-12-07 08:19:15.7978 Debug - App: Emby.Kodi.SyncQueue:  Folders Added To:     0
2015-12-07 08:19:15.7978 Debug - App: Emby.Kodi.SyncQueue:  Folders Removed From: 0
2015-12-07 08:19:15.8058 Info - App: Emby.Kodi.SyncQueue:  Updating ItemId: 'df3fec8de9ee3adbbb7208f23a0a2018' for UserId: '45f29f4500ed4643ba3a318d48166790' in table: 'ItemsUpdatedQueue'
2015-12-07 08:19:15.8058 Debug - App: Emby.Kodi.SyncQueue:  Using SQL Statement: 'UPDATE ItemsUpdatedQueue SET lastModified = '2015-12-07T15:19:15Z' WHERE itemId = 'df3fec8de9ee3adbbb7208f23a0a2018' and  userId = '45f29f4500ed4643ba3a318d48166790''
        64-Bit Process: False
        Program data path: /var/lib/emby
        Mono: 4.2.1 (Stable 4.2.1.102/6dd2d0d Sun Nov 29 12:05:19 MST 2015)
        Application Path: /usr/lib/emby-server/MediaBrowser.Server.Mono.exe
        The process must exit before getting the requested information.
        System.InvalidOperationException
          at System.Diagnostics.Process.get_ExitCode () <0x6df44828 + 0x00074> in <filename unknown>:0
          at (wrapper remoting-invoke-with-check) System.Diagnostics.Process:get_ExitCode ()
          at MediaBrowser.IsoMounter.LinuxIsoManager+<Mount>c__async0.MoveNext () <0x6cf0c000 + 0x009f3> in <filename unknown>:0      --- End of stack trace from previous location where exception was thrown ---
          at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw () <0x6df4e298 + 0x00024> in <filename unknown>:0
          at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess (System.Threading.Tasks.Task task) <0x6df4dfa0 + 0x000bf> in <filename unknown>:0 ilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification (System.Threading.Tasks.Task task) <0x6df4dec0 + 0x0008b> in <filename unknown>:0 ter.ValidateEnd (System.Threading.Tasks.Task task) <0x73423b20 + 0x0003f> in <filename unknown>:0 me.CompilerServices.ConfiguredTaskAwaitable`1+ConfiguredTaskAwaiter[TResult].GetResult () <0x72c9ef40 + 0x0001b> in <filename unknown>:0 MediaInfo.FFProbeVideoInfo+<ProbeVideo>c__async0`1[T].MoveNext () <0x6df3eea8 + 0x002eb> in <filename unknown>:0 k trace from previous location where exception was thrown ---
          at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw () <0x6df4e298 + 0x00024> in <filename unknown>:0
          at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess (System.Threading.Tasks.Task task) <0x6df4dfa0 + 0x000bf> in <filename unknown>:0 ilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification (System.Threading.Tasks.Task task) <0x6df4dec0 + 0x0008b> in <filename unknown>:0 ter.ValidateEnd (System.Threading.Tasks.Task task) <0x73423b20 + 0x0003f> in <filename unknown>:0 me.CompilerServices.ConfiguredTaskAwaitable`1+ConfiguredTaskAwaiter[TResult].GetResult () <0x6f48bd28 + 0x00017> in <filename unknown>:0 Manager.MetadataService`2+<RunCustomProvider>c__async5[TItemType,TIdType].MoveNext () <0x6e7479e8 + 0x002a3> in <filename unknown>:0
2015-12-07 08:19:10.7001 Debug - App: Running EpisodeNfoProvider for /mnt/treebrary_public/Storage/Videos/TV Shows/MLP ISOs/Season 1/MLP_DISC_3.ISO013 Debug - App: EpisodeNfoProvider returned no metadata for /mnt/treebrary_public/Storage/Videos/TV Show2015-12-07 08:19:10.7013 Debug - App: Running EpisodeXmlProvider for /mnt/treebrary_public/Storage/Videos/TV Shows/MLP ISOs/Season 1/MLP_DISC_3.ISO
2015-12-07 08:19:10.7018 Debug - App: EpisodeXmlProvider returned no metadata for /mnt/treebrary_public/Storage/Videos/TV Shows/MLP ISOs/Season 1/MLP_DISC_3.ISO
2015-12-07 08:19:10.7018 Debug - App: Running AniDbEpisodeProvider for /mnt/treebrary_public/Storage/Videos/TV Shows/MLP ISOs/Season 1/MLP_DISC_3.ISO
2015-12-07 08:19:10.7018 Debug - App: AniDbEpisodeProvider returned no metadata for /mnt/treebrary_public/Storage/Videos/TV Shows/MLP ISOs/Season 1/MLP_DISC_3.ISO
2015-12-07 08:19:10.7018 Debug - App: Running TvdbEpisodeProvider for /mnt/treebrary_public/Storage/Videos/TV Shows/MLP ISOs/Season 1/MLP_DISC_3.ISO
2015-12-07 08:19:10.7018 Debug - App: No series identity found for MLP_DISC_3
2015-12-07 08:19:10.7018 Debug - App: TvdbEpisodeProvider returned no metadata for /mnt/treebrary_public/Storage/Videos/TV Shows/MLP ISOs/Season 1/MLP_DISC_3.ISO
2015-12-07 08:19:10.7027 Debug - App: Running TvdbEpisodeImageProvider for /mnt/treebrary_public/Storage/Videos/TV Shows/MLP ISOs/Season 1/MLP_DISC_3.ISO
2015-12-07 08:19:10.7056 Debug - App: Running VideoImageProvider for /mnt/treebrary_public/Storage/Videos/TV Shows/MLP ISOs/Season 1/MLP_DISC_3.ISO
2015-12-07 08:19:10.7083 Debug - App: Saving /mnt/treebrary_public/Storage/Videos/TV Shows/MLP ISOs/Season 1/MLP_DISC_3.ISO to database.
2015-12-07 08:19:10.7190 Debug - App: Emby.Kodi.SyncQueue:  GetClientTypeName: Episode
2015-12-07 08:19:10.8521 Debug - App: Running FFProbeProvider for /mnt/treebrary_public/Storage/Videos/TV Shows/MLP ISOs/Season 1/MLP_DISC_4.ISO
2015-12-07 08:19:10.8529 Debug - App: Creating mount point /tmp/mediabrowser/783bf595-70a0-4eb1-87c2-bf028558efd7
2015-12-07 08:19:10.8538 Info - App: Mounting /mnt/treebrary_public/Storage/Videos/TV Shows/MLP ISOs/Season 1/MLP_DISC_4.ISO...
2015-12-07 08:19:15.7975 Debug - App: Emby.Kodi.SyncQueue:  User: pinkie - 45f29f45-00ed-4643-ba3a-318d48166790
2015-12-07 08:19:15.7978 Debug - App: Emby.Kodi.SyncQueue:  Items Added:          0
2015-12-07 08:19:15.7978 Debug - App: Emby.Kodi.SyncQueue:  Items Updated:        10
2015-12-07 08:19:15.7978 Debug - App: Emby.Kodi.SyncQueue:  Items Removed:        0
2015-12-07 08:19:15.7978 Debug - App: Emby.Kodi.SyncQueue:  Folders Added To:     0
2015-12-07 08:19:15.8058 Info - App: Emby.Kodi.SyncQueue:  Updating ItemId: 'df3fec8de9ee3adbbb7208f23a0a2018' for UserId: '45f29f4500ed4643ba3a318d48166790' in table: 'ItemsUpdatedQueue'sing SQL Statement: 'UPDATE ItemsUpdatedQueue SET lastModified = '2015-12-07T15:19:15Z' WHERE itemId = 'df3fec8de9ee3adbbb7208f23a0a2018' and  userId = '45f29f4500ed4643ba3a318d48166790'' '45f29f4500ed4643ba3a318d48166790' in table: 'ItemsUpdatedQueue'sing SQL Statement: 'UPDATE ItemsUpdatedQueue SET lastModified = '2015-12-07T15:19:15Z' WHERE itemId = '0ddbd3030abfcab6352f31fece12f944' and  userId = '45f29f4500ed4643ba3a318d48166790'' '45f29f4500ed4643ba3a318d48166790' in table: 'ItemsUpdatedQueue'sing SQL Statement: 'UPDATE ItemsUpdatedQueue SET lastModified = '2015-12-07T15:19:15Z' WHERE itemId = '6dd3d4fdce873ef2a288a0a3573d1689' and  userId = '45f29f4500ed4643ba3a318d48166790''d = '2015-12-07T15:19:15Z' WHERE itemId = '8fde9b0eb5f0904bad7ae337601b6ad7' and  userId = '45f29f4500ed4643ba3a318d48166790''
2015-12-07 08:19:15.9762 Info - App: Emby.Kodi.SyncQueue:  Updating ItemId: '1751f0bd1955040732623690d2309f37' for UserId: '45f29f4500ed4643ba3a318d48166790' in table: 'ItemsUpdatedQueue'
2015-12-07 08:19:15.9766 Debug - App: Emby.Kodi.SyncQueue:  Using SQL Statement: 'UPDATE ItemsUpdatedQueue SET lastModified = '2015-12-07T15:19:15Z' WHERE itemId = '1751f0bd1955040732623690d2309f37' and  userId = '45f29f4500ed4643ba3a318d48166790''
2015-12-07 08:19:16.0092 Info - App: Emby.Kodi.SyncQueue:  Updating ItemId: '24a54c7c841e2b21d91ed4ef83c95d77' for UserId: '45f29f4500ed4643ba3a318d48166790' in table: 'ItemsUpdatedQueue'
2015-12-07 08:19:16.0096 Debug - App: Emby.Kodi.SyncQueue:  Using SQL Statement: 'UPDATE ItemsUpdatedQueue SET lastModified = '2015-12-07T15:19:16Z' WHERE itemId = '24a54c7c841e2b21d91ed4ef83c95d77' and  userId = '45f29f4500ed4643ba3a318d48166790''
2015-12-07 08:19:16.0441 Info - App: Emby.Kodi.SyncQueue:  Updating ItemId: '268ee1b75f3c1e3f46077f04976bae87' for UserId: '45f29f4500ed4643ba3a318d48166790' in table: 'ItemsUpdatedQueue'
2015-12-07 08:19:16.0441 Debug - App: Emby.Kodi.SyncQueue:  Using SQL Statement: 'UPDATE ItemsUpdatedQueue SET lastModified = '2015-12-07T15:19:16Z' WHERE itemId = '268ee1b75f3c1e3f46077f04976bae87' and  userId = '45f29f4500ed4643ba3a318d48166790''
2015-12-07 08:20:07.2395 Info - App: IntervalTrigger fired for task: Scan media library
2015-12-07 08:20:07.2395 Info - App: Queueing task RefreshMediaLibraryTask
2015-12-07 08:21:08.2439 Info - App: IntervalTrigger fired for task: Scan media library
2015-12-07 08:21:08.2439 Info - App: Queueing task RefreshMediaLibraryTask
2015-12-07 08:22:09.2462 Info - App: IntervalTrigger fired for task: Scan media library
2015-12-07 08:22:09.2462 Info - App: Queueing task RefreshMediaLibraryTask
2015-12-07 08:23:15.1035 Info - App: IntervalTrigger fired for task: Scan media library
2015-12-07 08:23:15.2136 Info - App: Queueing task RefreshMediaLibraryTask
2015-12-07 08:24:16.3683 Info - App: IntervalTrigger fired for task: Scan media library
2015-12-07 08:24:16.3686 Info - App: Queueing task RefreshMediaLibraryTask
2015-12-07 08:25:17.3860 Info - App: IntervalTrigger fired for task: Scan media library
2015-12-07 08:25:17.3860 Info - App: Queueing task RefreshMediaLibraryTask
2015-12-07 08:26:18.4047 Info - App: IntervalTrigger fired for task: Scan media library
2015-12-07 08:26:18.4047 Info - App: Queueing task RefreshMediaLibraryTask
2015-12-07 08:27:19.4264 Info - App: IntervalTrigger fired for task: Scan media library
2015-12-07 08:27:19.4267 Info - App: Queueing task RefreshMediaLibraryTask
2015-12-07 08:28:20.4432 Info - App: IntervalTrigger fired for task: Scan media library
2015-12-07 08:28:20.4436 Info - App: Queueing task RefreshMediaLibraryTask
2015-12-07 08:29:21.4594 Info - App: IntervalTrigger fired for task: Scan media library
2015-12-07 08:29:21.4597 Info - App: Queueing task RefreshMediaLibraryTask
2015-12-07 08:30:22.4825 Info - App: IntervalTrigger fired for task: Scan media library
2015-12-07 08:30:22.4828 Info - App: Queueing task RefreshMediaLibraryTask
2015-12-07 08:31:23.5022 Info - App: IntervalTrigger fired for task: Scan media library
2015-12-07 08:31:23.5022 Info - App: Queueing task RefreshMediaLibraryTask
2015-12-07 08:32:24.5224 Info - App: IntervalTrigger fired for task: Scan media library
2015-12-07 08:32:24.5228 Info - App: Queueing task RefreshMediaLibraryTask
2015-12-07 08:33:25.5390 Info - App: IntervalTrigger fired for task: Scan media library
2015-12-07 08:33:25.5390 Info - App: Queueing task RefreshMediaLibraryTask
2015-12-07 08:34:26.5537 Info - App: IntervalTrigger fired for task: Scan media library
2015-12-07 08:34:26.5537 Info - App: Queueing task RefreshMediaLibraryTask

there after it just repeats those two lines indefinitely about once a second and the scan never progresses. I suppose I could disable the scan trigger for now and try again but these seems like a bug in the meantime.

 

If I'm possibly just doing something wrong please let me know.

[Luke 37053]

Hi, welcome. Try removing all plugins and see if the issue persists. Thanks.

[Ryex 0]

removing plugins has so far seemed to do nothing.

on further investigation it appears to be actually caused by ISO files.

I gave emby wheel access because I noted it was attempting to mount isos. I assmed to get metadata for them but every single time I come to a crash it had eiter tried to or had mounted an ISO isos. I'm moving all the DVD ISO's I have out of the library now to see if it can finish the scan with them gone.

[Ryex 0]

Ok, now I'm good and stumped Removing ISO's seems to have helped the scan got to 86.5% previously it only got as far as 46% however it has hung yet again and this time brought the entire emby process with it. the process is still running but the web interface and android app are unresponsive. I teed out out log when I stared the scan and attached it here. had to zip it because the text was 14 MB.

 

there doesn't even seem to be a reason. one seconds it's pulling metadata and then boom 35 minute blank in the log

2015-12-09 08:21:52.3690 Info - App: HttpClientManager GET: http://assets.fanart.tv/fanart/music/9a3bf45c-347d-4630-894d-7cf3ertistthumb/santana-4fd89238d8ffb.jpg
2015-12-09 08:21:53.4819 Debug - ProviderManager: Saving image to /var/lib/emby/metadata/artists/Santana/folder.jpg
2015-12-09 08:21:53.5018 Debug - ProviderManager: Saving image to /var/lib/emby/metadata/library/c0/c09189a8a48e67f27ddae42494lder.jpg
2015-12-09 08:21:53.5319 Info - App: HttpClientManager GET: http://assets.fanart.tv/fanart/music/9a3bf45c-347d-4630-894d-7cf3ertistbackground/santana-4e994fafc6c6a.jpg
2015-12-09 08:21:54.2049 Debug - ProviderManager: Saving image to /var/lib/emby/metadata/artists/Santana/fanart.jpg
2015-12-09 08:21:54.2115 Debug - ProviderManager: Saving image to /var/lib/emby/metadata/library/c0/c09189a8a48e67f27ddae42494ckdrop.jpg
2015-12-09 08:21:55.0286 Debug - ProviderManager: Saving /var/lib/emby/metadata/artists/Santana to Nfo.
2015-12-09 08:21:55.0368 Debug - App: Saving /var/lib/emby/metadata/artists/Santana to database.
2015-12-09 08:21:55.0507 Debug - App: Running ArtistNfoProvider for /var/lib/emby/metadata/artists/Tom Petty and the Heartbrea2015-12-09 08:21:55.0507 Debug - App: ArtistNfoProvider returned no metadata for /var/lib/emby/metadata/artists/Tom Petty and breakers
2015-12-09 08:21:55.0513 Debug - App: Running MusicBrainzArtistProvider for /var/lib/emby/metadata/artists/Tom Petty and the Hers
2015-12-09 08:21:56.0563 Info - App: HttpClientManager GET: http://www.musicbrainz.org/ws/2/artist/?query=artist:"Tom+Petty+anrtbreakers"
2015-12-09 08:21:56.1888 Debug - App: Running AudioDbArtistProvider for /var/lib/emby/metadata/artists/Tom Petty and the Heart2015-12-09 08:21:56.1936 Info - App: HttpClientManager GET: http://www.theaudiodb.com/api/v1/json/49jhsf8248yfahka89724011/artp?i=f93dbc64-6f08-4033-bcc7-8a0bb4689849
2015-12-09 08:21:56.4248 Debug - App: Running FanartArtistProvider for /var/lib/emby/metadata/artists/Tom Petty and the Heartb2015-12-09 08:21:56.4336 Info - App: HttpClientManager GET: http://webservice.fanart.tv/v3.1/music/f93dbc64-6f08-4033-bcc7-8a0?api_key=5c6b04c68e904cfed1e6cbc9a9e683d4 2015-12-09 08:56:27.0777 Info - App: IntervalTrigger fired for task: Refresh Guide 2015-12-09 08:56:27.0777 Info - App: Queueing task RefreshChannelsScheduledTask 2015-12-09 08:56:27.0777 Info - App: Executing Refresh Guide 2015-12-09 08:56:28.4545 Debug - App: Refreshing guide from Emby 2015-12-09 08:56:28.5104 Info - App: Refreshing guide with 14 days of guide data 2015-12-09 08:56:28.5114 Debug - SqliteItemRepository: select guid from TypedBaseItems where type=@type; select count (guid) fBaseItems where type=@type

server_scannlog.zip

Edited December 9, 2015 by Ryex