Re: RN104 start failed after update 6.5.0

TwILeK1 · ‎2016-05-31

Hi

I updated the RN104 Nas from 6.4.2 to 6.5.0. I started the update from readycloud website after upgraded my account

The nas downloaded and installed the new firmware, but can't start.

Readynasd get segmentation fault signal, create core dump file and exit.

pilgrim displays that the booting process at 97%, last message app.mounts (after removed the transmission app from console)

root@NyulNAS:~# systemctl status -a readynasd
readynasd.service - ReadyNAS System Daemon
Loaded: loaded (/lib/systemd/system/readynasd.service; enabled)
Active: activating (start) since Tue, 31 May 2016 22:51:16 +0200; 9s ago
Main PID: 9029 (readynasd)
Status: "Importing DB"
CGroup: name=systemd:/system/readynasd.service
└ 9029 /usr/sbin/readynasd -v 3 -t

May 31 22:51:16 NyulNAS readynasd[9029]: readynasd log started
May 31 22:51:16 NyulNAS readynasd[9029]: readynasd started. (restarted=0)
May 31 22:51:17 NyulNAS readynasd[9029]: DB (main) schema version: 20 ==> 20
May 31 22:51:17 NyulNAS readynasd[9029]: DB (queue) schema version: new ==> 0

sometime get these line too:

May 31 22:51:41 NyulNAS readynasd[9029]: get share quota fail.

root@NyulNAS:~# systemctl status -a apache2
apache2.service - The Apache HTTP Server
Loaded: loaded (/lib/systemd/system/apache2.service; enabled)
Active: active (running) since Tue, 31 May 2016 22:18:03 +0200; 34min ago
Main PID: 2790 (apache2)
CGroup: name=systemd:/system/apache2.service
├ 2790 /usr/sbin/apache2 -k start
├ 2791 apache_log
├ 2793 /usr/sbin/apache2 -k start
├ 2795 /usr/sbin/apache2 -k start
├ 2796 /usr/sbin/apache2 -k start
├ 2797 /usr/sbin/apache2 -k start
├ 2798 /usr/sbin/apache2 -k start
├ 2799 /usr/sbin/apache2 -k start
├ 2866 /usr/sbin/apache2 -k start
├ 7279 /usr/sbin/apache2 -k start
├ 8269 /usr/sbin/apache2 -k start
├ 8285 /usr/sbin/apache2 -k start
└ 8299 /usr/sbin/apache2 -k start

May 31 22:52:02 NyulNAS apache2[8269]: [error] [client 192.168.0.19] Connect rddclient failed, referer: https://192.168.0.200/admin/
May 31 22:52:02 NyulNAS apache2[8269]: [error] [client 192.168.0.19] Premature end of script headers: dbbroker.cgi, referer: https://192.168.0.200/admin/
May 31 22:52:06 NyulNAS apache2[2796]: [error] [client 192.168.0.19] Connect rddclient failed, referer: https://192.168.0.200/admin/
May 31 22:52:06 NyulNAS apache2[2796]: [error] [client 192.168.0.19] Premature end of script headers: dbbroker.cgi, referer: https://192.168.0.200/admin/
May 31 22:52:06 NyulNAS apache2[8299]: [error] [client 192.168.0.19] Connect rddclient failed, referer: https://192.168.0.200/admin/
May 31 22:52:06 NyulNAS apache2[8299]: [error] [client 192.168.0.19] Premature end of script headers: dbbroker.cgi, referer: https://192.168.0.200/admin/
May 31 22:52:09 NyulNAS apache2[7279]: [error] [client 192.168.0.19] Connect rddclient failed, referer: https://192.168.0.200/admin/
May 31 22:52:09 NyulNAS apache2[7279]: [error] [client 192.168.0.19] Premature end of script headers: dbbroker.cgi, referer: https://192.168.0.200/admin/
May 31 22:52:13 NyulNAS apache2[2798]: [error] [client 192.168.0.19] Connect rddclient failed, referer: https://192.168.0.200/admin/
May 31 22:52:13 NyulNAS apache2[2798]: [error] [client 192.168.0.19] Premature end of script headers: dbbroker.cgi, referer: https://192.168.0.200/admin/

Readynasd debug log:

