Hi
Installed yesterday and everything was running 100%.
Now Sonarr hangs when I try to access the web interface.
The error I get is:
require.js : 135
Error: Load timeout for modules:
api!system/status,api!sieries,api!tag
http://requirejs.org
/docs/errors.html#timeout
I would post logs but I do not know where to find them in the plugin jail
They will be in the same location as nzbdrone.db (usually in /home/<user>/.config/NzbDrone)
in the FreeNAS plugin the datadir is /var/db/sonarr
there should be a log directory in there
I’ve been running this on freenas for a while now and it seems to always die after a few days running. I’ve not seen anything interesting in the logs, it just stops logging and the first I know about it is that I’ll try and access the interface and find it unresponsive. Restarting the plugin or jail usually brings it back to life, for a while at least.
Anything I can do to help track this down?
Make sure mono is running with --debug, Sonarr is outputting trace logs (so you can see if its failing at about the same point of time every time).
Version of mono and Sonarr.
Status of mono when its dead (is it still running inside the jail)?
I have trace logging enabled now, I’ll have to dig about in the start scripts to see how to add the --debug switch to mono. I’ll report back next time it happens with lots of useful info.
I didn’t have to wait too long, all logging stopped at 0235 this morning and the web interface doesn’t load.
Jumping on the box this morning I can see that the process is still up:
root@sonarr_1:/var/db/sonarr/logs # ps -U media
PID TT STAT TIME COMMAND
80283 ?? IsJ 10:09.95 /usr/pbi/sonarr-amd64/bin/mono --debug /usr/pbi/sonarr-amd64/share/sonarr/NzbDrone/NzbDrone.exe --data=/var/db/sonarr --nobrowser (mono-sgen)
and it is idle:
last pid: 10999; load averages: 0.13, 0.05, 0.01 6 processes: 1 running, 5 sleeping
CPU: 0.3% user, 0.0% nice, 1.2% system, 0.1% interrupt, 98.4% idle
Mem: 1957M Active, 607M Inact, 4668M Wired, 99M Cache, 223M Buf, 344M Free
ARC: 3519M Total, 527M MFU, 2337M MRU, 16K Anon, 95M Header, 560M Other
Swap: 4096M Total, 41M Used, 4055M Free, 1% Inuse
PID USERNAME THR PRI NICE SIZE RES STATE C TIME WCPU COMMAND
80283 media 13 20 0 337M 170M usem 3 10:10 0.00% mono-sgen
11697 root 6 38 0 184M 17604K usem 3 0:13 0.00% python2.7
11493 root 1 20 0 14176K 1192K nanslp 0 0:00 0.00% cron
11435 root 1 20 0 12084K 1092K select 3 0:00 0.00% syslogd
10960 root 1 20 0 17564K 2672K pause 0 0:00 0.00% tcsh
10999 root 1 20 0 16596K 2016K CPU1 1 0:00 0.00% top
The log seems to indicate it was scanning my media files at the time, the last few lines are:
15-3-18 02:35:01.9|Trace|EventAggregator|Publishing CommandExecutedEvent
15-3-18 02:35:01.9|Trace|EventAggregator|CommandExecutedEvent -> TaskManager
15-3-18 02:35:01.9|Trace|EventAggregator|CommandExecutedEvent <- TaskManager
15-3-18 02:35:01.9|Trace|EventAggregator|CommandExecutedEvent -> TaskModule
15-3-18 02:35:01.9|Trace|EventAggregator|CommandExecutedEvent <- TaskModule
15-3-18 02:35:01.9|Trace|CommandExecutor|CleanMediaFileDb <- MediaFileTableCleanupService [00:00:00.0317960]
15-3-18 02:35:01.9|Debug|DiskScanService|Scanning '/media/TV/The Real Housewives of Beverly Hills' for video files
15-3-18 02:35:01.9|Trace|HttpClient|Res: [HEAD] http://thetvdb.com/banners/posters/258107-4.jpg : 200.OK (37 ms)
15-3-18 02:35:01.9|Debug|MediaCoverService|Resizing Poster-500 for [258107][The Fall]
15-3-18 02:35:01.9|Trace|DiskProviderBase|Deleting file: /var/db/sonarr/MediaCover/58/poster-500.jpg
15-3-18 02:35:01.9|Debug|MediaCoverService|Couldn't resize media cover Poster-500 for [258107][The Fall], using full size image instead.
15-3-18 02:35:01.9|Debug|MediaCoverService|Resizing Poster-250 for [258107][The Fall]
15-3-18 02:35:01.9|Trace|DiskProviderBase|Deleting file: /var/db/sonarr/MediaCover/58/poster-250.jpg
15-3-18 02:35:01.9|Debug|DiskScanService|95 video files were found in /media/TV/The Real Housewives of Beverly Hills
15-3-18 02:35:01.9|Debug|MediaCoverService|Couldn't resize media cover Poster-250 for [258107][The Fall], using full size image instead.
15-3-18 02:35:01.9|Trace|EventAggregator|Publishing MediaCoversUpdatedEvent
15-3-18 02:35:01.9|Trace|EventAggregator|MediaCoversUpdatedEvent -> MetadataService
15-3-18 02:35:01.9|Debug|CleanMetadataService|Cleaning missing metadata files for series: The Fall
15-3-18 02:35:01.9|Trace|DiskScanService|Finished getting episode files for: [196741][The Real Housewives of Beverly Hills] [00:00:00.0329255]
15-3-18 02:35:02.0|Debug|GlobalExceptionHandlers|Minor Fail: An exception was thrown by the type initializer for System.Drawing.GDIPlus
System.TypeInitializationException: An exception was thrown by the type initializer for System.Drawing.GDIPlus ---> System.DllNotFoundException: libgdiplus.so
at (wrapper managed-to-native) System.Drawing.GDIPlus:GdiplusStartup (ulong&,System.Drawing.GdiplusStartupInput&,System.Drawing.GdiplusStartupOutput&)
at System.Drawing.GDIPlus..cctor () [0x000cc] in /usr/wrkdirprefix/usr/ports/lang/mono/work/mono-3.10.0/mcs/class/System.Drawing/System.Drawing/gdipFunctions.cs:127
--- End of inner exception stack trace ---
at System.Drawing.Image.InitFromStream (System.IO.Stream stream) [0x00077] in /usr/wrkdirprefix/usr/ports/lang/mono/work/mono-3.10.0/mcs/class/System.Drawing/System.Drawing/Image.cs:290
at System.Drawing.Bitmap..ctor (System.IO.Stream stream, Boolean useIcm) [0x00006] in /usr/wrkdirprefix/usr/ports/lang/mono/work/mono-3.10.0/mcs/class/System.Drawing/System.Drawing/Bitmap.cs:113
at (wrapper remoting-invoke-with-check) System.Drawing.Bitmap:.ctor (System.IO.Stream,bool)
at ImageResizer.ImageBuilder.DecodeStream (System.IO.Stream s, ImageResizer.ResizeSettings settings, System.String optionalPath) [0x00000] in <filename unknown>:0
at ImageResizer.ImageBuilder.LoadImage (System.Object source, ImageResizer.ResizeSettings settings, Boolean restoreStreamPos) [0x00000] in <filename unknown>:0
15-3-18 02:35:02.0|Debug|GlobalExceptionHandlers|Minor Fail: An exception was thrown by the type initializer for System.Drawing.GDIPlus
System.TypeInitializationException: An exception was thrown by the type initializer for System.Drawing.GDIPlus ---> System.DllNotFoundException: libgdiplus.so
at (wrapper managed-to-native) System.Drawing.GDIPlus:GdiplusStartup (ulong&,System.Drawing.GdiplusStartupInput&,System.Drawing.GdiplusStartupOutput&)
at System.Drawing.GDIPlus..cctor () [0x000cc] in /usr/wrkdirprefix/usr/ports/lang/mono/work/mono-3.10.0/mcs/class/System.Drawing/System.Drawing/gdipFunctions.cs:127
--- End of inner exception stack trace ---
at System.Drawing.Image.InitFromStream (System.IO.Stream stream) [0x00077] in /usr/wrkdirprefix/usr/ports/lang/mono/work/mono-3.10.0/mcs/class/System.Drawing/System.Drawing/Image.cs:290
at System.Drawing.Bitmap..ctor (System.IO.Stream stream, Boolean useIcm) [0x00006] in /usr/wrkdirprefix/usr/ports/lang/mono/work/mono-3.10.0/mcs/class/System.Drawing/System.Drawing/Bitmap.cs:113
at (wrapper remoting-invoke-with-check) System.Drawing.Bitmap:.ctor (System.IO.Stream,bool)
at ImageResizer.ImageBuilder.DecodeStream (System.IO.Stream s, ImageResizer.ResizeSettings settings, System.String optionalPath) [0x00000] in <filename unknown>:0
at ImageResizer.ImageBuilder.LoadImage (System.Object source, ImageResizer.ResizeSettings settings, Boolean restoreStreamPos) [0x00000] in <filename unknown>:0
The gdiplus error appears frequently throughout the log and is not always the last thing to appear there when it freezes. I added the --debug switch to mono last night but I’m no sure where I’d find the mono logs if you need them.
Oh, mono version is:
root@sonarr_1:/var/db/sonarr/logs # mono --version
Mono JIT compiler version 3.10.0 (tarball Mon Jan 26 02:53:37 UTC 2015)
Copyright (C) 2002-2014 Novell, Inc, Xamarin Inc and Contributors. www.mono-project.com
TLS: __thread
SIGSEGV: altstack
Notification: kqueue
Architecture: amd64
Disabled: none
Misc: softdebug
LLVM: supported, not enabled.
GC: sgen
and Sonarr is up to date with the develop branch.
This morning things locked up again and looking through the logs I noticed some SQLite trace lines saying the database was locked.
I got it running again, updated to the latest develop version, deleted all my log files and log.db and started it up. The log starts with a whole load of db operations logged by the MigrationLogger which all complete correctly before it moves on to it’s normal start up process. I then see this:
15-3-19 10:59:42.6|Debug|HousekeepingService|Starting TrimLogDatabase
15-3-19 10:59:42.6|Info|Database|Vacuuming database
15-3-19 10:59:42.7|Info|Database|Database Compressed
15-3-19 10:59:42.7|Trace|Owin|
15-3-19 10:59:42.7|Trace|Owin|SQLite error (17): statement aborts at 32: [INSERT INTO [Logs]([Message],[Time],[Logger],[Exception],[ExceptionType],[Level]) VALUES(@Message,@Time,@Logger,@Exception,@ExceptionType,@Level)] d
atabase schema has changed
15-3-19 10:59:42.7|Trace|Owin|
15-3-19 10:59:42.7|Debug|HousekeepingService|Completed TrimLogDatabase
and this:
15-3-19 10:59:44.9|Debug|HousekeepingService|Compressing main database after housekeeping
15-3-19 10:59:44.9|Info|Database|Vacuuming database
15-3-19 10:59:45.3|Trace|Owin|
15-3-19 10:59:45.3|Trace|Owin|SQLite error (17): statement aborts at 17: [DELETE FROM [SceneMappings] WHERE ([Type] = @P0) ] database schema has changed
15-3-19 10:59:45.3|Trace|Owin|
15-3-19 10:59:45.3|Trace|Owin|
15-3-19 10:59:45.3|Trace|Owin|SQLite error (17): statement aborts at 25: [INSERT INTO [SceneMappings] ([Title],[ParseTerm],[SearchTerm],[TvdbId],[SeasonNumber],[Type]) VALUES (@Title,@ParseTerm,@SearchTerm,@TvdbId,@SeasonN
umber,@Type);] database schema has c
15-3-19 10:59:45.3|Trace|Owin|
15-3-19 10:59:45.4|Info|Database|Database Compressed
which doesn’t look good and I suspect leads onto a whole bunch of errors like this for every show:
15-3-19 11:00:15.3|Debug|ExistingMetadataService|Looking for existing metadata in /media/TV/Arrow
15-3-19 11:00:15.3|Trace|Owin|
15-3-19 11:00:15.3|Trace|Owin|SQLite error (5): database is locked
15-3-19 11:00:15.3|Trace|Owin|
Should I just bite the bullet and delete my main db at this point?
Making a backup and then trying it out with a small DB with a couple shows might be useful, but a DB lock could be on the logs.db still (the error doesn’t specify, so we can’t tell), the changing schema might be two different jobs trying to update the same table at the same time.
Does the nzbdrone.db contain all the config as well as the shows? If I delete it will I have to reconfigure everything or just add my shows again?
It contains most of the settings as well.
I only recommend trying this as a test, so setup the bare minimum, a few shows, download client and indexer to see if makes a difference for a night of shows.
Ultimately I don’t think this is going to do anything but prove its not a DB problem. Unless you have thousands of shows there likely isn’t much special about the DB.
I have the exact same issue. It just stops or gets stuck in certain functions. Right now it is stuck on searching an indexer for a show. Other times a wake up to it being completely unresponsive. Only way to recover is a restart from freenas.
I never updated with my experiences, but I kept my old DB and just removed a load of shows that weren’t currently airing. This made a huge difference and Sonarr has been solid for a while now. I’ve gradually added some of the removed shows back and so far it is still working.
I don’t know if there was a certain show that broke it or not, but if it happens again I’ll be back with more logs to try and track down what’s going on.
I backed up the DB and did a clean install, then reimported DB. It seems to be running a lot more stable now. I have an import problem now, where it doesn’t import some file that it says it doesn’t exist. I will post that under an other topic thanks.