first sequence boot issue after installation

[Jocko]

How did you verify that, if you connect the disk to Linux PC and looked at sda7 and sda8 then there is no proof that sda8 was mounted. With the output of mount you posted on previous page of this threat it was clear that sda8 was not mounted so it seems the mount command fialed.
If you have put it again in the nwsp1 then it has been booted twice.. ;)

I connected the disk on the usb port...
So, I read the boot.log and it is this with the fail message error.

Sda8, wasn't mounted. After the first boot, I done a command df and only sda 5 was mounted :

Code: Select all

df
Filesystem           1K-blocks      Used Available Use% Mounted on
/dev/root               151744    112496     31416  78% /
/dev/sda5               798508     17496    772900   2% /rw_fs
tmpfs                      200        72       128  36% /rw_fs/tmp/usr/var

[fvdw]

the only thing I can think of is that something is not right with permission set for nas conf database in sda5, that could cause failure of reading but then I would expect that the nas would not boot at all.

@jocko
the output of the log file you posted on page 5 in that detail can only be obtained in debug mode, that is disabled at first boot when using clean firmware..you need to change a setting in the firmware to get the detailed output, did you mix them up or changed the setting before putting back the new disk in the nwsp1?

[fvdw]

@jocko

in your output I notice this

Code: Select all

* Starting mount of volumes...
   - Mounting volume Default:
                      [ Fail ]
* Finishing mount of volumes...           [ Fail ]
* Generating Hosts File...              [ OK ]
* Configuring System Hostname... mwexec(): /usr/bin/hostname 'SPD8020-base.local'
          [ OK ]
* Configuring Samba...mwexec(): /bin/mkdir -p /share/1000/public
mwexec(): /bin/chmod 0777 /share/1000/public
                [ OK ]

the command behind configuring samba....mwexec():/bin/mkdir -p /share/1000/public
should not be there. It indicates that sda8 was not mounted and now it creates a public folder in /share/1000 that means in the the system directory (sda7)
When sda8 would have been mounted there would be no need to create the folder public as it would have been there already when sda8 would have been mounted on /share/100 and sda8 contains a folder "public"

Why the mount command fails at first boot to mount sda8 is still a question mark for me (on spd8020 it doesn't fail at first boot..)

[Jocko]

@jocko
the output of the log file you posted on page 5 in that detail can only be obtained in debug mode, that is disabled at first boot when using clean firmware..you need to change a setting in the firmware to get the detailed output, did you mix them up or changed the setting before putting back the new disk in the nwsp1?

Yes Fvdw,

After the various tests done witho the Langerak script , I made a last attempt with debug mode enabled from the first boot. The test disk is kept for now in this status.... ;)

If you want I can do another test with more echo commands in dm_mount_all() ?

[fvdw]

in debug mode you would expect an entry in the messages file in httpd section of logs there is also an error file

I noticed some issues in the main boot script as result some commands are not executed (more then one space between commands and options) sh shell doesn't like that. One of them has to do with setting of permission of /rw_fs folder, why it is then ok at second boot ??

[Jocko]

I had not looked in the right volume (sda5) :oops: ... There are many messages in the log var

Code: Select all

