I'm trying to troubleshoot why a restart of a SLES/OES server resulted in a very long delay after restart before NSS volumes mounted.

The server is:
Novell OES 11
Version 11.2
Patchlevel 2
SLES 11
Version 11
Patchlevel 3

The server does not yet have the July updates applied.

The restart of the server was needed as CIFS connections were being refused and a restart of the CIFS process failed due to a locked PID. We do see this problem with CIFS across a number of servers. However this problem was on the restart and not directly a result of the CIFS problem (although never rule anything out.)

On restart I was able to login to the desktop and could see that no volumes were mounted.

I checked /var/log/boot.msg and could see that the final entry at this point was:

<notice -- Sep 2 23:12:40.714719000> 'cron start' exits with status 0
<notice -- Sep 2 23:12:40.716282000> novell-nss start
Starting Novell Storage Services (NSS)
<notice -- Sep 2 23:12:42.651982000>
checkproc: /usr/sbin/namcd
4374



I also ran top and could see that some of the processes running were 'mount' which I'm assuming were processing the request to bring the volumes online.

The messages log contained this information:

Sep 2 23:12:42 studata03 nss: Start up NSS modules
Sep 2 23:12:42 studata03 kernel: [ 172.938638] NWRAID1: Initializing
Sep 2 23:12:42 studata03 kernel: [ 172.938767] NWRAID: Initializing
Sep 2 23:12:42 studata03 kernel: [ 172.938865] NWRAID5: Initializing
Sep 2 23:12:43 studata03 kernel: [ 173.013550] libnss loaded
Sep 2 23:12:43 studata03 kernel: [ 173.013555] Number RTSC counts in a microsecond is 2199
Sep 2 23:12:43 studata03 kernel: [ 173.147002] nsslnxlib loading...
Sep 2 23:12:43 studata03 kernel: [ 173.312016] Opening Unicode table 437
Sep 2 23:12:43 studata03 kernel: [ 173.423879] Open Unicode table status 0
Sep 2 23:12:43 studata03 kernel: [ 173.423885] Loaded host locale
Sep 2 23:12:43 studata03 kernel: [ 173.423888] nsslnxlib loaded
Sep 2 23:12:43 studata03 kernel: [ 173.511133] library loaded
Sep 2 23:12:43 studata03 kernel: [ 173.575573] NSS::/usr/src/packages/BUILD/nss/modules-build/nss/nssLKM.c[254]
Sep 2 23:12:43 studata03 kernel: [ 173.575579] NSS::/usr/src/packages/BUILD/nss/modules-build/nss/nssLKM.c[256]
Sep 2 23:12:43 studata03 kernel: [ 173.575582] register NSS_ConsoleCmdParser
Sep 2 23:12:43 studata03 kernel: [ 173.575584] ParseNSSConfigFile
Sep 2 23:12:43 studata03 kernel: [ 173.575708] now open config files: /etc/opt/novell/nss/nssstart.cfg
Sep 2 23:12:43 studata03 kernel: [ 173.577934] NSSGlobal_Startup
Sep 2 23:12:43 studata03 kernel: [ 173.577947] Importing LibC Unicode support
Sep 2 23:12:43 studata03 kernel: [ 173.580132] Opening Unicode table 1
Sep 2 23:12:43 studata03 kernel: [ 173.962968] Open Unicode table status 0
Sep 2 23:12:44 studata03 kernel: [ 173.968158] FDAT_UnitTest(start)
Sep 2 23:12:44 studata03 kernel: [ 173.968161] This test assumes USA locale.
Sep 2 23:12:44 studata03 kernel: [ 173.968168] Nov 1, 2000 11:35:28 am
Sep 2 23:12:44 studata03 kernel: [ 173.968172] May 14, 2001 3:55:44 pm
Sep 2 23:12:44 studata03 kernel: [ 173.968335] FDAT_UnitTest did not detect any errors in 116 tests.
Sep 2 23:12:44 studata03 kernel: [ 173.968337] FDAT_UnitTest(end)
Sep 2 23:12:44 studata03 kernel: [ 173.968341] NSS::/usr/src/packages/BUILD/nss/modules-build/nss/nssLKM.c[336]
Sep 2 23:12:44 studata03 kernel: [ 174.141791] ndpmod:misc_register called at tv_sec:1441231964 tv_usec:177746 retval = 0 success
Sep 2 23:12:44 studata03 kernel: [ 174.142034] Module ndpmod installed
Sep 2 23:12:44 studata03 ndpapp[4972]: stat of /dev/ndp at time tv_sec:1441231964 tv_usec:703914 errno=0 success
Sep 2 23:12:47 studata03 kernel: [ 177.107241] COMN::/usr/src/packages/BUILD/nss/modules-build/comn/comnLKM.c[198]
Sep 2 23:12:47 studata03 kernel: [ 177.107746] MaxBuffer_s = 3049205
Sep 2 23:12:47 studata03 kernel: [ 177.157416] NumPagesToWait = 762301
Sep 2 23:12:47 studata03 kernel: [ 177.488764] COMN::/usr/src/packages/BUILD/nss/modules-build/comn/comnLKM.c[200]=0
Sep 2 23:12:47 studata03 kernel: [ 177.804632] ZLSS::/usr/src/packages/BUILD/nss/modules-build/zlss/zlssLKM.c[233]
Sep 2 23:12:47 studata03 kernel: [ 177.807169] ZLSS::/usr/src/packages/BUILD/nss/modules-build/zlss/zlssLKM.c[235]
Sep 2 23:12:47 studata03 kernel: [ 177.857278] MANAGE::/usr/src/packages/BUILD/nss/modules-build/manage/manageLKM.c[239]
Sep 2 23:12:47 studata03 kernel: [ 177.857830] MANAGE::/usr/src/packages/BUILD/nss/modules-build/manage/manageLKM.c[241]
Sep 2 23:12:47 studata03 kernel: [ 177.883213] Opening trustee file: /etc/opt/novell/nss/trustees.xml
Sep 2 23:12:48 studata03 kernel: [ 178.044423] LSA::/usr/src/packages/BUILD/nss/modules-build/lsa/lsaLKM.c[547]
Sep 2 23:12:48 studata03 kernel: [ 178.046559] LSA::lsaLKM[549]
Sep 2 23:12:48 studata03 kernel: [ 178.183491] zapi loaded
Sep 2 23:12:51 studata03 jstcpd: jstcp: starting
Sep 2 23:12:51 studata03 jstcpd: Jet Stream starting with Connections NoActivity Timeout to be 300 seconds
Sep 2 23:12:53 studata03 vlrpc: VLRPC: Started !!
Sep 2 23:12:55 studata03 kernel: [ 185.388669] sdb: sdb1
Sep 2 23:12:55 studata03 kernel: [ 185.396280] sdc: sdc1
Sep 2 23:12:55 studata03 kernel: [ 185.403052] sdd: sdd1
Sep 2 23:12:55 studata03 kernel: [ 185.408528] sde: sde1
Sep 2 23:12:55 studata03 kernel: [ 185.414737] sdf: sdf1
Sep 2 23:12:55 studata03 kernel: [ 185.420931] sdg: sdg1
Sep 2 23:12:55 studata03 kernel: [ 185.601617] NSSLOG ==> [MSAP] comnLog[201]
Sep 2 23:12:55 studata03 kernel: [ 185.601620] Pool "POOLPROFT8B" - MSAP activate.
Sep 2 23:12:55 studata03 kernel: [ 185.601622] Server(8048cc92-1ca8-11e4-bc-f6-005056803a73) Cluster(00000000-0000-0000-00-00-000000000000)
Sep 2 23:12:55 studata03 kernel: [ 185.601631] NSSLOG ==> [MSAP] comnLog[201]
Sep 2 23:12:55 studata03 kernel: [ 185.601632] Pool "POOLPROFT8B" - Watching pool.
Sep 2 23:12:55 studata03 kernel: [ 185.775381] NSSLOG ==> [Upgrade] zlssUpgrade[3224]
Sep 2 23:12:55 studata03 kernel: [ 185.775384] ZLSS upgrade thread started.
Sep 2 23:12:56 studata03 kernel: [ 186.065519] NSSLOG ==> [MSAP] comnLog[201]
Sep 2 23:12:56 studata03 kernel: [ 186.065522] Pool "POOLUSRT80" - MSAP activate.
Sep 2 23:12:56 studata03 kernel: [ 186.065523] Server(8048cc92-1ca8-11e4-bc-f6-005056803a73) Cluster(00000000-0000-0000-00-00-000000000000)
Sep 2 23:12:56 studata03 kernel: [ 186.065533] NSSLOG ==> [MSAP] comnLog[201]
Sep 2 23:12:56 studata03 kernel: [ 186.065534] Pool "POOLUSRT80" - Watching pool.
Sep 2 23:13:05 studata03 nlvm: WARNING: Waited 10 seconds executing: mount -t nsspool /dev/pool/POOLUSRT80 /opt/novell/nss/mnt/.pools/POOLUSRT80 -o name=POOLUSRT80
Sep 2 23:13:15 studata03 nlvm: WARNING: Waited 10 seconds executing: mount -t nsspool /dev/pool/POOLUSRT80 /opt/novell/nss/mnt/.pools/POOLUSRT80 -o name=POOLUSRT80
Sep 2 23:13:24 studata03 nlvm: WARNING: Waited 10 seconds executing: mount -t nsspool /dev/pool/POOLUSRT80 /opt/novell/nss/mnt/.pools/POOLUSRT80 -o name=POOLUSRT80
Sep 2 23:13:34 studata03 nlvm: WARNING: Waited 10 seconds executing: mount -t nsspool /dev/pool/POOLUSRT80 /opt/novell/nss/mnt/.pools/POOLUSRT80 -o name=POOLUSRT80
Sep 2 23:13:41 studata03 [XTCOM]: WARNING: gdm_session_settings_load: lang = (null)
Sep 2 23:13:43 studata03 nlvm: WARNING: Waited 10 seconds executing: mount -t nsspool /dev/pool/POOLUSRT80 /opt/novell/nss/mnt/.pools/POOLUSRT80 -o name=POOLUSRT80
Sep 2 23:13:46 studata03 pam_autoncl[4997]: Auto Login will not continue - disabled for root user
Sep 2 23:13:47 studata03 checkproc: checkproc: can not get session id for process 5570!
Sep 2 23:13:51 studata03 pulseaudio[5624]: pid.c: Stale PID file, overwriting.
Sep 2 23:13:53 studata03 nlvm: WARNING: Waited 10 seconds executing: mount -t nsspool /dev/pool/POOLUSRT80 /opt/novell/nss/mnt/.pools/POOLUSRT80 -o name=POOLUSRT80
Sep 2 23:13:54 studata03 vmusr[5585]: [ warning] [Gtk] Unable to locate theme engine in module_path: "clearlooks",
Sep 2 23:13:54 studata03 vmusr[5585]: [ warning] [Gtk] Unable to locate theme engine in module_path: "clearlooks",
Sep 2 23:13:54 studata03 vmusr[5585]: [ warning] [Gtk] Unable to locate theme engine in module_path: "clearlooks",
Sep 2 23:13:54 studata03 vmusr[5585]: [ warning] [Gtk] Unable to locate theme engine in module_path: "pixmap",
Sep 2 23:13:54 studata03 vmusr[5585]: [ warning] [Gtk] Unable to locate theme engine in module_path: "pixmap",
Sep 2 23:13:54 studata03 vmusr[5585]: [ warning] [Gtk] Unable to locate theme engine in module_path: "pixmap",
Sep 2 23:13:54 studata03 vmusr[5585]: [ warning] [Gtk] Unable to locate theme engine in module_path: "pixmap",
Sep 2 23:13:54 studata03 vmusr[5585]: [ warning] [Gtk] Unable to locate theme engine in module_path: "pixmap",
Sep 2 23:13:54 studata03 vmusr[5585]: [ warning] [Gtk] Unable to locate theme engine in module_path: "pixmap",
Sep 2 23:13:54 studata03 vmusr[5585]: [ warning] [Gtk] Unable to locate theme engine in module_path: "pixmap",
Sep 2 23:13:54 studata03 vmusr[5585]: [ warning] [Gtk] Unable to locate theme engine in module_path: "pixmap",
Sep 2 23:13:54 studata03 vmusr[5585]: [ warning] [Gtk] Unable to locate theme engine in module_path: "pixmap",
Sep 2 23:13:54 studata03 vmusr[5585]: [ warning] [Gtk] Unable to locate theme engine in module_path: "pixmap",
Sep 2 23:13:54 studata03 vmusr[5585]: [ warning] [Gtk] Unable to locate theme engine in module_path: "pixmap",
Sep 2 23:13:54 studata03 vmusr[5585]: [ warning] [Gtk] Unable to locate theme engine in module_path: "pixmap",
Sep 2 23:13:54 studata03 vmusr[5585]: [ warning] [Gtk] Unable to locate theme engine in module_path: "pixmap",
Sep 2 23:13:54 studata03 vmusr[5585]: [ warning] [Gtk] Unable to locate theme engine in module_path: "clearlooks",
Sep 2 23:13:54 studata03 vmusr[5585]: [ warning] [Gtk] gtk_disable_setlocale() must be called before gtk_init()
Sep 2 23:14:01 studata03 kernel: [ 251.051231] NSSLOG ==> [MSAP] comnLog[201]
Sep 2 23:14:01 studata03 kernel: [ 251.051234] Pool "POOLUSRT86" - MSAP activate.
Sep 2 23:14:01 studata03 kernel: [ 251.051236] Server(8048cc92-1ca8-11e4-bc-f6-005056803a73) Cluster(00000000-0000-0000-00-00-000000000000)
Sep 2 23:14:01 studata03 kernel: [ 251.051245] NSSLOG ==> [MSAP] comnLog[201]
Sep 2 23:14:01 studata03 kernel: [ 251.051246] Pool "POOLUSRT86" - Watching pool.
Sep 2 23:14:01 studata03 kernel: [ 251.441708] NSSLOG ==> [MSAP] comnLog[201]
Sep 2 23:14:01 studata03 kernel: [ 251.441709] Pool "POOLUSRT87" - MSAP activate.
Sep 2 23:14:01 studata03 kernel: [ 251.441710] Server(8048cc92-1ca8-11e4-bc-f6-005056803a73) Cluster(00000000-0000-0000-00-00-000000000000)
Sep 2 23:14:01 studata03 kernel: [ 251.441715] NSSLOG ==> [MSAP] comnLog[201]
Sep 2 23:14:01 studata03 kernel: [ 251.441715] Pool "POOLUSRT87" - Watching pool.
Sep 2 23:14:01 studata03 kernel: [ 251.756098] NSSLOG ==> [MSAP] comnLog[201]
Sep 2 23:14:01 studata03 kernel: [ 251.756099] Pool "POOLUSRT88" - MSAP activate.
Sep 2 23:14:01 studata03 kernel: [ 251.756100] Server(8048cc92-1ca8-11e4-bc-f6-005056803a73) Cluster(00000000-0000-0000-00-00-000000000000)
Sep 2 23:14:01 studata03 kernel: [ 251.756110] NSSLOG ==> [MSAP] comnLog[201]
Sep 2 23:14:01 studata03 kernel: [ 251.756111] Pool "POOLUSRT88" - Watching pool.
Sep 2 23:14:02 studata03 kernel: [ 252.255405] NSSLOG ==> [MSAP] comnLog[201]
Sep 2 23:14:02 studata03 kernel: [ 252.255407] Pool "POOLUSRT89" - MSAP activate.
Sep 2 23:14:02 studata03 kernel: [ 252.255407] Server(8048cc92-1ca8-11e4-bc-f6-005056803a73) Cluster(00000000-0000-0000-00-00-000000000000)
Sep 2 23:14:02 studata03 kernel: [ 252.255411] NSSLOG ==> [MSAP] comnLog[201]
Sep 2 23:14:02 studata03 kernel: [ 252.255412] Pool "POOLUSRT89" - Watching pool.
Sep 2 23:17:02 studata03 kernel: [ 432.551087] [448]: VMCI: Updating context from (ID=0xffffffff) to (ID=0xa4801047) on event (type=0).
Sep 2 23:20:21 studata03 kernel: [ 629.930847] NSSLOG ==> [Error] zasAuthModel[2098]
Sep 2 23:20:21 studata03 kernel: [ 629.930849] Sep 2, 2015 11:20:21 pm NSS<COMN>-4.16a-714:
Sep 2 23:20:21 studata03 kernel: [ 629.930850] Error removing visibility for trustees just removed
Sep 2 23:20:21 studata03 kernel: [ 629.930852]


