UNRAID library update issues with Serviio 1.6.1

Good Evening All

I have attempted working through this myself multiple times and every time ended up reverting to version 1.4.1.2 as that was the last version my library updated correctly.

Basically all items in my library now say "This item is not currently available or cannot be read". Its not a permissions issue as UNRAID is not configured to restrict access at all. (yes i know this is bad)

I am unable to get Serviio to automatically update content. I have tried multiple things, including writing my own scripts and altering my ServiioService.exe.vmoptions to the below
-Xmx512m
-Dserviio.forceLibraryPoller=true
-Dserviio.libraryPollerFrequency=5
-Dplugins.check=false

One thing I am unsure - did i need to tell serviio to use this file or it just will by default?

I understand that the way polling is done was changed between versions at some stage from what I have read - is there anyway to have a tick box for 'use old style of polling' implemented so i can take advantage of the new features in 1.6 but not have to manually refresh my library?
It seems crazy that an old version met my needs.

[atc98092]

I'm unfamiliar with UNRAID. Is this a networked library, or attached to your Serviio computer via USB/SATA, etc?

If it's networked, yes it still could be a permissions issue. Serviio installs and operates under the Local System user account (on Windows). This user account has very restricted network permissions. It doesn't matter what the permissions are on the networked location, it's related to what Local System can do. To ensure proper network access permissions, you need to change the user account used for Serviio.

Yea I am already running under the local user account for the administrator. Should have said that.

Account has full access to the NAS (yes unraid is a NAS) and content is served fine. It's the library updating that is an issue and the polling of new files
No issues in the logs, just not detecting the files
The old polling in 1.4 worked fine but new files can't be auto discovered under 1.6 at the moment

Any suggestions ?

[DenyAll]

What does your log file say - toward the beginning there should be an entry to the effect:

[LibraryDeltaScanner] Added repository 'your NAS' to delta scanner (POLLER)

I presume you can manually refresh your library?

Have you tried re-adding the NAS to your shared folders.

ps. it uses ServiioService.exe.vmoptions by default... as long as you have restarted.

Manually refresh works fine. And yes have restarted both the box and the Serviio Service

I have lines for each NAS share similiar to the below
[LibraryDeltaScanner] Added repository '\\UNRAID\Media\TV' to delta scanner (POLLER)

I do have a few WARN in the log for EventDispatcher - these mean anything?
WARN [EventDispatcher] Error 400 received from event subscriber

[DenyAll]

OK:

• Firstly, as confirmed by your log file the POLLER scanner has been set up correctly (assuming \\UNRAID\Media\TV is the valid shared folder). Make sure your shared folders don't overlap - ie you don't have one share for \\UNRAID\Media\TV and another for \\UNRAID\Media\. This suggests your ServiioService.exe.vmoptions setup is working;
• One of the things that changed (version 1.5 ish) was that if a folder is unavailable at the time of refreshing, it is skipped. If this is the case then you should have entries to the effect "Repository '\\UNRAID\Media\TV' is unavailable at this time". You may need to turn on detailed logging for these messages. Turn on detailed logging anyway as this may shed some light.
• Have you tried re-adding one of your NAS folders to your shared folders (perhaps create a new folder for testing). Does this produce any errors?

ps. No I dont think those warnings are related.

So i have noticed my log file picking items up in the poller as below
2016-08-30 21:31:39,875 DEBUG [PipeManager] Adding file '\\UNRAID\Media\!Completed\Beauty.&.The.Beast.S04.E03...Down.for.the.Count - Copy.mp4' to the delta queue (file added)

However the latest log entry now being at (2016-08-30 22:32:31,046) and the file is still not present for DLNA devices.

I have intentionally not opened the console after a reboot and allowing just the service (Win 10 x64) to run - I was of the understanding that the console was not required for the library to update.

It's as if the delta queue is not being processed.

I still have my old 1.4.1.2 instance setup on my old VM and it is quite useful for comparison.
For Instance - At 10.17 pm I copied a file to the NAS

1.6.1 - Detected file - but cannot view from a DLNA device
2016-08-30 22:18:23,056 DEBUG [PipeManager] Adding file '\\UNRAID\Media\!Completed\11.22.63.S01.E01...The.Rabbit.Hole.mp4' to the delta queue (file added)