[16/05/31 22:13:34] 3084:3084 readynasd.c:1164 () readynasd started. (restarted=0)
[16/05/31 22:14:18] 3084:3084 readynasd.c:1253 (info) Export all service configuration in order to take care OS Upgrade
[16/05/31 22:14:20] 3212:3212 readynasd.c:992 () readynasd log started
[16/05/31 22:14:20] 3212:3212 context.c:152 (debug) NEW GLOBAL_CONTEXT: db.sq3=0xdee500
[16/05/31 22:14:20] 3212:3212 context.c:188 (debug) NEW GLOBAL_CONTEXT: event.sq3=0xdf32b0
[16/05/31 22:14:20] 3212:3212 context.c:191 (debug) NEW GLOBAL_CONTEXT: globalctx=0xdedf28
[16/05/31 22:14:20] 3212:3212 readynasd.c:1164 () readynasd started. (restarted=0)
[16/05/31 22:15:35] 3212:3212 readynasd.c:1253 (info) Export all service configuration in order to take care OS Upgrade
[16/05/31 22:15:36] 3354:3354 readynasd.c:992 () readynasd log started
[16/05/31 22:15:36] 3354:3354 context.c:152 (debug) NEW GLOBAL_CONTEXT: db.sq3=0x1937500
[16/05/31 22:15:36] 3354:3354 context.c:188 (debug) NEW GLOBAL_CONTEXT: event.sq3=0x193c2b0
[16/05/31 22:15:36] 3354:3354 context.c:191 (debug) NEW GLOBAL_CONTEXT: globalctx=0x1936f28
[16/05/31 22:15:36] 3354:3354 readynasd.c:1164 () readynasd started. (restarted=0)

ads.log:

[16-05-31 22:53:30] 9500 rndb_account.c:609 error: Local user import has started.
[16-05-31 22:53:30] 9500 rndb_account.c:612 error: Removing all users from $user table excluding ADS users if exist.
[16-05-31 22:53:59] 9599 rndb_account.c:609 error: Local user import has started.
[16-05-31 22:53:59] 9599 rndb_account.c:612 error: Removing all users from $user table excluding ADS users if exist.
[16-05-31 22:54:26] 9688 rndb_account.c:609 error: Local user import has started.
[16-05-31 22:54:26] 9688 rndb_account.c:612 error: Removing all users from $user table excluding ADS users if exist.

db_event.log:

[16/05/31 22:13:35] 3084:3084 rndb_queue.c:59 (error) DB (queue) schema version: new ==> 0
[16/05/31 22:13:35] 3084:3084 rndb_queue.c:124 (debug) rndb_queue_create() ==> 0 (5ms)
[16/05/31 22:14:21] 3212:3212 rndb_queue.c:59 (error) DB (queue) schema version: new ==> 0
[16/05/31 22:14:21] 3212:3212 rndb_queue.c:124 (debug) rndb_queue_create() ==> 0 (5ms)
[16/05/31 22:15:37] 3354:3354 rndb_queue.c:59 (error) DB (queue) schema version: new ==> 0
[16/05/31 22:15:37] 3354:3354 rndb_queue.c:124 (debug) rndb_queue_create() ==> 0 (5ms)

fwbroker.log

May 31 2016 22:47:44 Authorized granted for user: admin
May 31 2016 22:47:44 INFO: request method POST
May 31 2016 22:47:44 INFO: dpv_=dpv_1464727660000, njl_id_=njl_id_230, type=FirmwareProgress
May 31 2016 22:47:45 Authorized granted for user: admin
May 31 2016 22:47:45 INFO: request method POST
May 31 2016 22:47:45 INFO: dpv_=dpv_1464727660000, njl_id_=njl_id_244, type=FirmwareImage
May 31 2016 22:47:45 INFO:AAGET_LOCAL_INFO: sinfo .model=ReadyNAS, model_num=104, .serial=3EPB44EM00385, .firmware_name=(null), .firmware_version=6.5.0
May 31 2016 22:47:45 INFO:AAGET_REMOTE_INFO(STEP 1 URL:) http://update.readynas.com/download/ReadyNASOS-arm/index?key=d4cd51e5cc36bb0736f67eb9123ae453&model=...
ersion=6.5.0
May 31 2016 22:47:46 answer=info::name=ReadyNASOS,version=6.5.0,time=1463182439,size=61579264,md5sum=f4fcd05fdb724eddf453948c4f0fe7be,arch=arm,descr=ReadyNASOS Update,release_notes=https://
kb.netgear.com/app/answers/detail/a_id/30662
May 31 2016 22:47:46 INFO:AAGET_REMOTE_INFO: version:6.5.0 size:61579264 descr:ReadyNASOS Update release_notes:https://kb.netgear.com/app/answers/detail/a_id/30662 md5sum:f4fcd05fdb724eddf4
53948c4f0fe7be time:1463182439

