Another reason to love ZFS

While perusing the ZFS mailing list last today, I came across several interesting replies to a message titled “recover zfs data from a crashed system?”. I have been using ZFS now for 6-months, and the following reply is just one of the reasons I trust my data with it:

“I built a test zpool spanning 7 drives (raidz) on S10U2. The 7 disks were split between 3 controllers. I then started replacing the 18GB drives with 36GB drives, one at a time, and watched it rebuild the zpool, growing as it did.Finally, when I had all the drives replaced, I took the system down, moved the drives around on the controllers, reloaded the OS onto the internal drives on my Sun Blade 1000 workstation. I then forced a write of random data to one of the drives in the 7 disk raidz array. Then I did the zpool import – it reported the array, with errors. I did the zpool import , and it came right in, and mounted up. From there I did a scrub (and yes, it did essentially chew up all available system resources, while it scrubbed the 200+GB pool on this small and not so mighty system), and it corrected all the issues. All in all it was a good test, and I was rather impressed that it was able to juggle re-ordering of the drives, re-enumeration of the controllers they were attached to, erasure of one of the drives, all while importing the pool on a rebuilt system.

Fixing a broken Solaris zone

I applied the latest set of patches to my x86 Solaris 10 server this morning, and after the server was rebooted I noticed that my zones didn’t start. When I ran the zoneadm utility with the “list” option, all of the zones were in the “installed” state (they should be in the running state since the autoboot variables was set to true):

$ zoneadm list -vc

  ID NAME             STATUS         PATH                          
   0 global           running        /                             
   - z1-t             installed      /zones/z1-t               
   - z2-d             installed      /zones/z2-d               
   - z3-p             installed      /zones/z3-p             

At first I thought the zones service might be in the maintenance state, but after reviewing the output from the svcs command, that theory turned out to be incorrect:

$ svcs -a | grep zones

online          8:39:22 svc:/system/zones:default

Since the box contained several critical services, I decided to start the zones by hand and perform mostmortem analysis after the zones were back up and operational. When I ran zoneadm with the the “boot” option and the name of the zone to boot, I was greeted with the following error:

$ zoneadm -z dns boot

zoneadm: zone 'dns': Failed to initialize privileges: No such file or directory
zoneadm: zone 'dns': call to zoneadmd failed

Oh good grief! After reviewing my notes, I noticed that I had applied patch 122663-06 (a libezonecfg patch) as part of the patch bundle. Configurable zone privileges are coming as part of Solaris 10 update 3, and it looks like they prematurely made their way into a Solaris 10 patch. Since I have not had a chance to play with configurable privileges, I decided to create a new zone to see if zonecfg worked ok, and also to see if configurable privileges required additional attributes:

$ zonecfg -z test

test: No such zone configured
Use 'create' to begin configuring a new zone.
zonecfg:test> create
zonecfg:test> info
zonepath: 
autoboot: false
pool: 
inherit-pkg-dir:
        dir: /lib
inherit-pkg-dir:
        dir: /platform
inherit-pkg-dir:
        dir: /sbin
inherit-pkg-dir:
        dir: /usr
zonecfg:test> set zonepath=/zones/test
zonecfg:test> commit
ld.so.1: zonecfg: fatal: relocation error: file /usr/sbin/zonecfg: symbol zonecfg_add_index: referenced symbol not found
Killed

Well that isn’t good, and the output from the info command doesn’t seem to indicate that new attributes were added. I needed to get the box up and running, so I decided to try to back out patch 122663-06. When I ran patchrm to remove the patch, it bombed out since it wasn’t able to start the zones:

$ patchrm 122663-06

Validating patches...

Loading patches installed on the system...

Done!

Checking patches that you specified for removal.

Done!

Approved patches will be removed in this order:

122663-06 
Preparing checklist for non-global zone check...

Checking non-global zones...

Booting non-global zone dns for patch check...
 ERROR: unable to boot zone: problem running  on zone : error 1