There was no other activity in the messages log until 23:47 when the volumes suddenly appeared on the desktop and had been mounted.

I checked back with the boot.msg log at this point and it had been updated with this information which appears to be normal:


loading nwraid kernel module
loading admindrv kernel module
Creating /dev/admindrv major_number=251
loading libnss kernel module
loading nsslnxlib kernel module
loading nsslibrary kernel module
loading nss kernel module
loading ndpmod kernel module
Starting ndpapp daemon
Check for ndp devicec/dev/ndp
loading nsscomn kernel module
loading nsszlss kernel module
loading nssmanage kernel module
loading nsslsa kernel module
loading zapi kernel module
loading nebdrv kernel module
Creating /dev/userModeNebDrv major_number=249
Starting adminusd daemon
Mounting _admin volume
Starting jstcpd daemon
Starting vlrpc daemon
Scan devices and mount pools
Mounting all NSS volumes in /etc/fstab
Starting volmnd daemon
Starting ncp2nss daemon
NSS is running!
<notice -- Sep 2 23:47:46.168528000> 'novell-nss start' exits with status 0
<notice -- Sep 2 23:47:46.170192000> novell-xregd start
Starting novell-xregd...done
<notice -- Sep 2 23:47:46.387572000>
'novell-xregd start' exits with status 0

