I was having an issue with connecting to the ReadyNAS web admin. When I logged in I just got the loading bar. Eventually it timed out and gave me a few options to retry or check RAIDar, etc.
After some investigating I saw that I was getting a 500 error when the browser was trying to get dbbroker
. I checked the apache logs and found the following errors...
# systemctl status -a apache2
apache2.service - The Apache HTTP Server
Loaded: loaded (/lib/systemd/system/apache2.service; enabled)
Active: active (running) since Thu, 03 Sep 2015 21:03:37 -0500; 1min 51s ago
Process: 3016 ExecStart=/usr/sbin/apache2 $OPTIONS -k start (code=exited, status=0/SUCCESS)
Process: 2910 ExecStartPre=/frontview/bin/fvapps (code=exited, status=0/SUCCESS)
Main PID: 3018 (apache2)
CGroup: name=systemd:/system/apache2.service
├ 3018 /usr/sbin/apache2 -k start
├ 3019 apache_log
├ 3020 /usr/sbin/apache2 -k start
├ 3021 /usr/sbin/apache2 -k start
├ 3022 /usr/sbin/apache2 -k start
├ 3023 /usr/sbin/apache2 -k start
├ 3025 /usr/sbin/apache2 -k start
├ 3026 /usr/sbin/apache2 -k start
├ 3046 /usr/sbin/apache2 -k start
├ 3047 /usr/sbin/apache2 -k start
├ 3048 /usr/sbin/apache2 -k start
└ 3054 /usr/sbin/apache2 -k start
Sep 03 21:05:22 ReadyNas apache2[3048]: [error] [client 1.2.3.191] Premature end of script headers: dbbroker.cgi, referer: https://1.2.3.15/admin/
Sep 03 21:05:23 ReadyNas apache_access[3019]: 1.2.3.191 "POST /dbbroker HTTP/1.1" 500
Sep 03 21:05:23 ReadyNas apache_access[3019]: 1.2.3.191 "GET /favicon.ico HTTP/1.1" 200
Sep 03 21:05:24 ReadyNas apache2[3023]: [error] [client 1.2.3.191] Connect rddclient failed, referer: https://1.2.3.15/admin/
Sep 03 21:05:24 ReadyNas apache2[3023]: [error] [client 1.2.3.191] Premature end of script headers: dbbroker.cgi, referer: https://1.2.3.15/admin/
Sep 03 21:05:24 ReadyNas apache_access[3019]: 1.2.3.191 "POST /dbbroker HTTP/1.1" 500
Sep 03 21:05:26 ReadyNas apache2[3026]: [error] [client 1.2.3.191] Connect rddclient failed, referer: https://1.2.3.15/admin/
Sep 03 21:05:26 ReadyNas apache2[3026]: [error] [client 1.2.3.191] Premature end of script headers: dbbroker.cgi, referer: https://1.2.3.15/admin/
Sep 03 21:05:27 ReadyNas apache_access[3019]: Suppressed 1 duplicate messages
Sep 03 21:05:27 ReadyNas apache_access[3019]: 1.2.3.191 "GET /favicon.ico HTTP/1.1" 200
Well "Premature end of script headers: dbbroker.cgi" doesn't sound very good. Based on a hint from this thread, I checked the status of readynasd
...
# systemctl status -a readynasd
readynasd.service - ReadyNAS System Daemon
Loaded: loaded (/lib/systemd/system/readynasd.service; enabled)
Active: inactive (dead) since Thu, 27 Aug 2015 03:03:10 -0500; 1 weeks and 0 days ago
Main PID: 1345 (code=exited, status=0/SUCCESS)
Status: "Start Main process"
CGroup: name=systemd:/system/readynasd.service
Aug 27 00:00:25 ReadyNas readynasd[1345]: Snapshot 'c_1440651624' has been successfully created for share or LUN 'Pictures'.
Aug 27 00:00:26 ReadyNas readynasd[1345]: Snapshot 'c_1440651625' has been successfully created for share or LUN 'Videos'.
Aug 27 00:21:53 ReadyNas readynasd[1345]: Smart Snapshot successfully deleted snapshot '2015_07_30__00_00_40' from share or LUN 'Backup'.
Aug 27 00:22:00 ReadyNas readynasd[1345]: Smart Snapshot successfully deleted snapshot '2015_07_30__00_00_43' from share or LUN 'Documents'.
Aug 27 00:22:07 ReadyNas readynasd[1345]: Smart Snapshot successfully deleted snapshot '2015_07_30__00_00_44' from share or LUN 'Music'.
Aug 27 00:22:14 ReadyNas readynasd[1345]: Smart Snapshot successfully deleted snapshot '2015_07_30__00_00_45' from share or LUN 'Pictures'.
Aug 27 00:22:21 ReadyNas readynasd[1345]: Smart Snapshot successfully deleted snapshot '2015_07_30__00_00_46' from share or LUN 'Videos'.
Aug 27 03:03:09 ReadyNas readynasd[1345]: g_dbus_connection_real_closed: Remote peer vanished with error: Underlying GIOStream returned 0 bytes on an async read (g-io-error-quark, 0). Exiting.
Aug 27 03:03:09 ReadyNas readynasd[1345]: Exit main thread by SIGTERM.
Aug 27 03:03:09 ReadyNas readynasd[1345]: readynasd is halted.
Well, there's your problem. Let's fix that right up
# systemctl restart readynasd
.... wait for it .... wait for it ....
#systemctl status -a readynasd
readynasd.service - ReadyNAS System Daemon
Loaded: loaded (/lib/systemd/system/readynasd.service; enabled)
Active: active (running) since Thu, 03 Sep 2015 21:07:06 -0500; 35min ago
Main PID: 3138 (readynasd)
Status: "Start Main process"
CGroup: name=systemd:/system/readynasd.service
└ 3138 /usr/sbin/readynasd -v 3 -t
Sep 03 21:07:47 ReadyNas readynasd[3138]: Smart Snapshot successfully deleted snapshot '2015_08_04__00_00_33' from share or LUN 'Pictures'.
Sep 03 21:07:48 ReadyNas readynasd[3138]: Smart Snapshot successfully deleted snapshot '2015_08_03__00_00_57' from share or LUN 'Pictures'.
Sep 03 21:07:49 ReadyNas readynasd[3138]: Smart Snapshot successfully deleted snapshot '2015_08_02__00_00_19' from share or LUN 'Pictures'.
Sep 03 21:07:49 ReadyNas readynasd[3138]: Smart Snapshot successfully deleted snapshot '2015_07_04__00_00_43' from share or LUN 'Pictures'.
Sep 03 21:07:56 ReadyNas readynasd[3138]: Smart Snapshot successfully deleted snapshot '2015_08_06__00_00_28' from share or LUN 'Videos'.
Sep 03 21:07:56 ReadyNas readynasd[3138]: Smart Snapshot successfully deleted snapshot '2015_08_05__00_00_53' from share or LUN 'Videos'.
Sep 03 21:07:56 ReadyNas readynasd[3138]: Smart Snapshot successfully deleted snapshot '2015_08_04__00_00_34' from share or LUN 'Videos'.
Sep 03 21:07:57 ReadyNas readynasd[3138]: Smart Snapshot successfully deleted snapshot '2015_08_03__00_00_58' from share or LUN 'Videos'.
Sep 03 21:07:57 ReadyNas readynasd[3138]: Smart Snapshot successfully deleted snapshot '2015_08_02__00_00_21' from share or LUN 'Videos'.
Sep 03 21:07:57 ReadyNas readynasd[3138]: Smart Snapshot successfully deleted snapshot '2015_07_04__00_00_44' from share or LUN 'Videos'.
And we're back in business. Admin is once again functioning!