Jan  1 01:00:05 (none) syslog.info syslogd started: BusyBox v1.15.3
Jan  1 01:00:16 (none) local0.warn API[1970/01/01 01:00:16] userfunc_users_commit.finc(40)[430]: Error: cannot open rootpasswd file.
Jan  1 01:00:16 (none) auth.info passwd[445]: password for `dummy' changed by user `root'
Jan  1 01:00:17 (none) local0.warn API[1970/01/01 01:00:17] userfunc_users_commit.finc(102)[430]: userfunc_users_commit: no smb user for dummy.
Jan  1 01:00:17 (none) local2.notice sudo:     root : TTY=console ; PWD=/ ; USER=root ; COMMAND=/bin/mkdir -p /share/1000
Jan  1 01:00:17 (none) local0.warn API[1970/01/01 01:00:17] dm_mount_all.finc(59)[430]: Failed to mount /share/1000
Jan  1 01:00:18 (none) local0.warn API[1970/01/01 01:00:18] api_dhcpc.php(26)[468]: calling /etc/api/api_dhcpc.php deconfig
Jan  1 01:00:18 (none) local0.warn API[1970/01/01 01:00:18] dhcpcfunc_deconfig.finc(28)[468]: deconfig ifconfig eth0  FAILED!
Jan  1 01:00:18 (none) local0.warn API[1970/01/01 01:00:18] api_dhcpc.php(61)[468]: deconfig retcode: 1
Jan  1 01:00:25 (none) local0.warn API[1970/01/01 01:00:25] api_dhcpc.php(26)[471]: calling /etc/api/api_dhcpc.php bound
Jan  1 01:00:28 (none) local0.warn API[1970/01/01 01:00:27] api_dhcpc.php(61)[471]: bound retcode: 0
Jan  1 01:00:43 (none) local2.notice sudo:     root : TTY=console (deleted) ; PWD=/usr/htdocs ; USER=root ; COMMAND=/usr/bin/mrvlqosd
Jan  1 01:00:44 (none) local2.notice sudo:     root : TTY=console (deleted) ; PWD=/usr/htdocs ; USER=root ; COMMAND=/bin/df
Jan  1 01:00:45 (none) local0.warn API[1970/01/01 01:00:44] ftpfunc_restart.finc(349)[430]: Error: cannot create file [/tmp/var/log/proftpd/proftpd.log] in ftpfunc_restart() [1].
Jan  1 01:00:47 (none) local2.notice sudo:     root : TTY=console (deleted) ; PWD=/ ; USER=root ; COMMAND=/usr/bin/dropbear
Jan  1 01:00:47 (none) authpriv.warn dropbear[578]: Failed reading '/etc/dropbear/dropbear_dss_host_key', disabling DSS
Jan  1 01:00:49 (none) authpriv.info dropbear[578]: Warning: Reading the random source seems to have blocked. If you experience problems, you probably need to find a better entropy source.
Jan  1 01:01:01 (none) daemon.info init: starting pid 613, tty '': '/bin/sh'
Jan  1 01:01:13 (none) authpriv.info dropbear[578]: Running in background
Jan  1 01:01:42 (none) local0.warn API[1970/01/01 01:01:42] nasapi.inc(27)[511]: calling mrvlGetLanguage
Jan  1 01:01:42 (none) local0.warn API[1970/01/01 01:01:42] nasapi.inc(453)[511]: mrvlGetLanguage  Return Code: nl
Jan  1 01:01:42 (none) local0.warn API[1970/01/01 01:01:42] nasapi.inc(27)[511]: calling mrvlGetLanguage
Jan  1 01:01:42 (none) local0.warn API[1970/01/01 01:01:42] nasapi.inc(453)[511]: mrvlGetLanguage  Return Code: nl
Jan  1 01:02:19 (none) local0.warn API[1970/01/01 01:02:19] nasapi.inc(27)[511]: calling mrvlGetLanguage
Jan  1 01:02:19 (none) local0.warn API[1970/01/01 01:02:19] nasapi.inc(453)[511]: mrvlGetLanguage  Return Code: nl
Jan  1 01:02:20 (none) local0.warn API[1970/01/01 01:02:20] nasapi.inc(27)[511]: calling mrvlGetShare all
Jan  1 01:02:20 (none) local2.notice sudo:   nobody : TTY=unknown ; PWD=/usr/htdocs/global ; USER=root ; COMMAND=/bin/df
Jan  1 01:02:20 (none) local0.warn API[1970/01/01 01:02:20] nasapi.inc(453)[511]: mrvlGetShare all Return Code: Array
Jan  1 01:02:21 (none) local0.warn API[1970/01/01 01:02:21] nasapi.inc(27)[511]: calling mrvlGetVolumeSummary
Jan  1 01:02:21 (none) local2.notice sudo:   nobody : TTY=unknown ; PWD=/usr/htdocs/global ; USER=root ; COMMAND=/bin/df
Jan  1 01:02:21 (none) local2.notice sudo:   nobody : TTY=unknown ; PWD=/usr/htdocs/global ; USER=root ; COMMAND=/bin/df
Jan  1 01:02:21 (none) local0.warn API[1970/01/01 01:02:21] nasapi.inc(453)[511]: mrvlGetVolumeSummary  Return Code: Array


[fvdw]

well most of them are normal

In these lines it is shown that the directory /share/1000 was created but that the mount command for sda8 failed.

Code: Select all

Jan  1 01:00:17 (none) local2.notice sudo:     root : TTY=console ; PWD=/ ; USER=root ; COMMAND=/bin/mkdir -p /share/1000
Jan  1 01:00:17 (none) local0.warn API[1970/01/01 01:00:17] dm_mount_all.finc(59)[430]: Failed to mount /share/1000