1.4.1.2 - Detected and Viewable almost immediately
2016-08-30 22:19:11,676 INFO [LibraryAdditionsCheckerThread] Added file '11.22.63.S01.E01...The.Rabbit.Hole.mp4' (title: The Rabbit Hole) to Library

I cannot find anything similar to the [LibraryAdditionsCheckerThread] in the 1.6 log.

It's now been an hour that i have been continually refreshing the logs and view to no avail. I have attached them for your viewing pleasure - hopefully it helps get to the bottom of the issue.

[DenyAll]

Is the !Completed folder the end-folder for the file, or is it moved somewhere automatically after that.

It does appear that the delta queue is not being processed. From memory (I will check tonight when home) you should have other messages testing whether the file has an existing reference in the database. The delta queue is a temporary queue where file references go pending further updates from the scanner - it was designed to cater for files that are progressively downloaded.

I have another solution (work-around really) for you as well which will overcome the issue for now (need to test it for the latest version, also tonight).

ps. your VM's are completely independent ie. they are not sharing any component of Serviio at all???

Yes - Can confirm they are seperate VM's. No common servio component.

The !completed folder is also the end destination in this case. These were files i copied into the directory for this test

[DenyAll]

Thanks. Something to test:

Normally on startup Serviio does a complete scan of your shared folders. This sets the "baseline" for all delta scans thereafter. On completion of this initial scan, Servio then enables delta queue processing (you get this statement: DEBUG [PipeManager] Enabling processing Delta scan queue . Your log doesn't contain this message but I'm not sure whether that's the problem (ie. something is failing in the initial scan, which prohibits the delta scan processing from starting) or whether it's because you haven't enabled detail logging including library messages, or simply because it's just not in the bits of the log you posted.

To enable detailed logging of library messages you have to add:

  Code:

  <category name="org.serviio.library.local">
    <priority value="DEBUG" />
  </category>

to your log4j.xml file (or you can use my WinHelper app that makes all this a bit easier). This can create a massive amount of log entries so it may pay to also change <param name="MaxFileSize" value="500KB" /> to value="5000KB" to make sure you don't get too many log files created and miss the bit we need to see.

Once you restart you will notice a whole lot of entries related to Serviio checking the initial state of the library. Once this is complete (and may take some time) look for the DEBUG [PipeManager] Enabling processing Delta scan queue statement. If it doesn't exist, post the log file containing the end of the initial scan here (you'll need to compress it) for further analysis (if what I suspect is happening, then this will be something zip will need to look at).
--------------------
OK - now for the promised workaround. Firstly dont forget to revert your log file back to normal (at some stage) so that it doesn't keep growing Keep the 5000KB log file size if you want (I don't think that's an unreasonable size for a log).

Next download the ForceServiioRefresh app from viewtopic.php?f=17&t=18183#p97403 and unzip it somewhere.

You can now create a Windows Task (run Task Scheduler from your start command) and create a task to run the ForceServiioRefresh app every x minutes. This will then do a Forced Refresh periodically. Sing out if you need help creating the task, but it's reasonably intuitive so have a go at it first (tip: use a trigger that begins the task on start-up, and repeats it every x minutes for an indefinite duration).

Have actually tested out that program, and wrote my own powershell web-call as well. Just looking for a better solution that doesnt require a workaround.

In an act of pure genius, I decided to rebuild my library today with just one folder (with 5 items) - as I remembered i had similar issues back in version 1.5.x and gave up (never posted anything back then)

With that addition to the log file i can see the addition correctly so I believe the issue may be related to item count. With just 5 items in the library the file is added within 5 minutes. (And available to DLNA devices obviously)

I have just kicked off the process of rebuilding the library with all 18000 items now so will need to check again tomorrow once that is complete.

[DenyAll]

Excellent. In my previous post I was trying to see if there is one particular file that it was stumbling over - ie. the initial scan gets to a certain file, which causes it to fail somehow, which then causes the "delta scanner processing" process not to be initiated.

Let us know how you go. Hopefully it will either all work (fingers crossed) or will highlight which file it stumbles over, which we can pass on for examination.

Unfortunately there seems to be an issue once the library is compiled