zoneadm: zone 'dns': Failed to initialize privileges: No such file or directory
zoneadm: zone 'dns': call to zoneadmd failed

Can not boot non-global zone dns

Gak! Once I realized that backing out the patch with patchrm wouldn’t work, I decided to back up the libzonecfg shared library that 122663-06 had installed, and copy the previous version over it. To find the previous version, I used the find command in the /var/sadm directory:

$ cd /var/sadm

$ find . -name 122663-06

./pkg/SUNWcsr/save/pspool/SUNWcsr/save/122663-06
./pkg/SUNWcsr/save/122663-06
./pkg/SUNWzoneu/save/pspool/SUNWzoneu/save/122663-06
./pkg/SUNWzoneu/save/122663-06
./patch/122663-06

After I located the patch directories, I looked for the file named undo.Z. The undo.Z file contains a backup of each file the patch overwrites, and is used by the patchrm utility to restore a server to it’s previosu state. To find the right undo.Z file, I ran the find command in the pkg/SUNWzoneu directory, and then used the ls “-i” (print inode) and “-l” (long output) options to print the inode number and size of each undo.Z file I found:

$ ls -li ./pkg/SUNWzoneu/save/pspool/SUNWzoneu/save/122663-06/*.Z ./pkg/SUNWzoneu/save/122663-06/*.Z

    102041 -rw-r--r--   1 root     root      158534 Oct 29 08:56 ./pkg/SUNWzoneu/save/122663-06/undo.Z
    101589 -rw-r--r--   1 root     root      158534 Oct 29 08:56 ./pkg/SUNWzoneu/save/pspool/SUNWzoneu/save/122663-06/undo.Z

Since the size and timestamps on the files I located were identical (as a side note — I am curious why Sun keeps two copies of the undo.Z file. If anyone knows, please add your thoughts to the comment section. ), I copied one of the files to /tmp, and used the uncompress and pkgadd utilities to extract the file to /tmp/u:

$ cp undo.Z /tmp

$ cd /tmp

$ uncompress undo.Z

$ pkgadd -s /tmp/u -d undo

The following packages are available:
  1  SUNWzoneu     Solaris Zones (Usr)
                   (i386) 11.10.0,REV=2005.01.21.16.34

Select package(s) you wish to process (or 'all' to process
all packages). (default: all) [?,??,q]: 
Transferring  package instance

Once the packages were extracted to /tmp/u, I started to poke around to see which files were included in the package:

$ cd /tmp/u/*

$ find .

.
./pkginfo
./pkgmap
./install
./install/checkinstall
./install/postinstall
./reloc
./reloc/usr
./reloc/usr/lib
./reloc/usr/lib/amd64
./reloc/usr/lib/amd64/libzonecfg.so.1
./reloc/usr/lib/libzonecfg.so.1
./reloc/usr/share
./reloc/usr/share/lib
./reloc/usr/share/lib/xml
./reloc/usr/share/lib/xml/dtd
./reloc/usr/share/lib/xml/dtd/zonecfg.dtd.1

Since the new version of libzonecfg.so was most likely the cause of my problems, I backed up the shared libraries the patch had installed in /usr/lib and /usr/lib/amd, and then replaced these with the versions I had extracted to /tmp/u:

$ cd /usr/lib

$ pwd
/usr/lib

$ cp libzonecfg.so.1 libzonecfg.so.1.orig

$ cp /tmp/u/SUNWzoneu/reloc/usr/lib/libzonecfg.so.1 .

$ cd /usr/lib/amd

$ pwd
/usr/lib/amd

$ cp libzonecfg.so.1 libzonecfg.so.1.orig

$ cp /tmp/u/SUNWzoneu/reloc/usr/lib/amd/libzonecfg.so.1 .

Once the old version of libzonecfg was in place, I was able to boot my zones without issue:

$ zoneadm -z dns boot

This experience once again leads me to wonder if Sun actually tests patches prior to sending them out to the public (this is my second bad experience in as many months). Now to schedule another downtime to properly back out the patch. :(

Viewing previous dates with GNU date

GNU date has some nifty options, and is a time keepers toolbox rolled up into an ELF executable. One really cool option in GNU date is the ability to print a date in the past using the the “–date” option, and the “days ago” format string:

$ date –date=”30 days ago”
Wed Aug 30 15:15:51 EDT 2006

$ date –date=”10 years ago”
Sun Sep 29 15:15:56 EDT 1996

Now if only more vendors would include GNU date with their operating system. :)

Solaris needs SMART support! Please help!

While attempting to run the smartctl utility a few weeks back on an x86 Solaris 10 host with IDE disk drives, I received the following error:

$ smartctl -a /dev/dsk/c1d0s0

smartctl version 5.36 [i386-pc-solaris2.10] Copyright (C) 2002-6 Bruce Allen
Home page is http://smartmontools.sourceforge.net/

#######################################################################
ATA command routine ata_command_interface() NOT IMPLEMENTED under Solaris.
Please contact smartmontools-support@lists.sourceforge.net if
you want to help in porting smartmontools to Solaris.
#######################################################################

Smartctl: Device Read Identity Failed (not an ATA/ATAPI device)

A mandatory SMART command failed: exiting. To continue, add one or more '-T permissive' options.

It turns out this error is caused by several missing ioctls in the x86 Solaris cmdk IDE device driver. Since I have always wanted to develop (or modify) a kernel device driver, I decided to start reviewing the source code in cmdk.c to see what would be needed to make smartmontools happy. After reading through the cmdkioctl routine in cmdk.c, it dawned on me that the SPARC IDE driver, dad, contained the ioctls that are used by smartmontools. If the dad device driver used the underlying DDI framework, it would be relatively trivial to port the missing pieces from the dad driver (the SPARC IDE driver) to the cmdk driver (the x86 Solaris IDE driver). Well — it turns out the dad driver is closed source (so much for “open” solaris, ey?), so that dashed my hopes of porting code. :( Since there were two open bugs related to SMART support:

Bug ID: 4665068 SMART support in IDE driver
Bug ID: 6280687 Collect SMART data from disks and deliver info to FMA

I decided to call the Sun support center to get the current status of these bugs (I had already pinged my sales team to get the status of these bugs, but my inquiries got silently routed to /dev/null). The support folks weren’t able to tell me if and when these bugs would be fixed, but they did inform me that I could add my employers name to the bugs. They also mentioned that bug fixes are drive by customer demand, so hopefully folks who read my blog can help me out here. Since disk drives are the single component most likely to fail in a system, and SMART can help to proactively detect when a disk drive will fail, it seems only logical that Sun would devote resources to adding SMART support (or at least fixing the existing bugs so people can use third party packages). If you happen to have a support contract with Sun, I would greatly appreciate it if you could open a case (either online or by phone) and request the status of these bugs, and request that your companies name be attached to the bug. Hopefully the customers voice will be heard. :)

Debugging the ipfilter SMF service

I logged into one of my Solaris 10 hosts today to add some additional firewall rules, and noticed that the ipfilter service was in the maintenance state:

$ svcs -x ipfilter

svc:/network/ipfilter:default (IP Filter)
 State: maintenance since Sat Oct 28 15:56:30 2006
Reason: Start method failed repeatedly, last exited with status 2.
   See: http://sun.com/msg/SMF-8000-KS
   See: ipfilter(5)
   See: /etc/svc/volatile/network-ipfilter:default.log
Impact: This service is not running.

This is odd, considering this was working the last time I had checked up on the server. When I dumped out the logfile mentioned in the service state listed above, I noticed that the shell script that starts ipfilter was bombing out at line 180:

$ cat /etc/svc/volatile/network-ipfilter:default.log

[ Oct 28 15:56:16 Enabled. ]
[ Oct 28 15:56:27 Executing start method ("/lib/svc/method/ipfilter start") ]
/lib/svc/method/ipfilter: syntax error at line 180: `end of file' unexpected
[ Oct 28 15:56:27 Method "start" exited with status 2 ]
[ Oct 28 15:56:27 Executing start method ("/lib/svc/method/ipfilter start") ]
/lib/svc/method/ipfilter: syntax error at line 180: `end of file' unexpected
[ Oct 28 15:56:28 Method "start" exited with status 2 ]
[ Oct 28 15:56:28 Executing start method ("/lib/svc/method/ipfilter start") ]
/lib/svc/method/ipfilter: syntax error at line 180: `end of file' unexpected

Since I didn’t modify /lib/svc/method/ipfilter, I started to wonder why ipfilter all of a sudden quit working. The erorr message above indicated that there was an error in the script at line 180, which is a bit misleading considering the script only has 179 lines:

$ cat /lib/svc/method/ipfilter | wc -l
179

To find the actual line that was causing the issue, I decided to change the shell in /lib/svc/method/ipfilter from /sbin/sh to /bin/bash ( As a side note — I still don’t quite understand why anyone would use /sbin/sh on Solaris hosts, considering zsh, tsch and bash are available. If the reason is because of dependencies, Sun should consider moving the shells folks actually use into one of the core packages!). Once I made this change and invoked the script with the start option, bash notified me that line 123 was actually to blame:

$ /lib/svc/method/ipfilter start

/lib/svc/method/ipfilter: line 123: unexpected EOF while looking for matching “’
/lib/svc/method/ipfilter: line 180: syntax error: unexpected end of file

Upon inspecting the ipfitler script in more detail, I noticed that a “`” character was missing on line 123:

case "$1" in
        start)
                [ ! -f ${IPFILCONF} ] && exit 0
                [ -n "$pfildpid" ] && kill -TERM $pfildpid 2>/dev/null
                [ -n "$pid" ] && kill -TERM $pid 2>/dev/null
                /usr/sbin/pfild >/dev/null
                if load_ippool && load_ipf && load_ipnat ; then
                        ipmon -Dsv`  <------- ** PROBLEM **
                else

Once I removed the "`" from line 123, everything worked as expected. I am still not certain what caused this to happen in the first place, and the sunsolve and opensolaris bug database are not much help. If anyone else happens to experience this issue, please let me know!

Dumping HTTP requests and reponses to the Apache error log

When debugging problems with web applications, it is often useful to display the HTTP request and response headers along with the HTTP entity bodies. There are numerous ways to do this, and I covered several client centric solutions in my SysAdmin article Debugging Web Applications. Client side tools are extremely useful for pinpointing problems, but periodically it is helpful to see the raw requests from the client, and the responses from the server. If you happen to be running Apache, you can use the dumpio module to dump the request and response data to the Apache error log.

Setting up dumpio is super easy. To enable the dumpio module during the Apache build process, you can pass the “–enable-dumpio=shared” option to the configure script:

$ ./configure –enable-mods-shared=most –enable-dumpio-shared –with-mpm=worker \
–enable-deflate=shared –prefix=/opt/apache-2.2.3

To enable the module, you will first need to load the module with “LoadModule” directive. Once the module is configured to load, you can add the “DumpIOInput On” directive to to dump incoming data, and “DumpIOOutput On” to dump data sent by Apache. This will result in messages similar to the following appearing in the Apache error logfile:

[Sat Oct 28 10:52:31 2006] [debug] mod_dumpio.c(103): mod_dumpio: dumpio_in [getline-blocking] 0 readbytes
[Sat Oct 28 10:52:31 2006] [debug] mod_dumpio.c(51): mod_dumpio:  dumpio_in (data-HEAP): 16 bytes
[Sat Oct 28 10:52:31 2006] [debug] mod_dumpio.c(67): mod_dumpio:  dumpio_in (data-HEAP): GET / HTTP/1.1\r\n
[Sat Oct 28 10:52:31 2006] [debug] mod_dumpio.c(103): mod_dumpio: dumpio_in [getline-blocking] 0 readbytes
[Sat Oct 28 10:52:31 2006] [debug] mod_dumpio.c(51): mod_dumpio:  dumpio_in (data-HEAP): 13 bytes
[Sat Oct 28 10:52:31 2006] [debug] mod_dumpio.c(67): mod_dumpio:  dumpio_in (data-HEAP): Accept: */*\r\n
[Sat Oct 28 10:52:31 2006] [debug] mod_dumpio.c(103): mod_dumpio: dumpio_in [getline-blocking] 0 readbytes
[Sat Oct 28 10:52:31 2006] [debug] mod_dumpio.c(51): mod_dumpio:  dumpio_in (data-HEAP): 21 bytes
[Sat Oct 28 10:52:31 2006] [debug] mod_dumpio.c(67): mod_dumpio:  dumpio_in (data-HEAP): Accept-Language: en\r\n
[Sat Oct 28 10:52:31 2006] [debug] mod_dumpio.c(103): mod_dumpio: dumpio_in [getline-blocking] 0 readbytes
[Sat Oct 28 10:52:31 2006] [debug] mod_dumpio.c(51): mod_dumpio:  dumpio_in (data-HEAP): 32 bytes
[Sat Oct 28 10:52:31 2006] [debug] mod_dumpio.c(67): mod_dumpio:  dumpio_in (data-HEAP): Accept-Encoding: gzip, deflate\r\n
[Sat Oct 28 10:52:31 2006] [debug] mod_dumpio.c(103): mod_dumpio: dumpio_in [getline-blocking] 0 readbytes
[Sat Oct 28 10:52:31 2006] [debug] mod_dumpio.c(103): mod_dumpio: dumpio_in [getline-blocking] 0 readbytes
[Sat Oct 28 10:52:31 2006] [debug] mod_dumpio.c(51): mod_dumpio:  dumpio_in (data-HEAP): 24 bytes
[Sat Oct 28 10:52:31 2006] [debug] mod_dumpio.c(67): mod_dumpio:  dumpio_in (data-HEAP): Connection: keep-alive\r\n
[Sat Oct 28 10:52:31 2006] [debug] mod_dumpio.c(103): mod_dumpio: dumpio_in [getline-blocking] 0 readbytes
[Sat Oct 28 10:52:31 2006] [debug] mod_dumpio.c(51): mod_dumpio:  dumpio_in (data-HEAP): 20 bytes
[Sat Oct 28 10:52:31 2006] [debug] mod_dumpio.c(67): mod_dumpio:  dumpio_in (data-HEAP): Host: 192.168.9.24\r\n
[Sat Oct 28 10:52:31 2006] [debug] mod_dumpio.c(103): mod_dumpio: dumpio_in [getline-blocking] 0 readbytes
[Sat Oct 28 10:52:31 2006] [debug] mod_dumpio.c(51): mod_dumpio:  dumpio_in (data-HEAP): 2 bytes
[Sat Oct 28 10:52:31 2006] [debug] mod_dumpio.c(67): mod_dumpio:  dumpio_in (data-HEAP): \r\n
[Sat Oct 28 10:52:31 2006] [debug] mod_dumpio.c(129): mod_dumpio: dumpio_out
[Sat Oct 28 10:52:31 2006] [debug] mod_dumpio.c(51): mod_dumpio:  dumpio_out (data-HEAP): 281 bytes
[Sat Oct 28 10:52:31 2006] [debug] mod_dumpio.c(67): mod_dumpio:  dumpio_out (data-HEAP): HTTP/1.1 200 OK\r\nDate: Sat, 28 Oct 2006 14:52:31 GMT\r\nServer: Apache/2.2.3 (Unix)\r\nLast-Modified: Sat, 20 Nov 2004 20:16:24 GMT\r\nETag: "45b81-2c-4c23b600"\r\nAccept-Ranges: bytes\r\nContent-Length: 44\r\nKeep-Alive: timeout=5, max=100\r\nConnection: Keep-Alive\r\nContent-Type: text/html\r\n\r\n

<.....>

Dumpio is an extremely useful module, and is an invaluable tool for debugging web application.