The question is now why does it need a second boot to make the command work ?? (It's not needed on a spd8020 using exactly the same disk image)

[fvdw]

I added a line in the php script to see the mount command used, nothing wrong with that (in case of lacie nwsp1 /dev/sda6 should be /dev/sda8

Code: Select all

Jul  8 07:31:01 (none) local2.notice sudo:     root : TTY=ttyS0 ; PWD=/ ; USER=root ; COMMAND=/bin/mkdir -p /share/1000
Jul  8 07:31:01 (none) local0.warn API[2011/07/08 08:31:01] dm_mount_all.finc(57)[429]: mount command mount /dev/sda6 /share/1000 > /dev/null 2>&1


@jocko
I added this line on line 57 of dm_mount_all.finc to see the mount command used (of course debug mode enabled)

Code: Select all

logError(__FILE__,  __LINE__ , "mount command ".$cmd, LOG_WARNING);

To simulate firt time boot you could unmonut sda8 from /share/1000 and then delete /share/1000
ps be sure you unmounted /share/1000 first before removing /share/1000 otherwise you might delet all files on sda8
Just ceck if no files are present in /share/1000 before removing it.

[Jocko]

Ok fvdw,

I did the additional test :
and all the boot sequence runs well...

boot.log

Code: Select all

 * Starting syslogd... mwexec(): /sbin/syslogd
             [ OK ]
mwexec(): chown 99:99 /tmp/etc/nas_conf_vltl.xml
 * Initial Orion-Nas XML configuration file...       [ OK ]
 * Configuring Disks... mwexec(): /usr/sbin/noflushd -n 15 /dev/sda
             [ OK ]
 * Configuring System Users...
Warning: fopen(/etc/rootpasswd): failed to open stream: No such file or directory in /etc/finc/userfunc_users_commit.finc on line 38
mwexec(): /usr/bin/passwd -P dummy dummy
mwexec(): /usr/bin/smbpasswd -e 'dummy'
             [ OK ]
 * Starting mount of volumes...
   - Mounting volume Default:
                      [ OK ]
 * Finishing mount of volumes...           [ OK ]
 * Generating Hosts File...              [ OK ]
 * Configuring System Hostname... mwexec(): /usr/bin/hostname 'SPD8020-base.local'
          [ OK ] 
 * Configuring Samba...                [ OK ]
 * Configuring LAN interface... mwexec(): /sbin/ifconfig -a 'eth0' 169.254.146.160 netmask 255.255.0.0
mwexec(): /sbin/ifconfig 'eth0' up
mwexec(): /sbin/udhcpc -b -i 'eth0' -s /etc/api/api_dhcpc.php dhcpdCbScript
          [ OK ]
 * Starting udevd... mwexec(): /sbin/udevstart
mwexec(): /sbin/udevd
                [ OK ]
 * Starting web server... mwexec(): /usr/bin/httpd -f httpd.conf -d /etc
             [ OK ]
 * Initializing Timezone... mwexec(): ln -sf /usr/share/zoneinfo/Etc/GMT+1 /etc/localtime
             [ OK ]
mwexec(): /usr/bin/killall  smbd
mwexec(): /usr/bin/killall  nmbd
 * Configuring Samba...                [ OK ]
mwexec(): /usr/bin/killall  smbd
mwexec(): /usr/bin/killall  nmbd
mwexec(): /usr/sbin/nmbd -D -l /var/log/samba
mwexec(): /usr/sbin/smbd -D -l /var/log/samba
mwexec(): cat /etc/nas_services | grep TG | grep syncawayd
 * Starting syncawayd... mwexec(): /usr/bin/killall  syncawayd
mwexec(): /usr/sbin/syncawayd -n 3
             [ OK ]
 * Marvell mediaserver not started...mwexec(): /usr/bin/killall  zxtract
mwexec(): /usr/bin/killall  mrvldms
mwexec(): /usr/bin/killall  zfs
,QOSd... mwexec(): /usr/bin/killall  mrvlqosd
mwexec(): /usr/bin/killall -9 proftpd
 * Starting FTP Service... mwexec(): mkdir -p /var/proftpd
mwexec(): chmod 777 /var/proftpd
mwexec(): chmod 777 /etc
mwexec(): rm -Rf /etc/proftpd.conf
mwexec(): touch /etc/proftpd.conf
mwexec(): chmod 666 /etc/proftpd.conf
mwexec(): /bin/mkdir -pm 755 /tmp/var/log/proftpd
mwexec(): /usr/sbin/proftpd
mwexec(): chmod 755 /tmp/var/log/proftpd/proftpd.log
mwexec(): /usr/bin/killall -QUIT ez-ipupdate
starting php based setup routines step 2
 * Starting dropbear...              [ OK ]
starting php based setup routines step banner

messages

Code: Select all

Jan  1 01:00:05 (none) syslog.info syslogd started: BusyBox v1.15.3
Jan  1 01:00:16 (none) local0.warn API[1970/01/01 01:00:16] userfunc_users_commit.finc(40)[430]: Error: cannot open rootpasswd file.
Jan  1 01:00:16 (none) auth.info passwd[445]: password for `dummy' changed by user `root'
Jan  1 01:00:17 (none) local0.warn API[1970/01/01 01:00:17] userfunc_users_commit.finc(102)[430]: userfunc_users_commit: no smb user for dummy.
Jan  1 01:00:17 (none) local2.notice sudo:     root : TTY=ttyS0 ; PWD=/ ; USER=root ; COMMAND=/bin/mkdir -p /share/1000
Jan  1 01:00:17 (none) local0.warn API[1970/01/01 01:00:17] dm_mount_all.finc(57)[430]: mount command mount /dev/sda8 /share/1000 > /dev/null 2>&1
Jan  1 01:00:18 (none) local0.warn API[1970/01/01 01:00:18] api_dhcpc.php(26)[461]: calling /etc/api/api_dhcpc.php deconfig
Jan  1 01:00:19 (none) local0.warn API[1970/01/01 01:00:19] dhcpcfunc_deconfig.finc(28)[461]: deconfig ifconfig eth0  FAILED!
Jan  1 01:00:19 (none) local0.warn API[1970/01/01 01:00:19] api_dhcpc.php(61)[461]: deconfig retcode: 1
Jan  1 01:00:22 (none) local0.warn API[1970/01/01 01:00:22] api_dhcpc.php(26)[464]: calling /etc/api/api_dhcpc.php bound
Jan  1 01:00:25 (none) local0.warn API[1970/01/01 01:00:25] api_dhcpc.php(61)[464]: bound retcode: 0
Jan  1 01:00:40 (none) local2.notice sudo:     root : TTY=ttyS0 ; PWD=/usr/htdocs ; USER=root ; COMMAND=/usr/bin/mrvlqosd
Jan  1 01:00:41 (none) local2.notice sudo:     root : TTY=ttyS0 ; PWD=/usr/htdocs ; USER=root ; COMMAND=/bin/df
Jan  1 01:00:42 (none) local0.warn API[1970/01/01 01:00:42] ftpfunc_restart.finc(349)[430]: Error: cannot create file [/tmp/var/log/proftpd/proftpd.log] in ftpfunc_restart() [1].
Jan  1 01:00:44 (none) local2.notice sudo:     root : TTY=ttyS0 ; PWD=/ ; USER=root ; COMMAND=/usr/bin/dropbear
Jan  1 01:00:44 (none) authpriv.warn dropbear[573]: Failed reading '/etc/dropbear/dropbear_dss_host_key', disabling DSS
Jan  1 01:00:46 (none) authpriv.info dropbear[573]: Warning: Reading the random source seems to have blocked. If you experience problems, you probably need to find a better entropy source.
Jan  1 01:00:59 (none) daemon.info init: starting pid 608, tty '': '/bin/sh'
Jan  1 01:01:39 (none) authpriv.info dropbear[573]: Running in background
Jan  1 01:01:55 (none) authpriv.info dropbear[614]: Child connection from 192.168.1.42:1685
Jan  1 01:01:57 (none) authpriv.notice dropbear[614]: password auth succeeded for 'root' from 192.168.1.42:1685
Jan  1 01:01:58 (none) authpriv.warn dropbear[615]: lastlog_perform_login: Couldn't stat /var/log/lastlog: No such file or directory
Jan  1 01:01:58 (none) authpriv.warn dropbear[615]: lastlog_openseek: /var/log/lastlog is not a file or directory!

I think the problem is to look before running the function, maybe an initialization issue of permissions ...

[fvdw]

its very strange as the same image is used for the spd8020. In principle the first boot is the same on both spd8020 and nwsps1 with new disk as the basic file system (clean image is the same). The only difference is sda5. On the spd8020 the existing one is used, on the nwsp1 first install the one from the tar ball, but when extracting a tar ball the permission are maintained, as such it should be fine. But something is changed at first boot making the one ok..
For me is difficulty to debug as I can not reproduce it on the spd8020