Attached in following posts are logs (too big to attach to one post apparantly.
Success.log contains the successful import for a small library including the MediaItemDAOImpl and MediaFileIndexer indexer events.

Unfortunately these events dont appear to have fired once I rebuilt the library and added a new file. Despite the line below at 3911 in servio.log
2016-09-01 18:53:32,228 DEBUG [PipeManager] Adding file '\\UNRAID\Media\!Completed\11.22.63.S01.E01...The.Rabbit.Hole - Copy.mp4' to the delta queue (file added)

In the mean time i just kicked off a forceLibraryRefresh to check if the files appear. Does the start and interrupt look like an issue to you? Would that indicate it never starts the scan?
2016-09-01 19:10:10,965 DEBUG [ActionsServerResource] Action with name 'forceLibraryRefresh' was requested
2016-09-01 19:10:10,990 INFO [LocalLibraryManager] Starting manual library scan
2016-09-01 19:10:10,992 INFO [LibraryOneTimeScanner] Interrupting library scan

Failed logs 1

I have looked through the logs, couldn't see any errors, just the absence of the scan.

[DenyAll]

Does the start and interrupt look like an issue to you?

No, this looks normal.

From your success.log we can see Serviio doing its initial scan and checking whether files are in the library - these types of messages:

  Code:

2016-08-31 22:52:33,189 DEBUG [MediaItemDAOImpl] Checking if DB already contains media item \\unraid\Media\!Test\Beauty.&.The.Beast.S04.E03...Down.for.the.Count.mp4
2016-08-31 22:52:33,189 DEBUG [MediaItemDAOImpl] Looking up a media item for file path: \\unraid\Media\!Test\Beauty.&.The.Beast.S04.E03...Down.for.the.Count.mp4, ignore case: true
2016-08-31 22:52:33,189 DEBUG [MediaItemDAOImpl] Media item \\unraid\Media\!Test\Beauty.&.The.Beast.S04.E03...Down.for.the.Count.mp4 already exists in DB

After the initial scan is complete, you get the critical

  Code:

2016-08-31 22:52:33,298 DEBUG [LibraryOneTimeScanner] Finished the scan of the library
2016-08-31 22:52:33,298 DEBUG [PipeManager] Enabling processing Delta scan queue

After this all is good - when your poller finds new media, it updates the delta queue, which is then processed (until the Delta scan queue is actually enabled, items may be added to it (ie. any new items), but they wont be processed).

Conversely, your posted serviio.log.1, serviio.log.2 and serviio.log files indicates that the initial scan is not completed. There is no "Finished the scan of the library" message, and hence the delta scan queue never gets enabled. I believe that this is the issue... but why it is happening is still the question - one for which I haven't a definative answer (could be a bad file freaking things out, could be too many new files being added to the delta scanner).

So what to do - a few things come to mind (either is time consuming I'm afraid):

1. The last folders scanned in the initial scan is TV\Game of Thrones. After that the folders \TV\H.R. Pufnstuf (1969),Charmed, Constatine... etc (look in serviio.log) are scanned but no media is found???? On the theory that something in this last part of the initial scan is freaking things out, perhaps remove the TV folder from the Serviio shared folders. Restart Serviio and monitor for the magic message "Finished the scan of the library" in the log. If successful
   
   • on the NAS rename the folder TV to TV1.
   • add the new TV folder back to to the Serviio share
   • move each TV1 sub-folder back into the TV folder one at a time. You need to continually check the log to ensure the media is added - what we are trying to find what folder/file is causing the failure (Game of Thrones perhaps, or H.R. Pufnstuf).
   • Once done test again with a restart making sure you get the magic message
2. Have you ever re-created your library? To do either:
   
   • Remove all shares from the library, and (after giving it some time to process and checking its finished and that all media has been removed) re-add the shares one at a time (ensuring the initial process is complete at for each share). After adding each share individually, as an additional step, restart Serviio, monitoring the log to ensure you get the magical "Finished the scan of the library" message after the initial scan (start by adding the TV share as that's my most likely culprit - see below); or (arguably better)
   • do a clean install of Serviio. Uninstall it, delete the Serviio folder (if any remnants exist) and then re-install. You will need to add all your settings back in. Add your shares back in one at a time again, monitoring as you go.

So after rebuilding from scratch it all seems to be working now.

Issue seems to have been due to a few files that must have become corrupted at some stage, and were all 0KB video files. Serviio couldnt process them.
Once I deleted them everything started chugging along

Thanks for all the help, and hopefully it is resolved permanantly.

For info anyone thinking they might have the same issue run the below command in windows powershell to display all 0kb files

  Code:

cd "Your Filepath"
dir -Recurse | ?{$_.Length -eq 0} | Select -ExpandProperty fullname