Please help, and sorry for my bad english 😞

TwILeK1 · ‎2016-06-01

Hi

Problem solved.

I mounted some directory from externa usb device in fstab

But when booting the device first try to mount disks from NOT mounted device ... (directory not found)

So can fix readynasd to skip these user error and log out 🙂

Remove it -> /media/USB_HDD_5/MyData /Data/MyData rw bind

View solution in original post

mdgm-ntgr · ‎2016-05-31

How full is the 4GB root volume?

# df -h

# df -i

Which apps or other packages have you installed?

Can you send in your logs (see the Sending Logs link in my sig)?

TwILeK1 · ‎2016-05-31

Hi

root@NyulNAS:~# df -h
Filesystem Size Used Avail Use% Mounted on
udev 10M 4.0K 10M 1% /dev
/dev/md0 4.0G 2.0G 1.8G 53% /
tmpfs 249M 0 249M 0% /dev/shm
tmpfs 249M 1.2M 248M 1% /run
tmpfs 249M 0 249M 0% /sys/fs/cgroup
tmpfs 249M 0 249M 0% /media
/dev/md124 4.6T 4.1T 469G 90% /Data
tmpfs 249M 0 249M 0% /Data/Filmek/Mese
tmpfs 249M 0 249M 0% /Data/Filmek/Dokumentum
tmpfs 249M 0 249M 0% /Data/Filmek/_3D
tmpfs 249M 0 249M 0% /Data/Filmek/Western
/dev/md124 4.6T 4.1T 469G 90% /home
/dev/md124 4.6T 4.1T 469G 90% /apps

root@NyulNAS:~# df -i
Filesystem Inodes IUsed IFree IUse% Mounted on
udev 63201 471 62730 1% /dev
/dev/md0 65536 36418 29118 56% /
tmpfs 63641 1 63640 1% /dev/shm
tmpfs 63641 597 63044 1% /run
tmpfs 63641 9 63632 1% /sys/fs/cgroup
tmpfs 63641 7 63634 1% /media
/dev/md124 0 0 0 - /Data
tmpfs 63641 7 63634 1% /Data/Filmek/Mese
tmpfs 63641 7 63634 1% /Data/Filmek/Dokumentum
tmpfs 63641 7 63634 1% /Data/Filmek/_3D
tmpfs 63641 7 63634 1% /Data/Filmek/Western
/dev/md124 0 0 0 - /home
/dev/md124 0 0 0 - /apps

Apps:

mysqlr6

phpmyadminr6

smbplus

Installed packages:

dpkg-query -l -> http://www.twilek.hu/apps.dpkg.txt

The admin page don't loading, so i can't download logs, but i can tar gz the /var/log/readynasd (i sent the logs to the email address)

mdgm-ntgr · ‎2016-05-31

Can you download the logs using RAIDar 6.1? If so, can you send those in?

Your data volume is very full.

There's quite a bit on the 4GB root volume as well.

TwILeK1 · ‎2016-06-01

Hello

I sent the logs, donwloaded by raider6 THANKS!

Yes Data partition is highly used 😄 but it's only a data store, it was on 98% too 🙂

THANKS

mdgm-ntgr · ‎2016-06-01

Well the firmware upgrade guide and tips indicates that updating the firmware when the volume is very full is not recommended.

You really should keep your volume under 80% full.

You are using a non-redundant volume configuration and one of your disks has a non-zero current pending sector count.

You probably should backup your data, do a factory default (wipes all data, settings, everything) with good disks installed and restore your data from backup.

TwILeK1 · ‎2016-06-01

Hi

420GB free space onn /Data partition ... i think it more than enough 🙂

I can't save my data, more than 3.5 TB ... 😞

Can i reinstall the 6.5 without loosing data? from ssh console?

or revert back only readynasd binary?

TwILeK1 · ‎2016-06-01

Hi

Problem solved.

I mounted some directory from externa usb device in fstab

But when booting the device first try to mount disks from NOT mounted device ... (directory not found)

So can fix readynasd to skip these user error and log out 🙂

Remove it -> /media/USB_HDD_5/MyData /Data/MyData rw bind