<notice -- Sep 2 23:47:46.389416000> smartd start
Starting smartd done
<notice -- Sep 2 23:47:46.670336000>
'smartd start' exits with status 0
<notice -- Sep 2 23:47:46.673206000>
nagios start

Starting Nagios
<notice -- Sep 2 23:47:47.380185000> startproc: execve (/usr/sbin/nagios) [ /usr/sbin/nagios -d /etc/nagios/nagios.cfg ], [ CONSOLE=/dev/console SELINUX_INIT=YES ROOTFS_FSTYPE=ext3 SHELL=/bin/sh TERM=linux ROOTFS_FSCK=0 crashkernel=256M-:128M LC_ALL=POSIX INIT_VERSION=sysvinit-2.86 REDIRECT=/dev/tty1 COLUMNS=96 PATH=/bin:/sbin:/usr/bin:/usr/sbin vga=0x314 DO_CONFIRM= RUNLEVEL=5 PWD=/ SPLASHCFG=/etc/bootsplash/themes/SLES/config/bootsplash-800x600.cfg PREVLEVEL=N LINES=33 HOME=/ SHLVL=2 splash=silent SPLASH=yes ROOTFS_BLKDEV=/dev/sda2 _=/sbin/startproc DAEMON=/usr/sbin/nagios ]
done
<notice -- Sep 2 23:47:47.658800000> 'nagios start' exits with status 0
<notice -- Sep 2 23:47:47.660624000> ncp2nss start
ncp2nss (20750) is running.
<notice -- Sep 2 23:47:47.750601000> 'ncp2nss start' exits with status 0
<notice -- Sep 2 23:47:47.752935000> novell-cifs start
Starting Novell CIFS Service
<notice -- Sep 2 23:47:48.630100000> startproc: execve (/usr/sbin/cifsd) [ /usr/sbin/cifsd ], [ CONSOLE=/dev/console SELINUX_INIT=YES ROOTFS_FSTYPE=ext3 SHELL=/bin/sh TERM=linux ROOTFS_FSCK=0 crashkernel=256M-:128M LC_ALL=POSIX INIT_VERSION=sysvinit-2.86 REDIRECT=/dev/tty1 COLUMNS=96 PATH=/bin:/sbin:/usr/bin:/usr/sbin vga=0x314 DO_CONFIRM= RUNLEVEL=5 PWD=/
SPLASHCFG=/etc/bootsplash/themes/SLES/config/bootsplash-800x600.cfg PREVLEVEL=N LINES=33 HOME=/ SHLVL=2 splash=silent SPLASH=yes ROOTFS_BLKDEV=/dev/sda2 _=/sbin/startproc DAEMON=/usr/sbin/cifsd ]
done
<notice -- Sep 2 23:47:48.958444000> 'novell-cifs start' exits with status 0
<notice -- Sep 2 23:47:48.960739000> novell-smdrd start
Starting smdrd daemon
<notice -- Sep 2 23:47:49.88882000>
startproc: execve (/opt/novell/sms/bin/smdrd) [
/opt/novell/sms/bin/smdrd
], [
CONSOLE=/dev/console
SELINUX_INIT=YES
ROOTFS_FSTYPE=ext3
SHELL=/bin/sh
TERM=linux
ROOTFS_FSCK=0
crashkernel=256M-:128M
LC_ALL=POSIX
INIT_VERSION=sysvinit-2.86
REDIRECT=/dev/tty1
COLUMNS=96
PATH=/bin:/sbin:/usr/bin:/usr/sbin
vga=0x314
DO_CONFIRM=
RUNLEVEL=5
PWD=/
SPLASHCFG=/etc/bootsplash/themes/SLES/config/bootsplash-800x600.cfg
PREVLEVEL=N
LINES=33
HOME=/
SHLVL=2
splash=silent
SPLASH=yes
ROOTFS_BLKDEV=/dev/sda2
_=/sbin/startproc
DAEMON=/opt/novell/sms/bin/smdrd
]
done
<notice -- Sep 2 23:47:49.215372000>
'novell-smdrd start' exits with status 0

<notice -- Sep 2 23:47:49.216166000> novfsd start
Starting Novell novfs daemon...
<notice -- Sep 2 23:47:49.324603000> start_daemon: execve (/opt/novell/ncl/bin/novfsd) [ /opt/novell/ncl/bin/novfsd ], [ CONSOLE=/dev/console SELINUX_INIT=YES ROOTFS_FSTYPE=ext3 SHELL=/bin/sh TERM=linux ROOTFS_FSCK=0 crashkernel=256M-:128M LC_ALL=POSIX LD_LIBRARY_PATH=${LD_LIBRARY_PATH}:/opt/novell/xtier/lib64:/opt/novell/nmas/client/lib64
INIT_VERSION=sysvinit-2.86 REDIRECT=/dev/tty1 COLUMNS=96 PATH=/bin:/sbin:/usr/bin:/usr/sbin vga=0x314 DO_CONFIRM= RUNLEVEL=5 PWD=/ SPLASHCFG=/etc/bootsplash/themes/SLES/config/bootsplash-800x600.cfg PREVLEVEL=N LINES=33 HOME=/ SHLVL=2 NCPL_DO_NOT_OVERWRITE_OPENLOG=1
splash=silent
SPLASH=yes XTIER_CODE_PAGE=ANSI_X3.4-1968 ROOTFS_BLKDEV=/dev/sda2 _=/sbin/start_daemon DAEMON=/opt/novell/ncl/bin/novfsd ]

No Config File Found - Using Defaults
novfsd: Novell Client for Linux Daemon
Copyright 1992-2005, by Novell, Inc. All rights reserved.
Version 3.0.3-1151

done
<notice -- Sep 2 23:47:49.377034000> 'novfsd start' exits with status 0
<notice -- Sep 2 23:47:49.378097000>
SuSEfirewall2_setup start

Starting Firewall Initialization (phase 2 of 2) done
<notice -- Sep 2 23:47:49.661779000> 'SuSEfirewall2_setup start' exits with status 0
Master Resource Control: runlevel 5 has been reached
Skipped services in runlevel 5: nfs
<notice -- Sep 2 23:47:49.664169000>
killproc: kill(612,3)





It looks like there was a problem, certainly a delay, which involved namcd. Has anyone experienced this problem themselves, and if so is there a fix? And what other avenues can I pursue to troubleshoot this (for example other logs)?


I will take this to Novell support if there are no answers although I'm not looking forward to arguing that this problem isn't caused by not having the most up to date version of VMware tools installed or the latest set of patches.

Any help would be appreciated.

Cheers,

Andy