[Unionfs] RHEL 2.6.9 hangs with unionfs-1.1.5

Benoit Guillon guillon at thalescomputers.fr
Tue Nov 28 10:04:27 EST 2006


Josef Sipek wrote:

>>Nov 27 14:36:35 node1 kernel: Modules linked in: unionfs(U) i915 nfsd 
>>exportfs lockd nfs_acl sunrpc i2c_dev i2c_core poweroff(U) allocator(U) 
>>dm_mirror dm_mod button battery ac md5 ipv6 joydev uhci_hcd ehci_hcd 
>>hw_random snd_intel8x0 snd_ac97_codec snd_pcm_oss snd_mixer_oss snd_pcm 
>>snd_timer snd_page_alloc snd_mpu401_uart snd_rawmidi snd_seq_device snd 
>>soundcore tg3 8139too mii floppy ext3 jbd ata_piix libata sd_mod scsi_mod
>>Nov 27 14:36:35 node1 kernel: CPU:    0
>>Nov 27 14:36:35 node1 kernel: EIP:    0060:[<e07bf9f6>]    Tainted: 
>>P      VLI
>>    
>>
>Can you reproduce the problem without the proprietary module?
>  
>
I've changed the server board (no more SMP) and now I can reproduce 
systematically the problem. Please find attached two kernel traces (in 
the first one there is still one proprietary module, but not in the 
second one).

The buggy case I use involves the crazy lastlog sparse file provided for 
the ppc board, but I have troubles anyway even if this file is removed 
(but it takes longer to arise and it is not deterministic). The 
procedure that uses lastlog simply makes hanging systematically the 
server. It is the following:

1. The diskless distribution is unionfs mounted and NFS exported. It 
contains the crazy lastlog file:

[root at node1 ~]# ll /diskless/layers/pn5-base2/var/log/
total 40
-rw-------  1 root utmp             0 Nov 28 11:28 btmp
-r--------  1 root root 1254130450140 Nov 28 11:29 lastlog
-rw-------  1 root root             0 Nov 28 11:28 maillog
-rw-------  1 root root             0 Nov 28 11:28 messages
-rw-------  1 root root             0 Nov 28 11:28 secure
-rw-------  1 root root             0 Nov 28 11:28 spooler
-rw-rw-r--  1 root utmp             0 Nov 28 11:28 wtmp
-rw-r--r--  1 root root          7587 Nov 28 11:29 yum.log
[root at node1 ~]# du /diskless/layers/pn5-base2/var/log/
44      /diskless/layers/pn5-base2/var/log/
[root at node1 ~]# du /diskless/layers/pn5-base2/var/log/lastlog
32      /diskless/layers/pn5-base2/var/log/lastlog

[root at node1 ~]# exportfs
/diskless/exports/node2
                node2

[root at node1 ~]# mount
...
node2-root on /diskless/exports/node2 type unionfs 
(rw,debug=15,dirs=/diskless/cow/node2=rw:/diskless/layers/pmp9-minimal-fc4=ro:/diskless/layers/pn5-base2=ro,imap=/dev/shm/imap/node2.fwd:/dev/shm/imap/node2.rev.0)


2. Once the diskless node has booted on, I try to log in:

[root at node1 ~]# ssh node2
The authenticity of host 'node2 (192.168.1.2)' can't be established.
RSA key fingerprint is 02:41:dd:c8:7a:19:8c:5a:a2:6e:b8:12:bb:fb:13:54.
Are you sure you want to continue connecting (yes/no)? yes
Warning: Permanently added 'node2,192.168.1.2' (RSA) to the list of 
known hosts.
root at node2's password:
-bash-3.00#
-bash-3.00#
-bash-3.00#

3. So far so good. Note that there's an empty lastlog file put in the 
COW directory:

[root at node1 diskless]# ll /diskless/cow/node2/var/log/
total 28
-rw-------  1 root root     0 Nov 28 15:53 boot.log
-rw-------  1 root root     0 Nov 28 15:53 cron
-rw-r--r--  1 root root  5960 Nov 28 15:53 dmesg
-rwx------  1 root root     0 Nov 28 15:53 lastlog
-rw-------  1 root root 10461 Nov 28 15:53 messages
-rw-------  1 root root   163 Nov 28 15:53 secure
-rw-rw-r--  1 root utmp  3456 Nov 28 15:53 wtmp

4. Now, from the diskless node I try to ls /var/log, and then it hangs 
the server:

-bash-3.00# ls /var/log


Does it help?

Thanks,

-- 
Benoît Guillon                guillon at thalescomputers.fr
TRT/SML                       tel. : 33 (0)4 98 16 33 90
 
THALES RESEARCH & TECHNOLOGY

-------------- next part --------------
Nov 28 11:53:14 node1 kernel: ------------[ cut here ]------------
Nov 28 11:53:14 node1 kernel: kernel BUG at /tmp/build.mmm/unionfs-tools-1.1.5/unionfs_debugmacros.h:291!
Nov 28 11:53:14 node1 kernel: invalid operand: 0000 [#1]
Nov 28 11:53:14 node1 kernel: Modules linked in: unionfs(U) i915 nfsd exportfs lockd nfs_acl sunrpc i2c_dev i2c_core ipt_REJECT ipt_state ip_conntrack iptable_filter ip_tables dm_mirror dm_mod md5 ipv6 uhci_hcd ehci_hcd hw_random e1000 ext3 jbd
Nov 28 11:53:14 node1 kernel: CPU:    0
Nov 28 11:53:14 node1 kernel: EIP:    0060:[<f8e9d6c9>]    Tainted: P      VLI
Nov 28 11:53:14 node1 kernel: EFLAGS: 00010246   (2.6.9-34.EL) 
Nov 28 11:53:14 node1 kernel: EIP is at unionfs_d_revalidate+0x1a79/0x1b00 [unionfs]
Nov 28 11:53:14 node1 kernel: eax: 00000000   ebx: eff1e814   ecx: efec2bb0   edx: 00000003
Nov 28 11:53:14 node1 kernel: esi: 00000002   edi: f4ee7400   ebp: eff1e814   esp: f638ea30
Nov 28 11:53:14 node1 kernel: ds: 007b   es: 007b   ss: 0068
Nov 28 11:53:14 node1 kernel: Process nfsd (pid: 2730, threadinfo=f638e000 task=f73ee880)
Nov 28 11:53:14 node1 kernel: Stack: f8ed9424 f8ed89e2 0000002c 00000006 f8edbe7b f8ee2600 f8ed89e2 f8ed9424 
Nov 28 11:53:14 node1 kernel:        0000002c f0144ac0 00000000 00000002 f8ea8016 f8ed6204 00000000 00000001 
Nov 28 11:53:14 node1 kernel:        00000000 00000001 00000001 00000000 efec2910 eff1e814 00000002 efec2910 
Nov 28 11:53:14 node1 kernel: Call Trace:
Nov 28 11:53:14 node1 kernel:  [<f8ea8016>] inode_permission+0xe6/0x1b0 [unionfs]
Nov 28 11:53:14 node1 kernel:  [<f8ed6204>] fist_dprint_internal+0x14/0x80 [unionfs]
Nov 28 11:53:14 node1 kernel:  [<f8e9d839>] unionfs_d_revalidate_wrap+0xe9/0x220 [unionfs]
Nov 28 11:53:14 node1 kernel:  [<c0177ca0>] cached_lookup+0x37/0x56
Nov 28 11:53:14 node1 kernel:  [<c01791e3>] __lookup_hash+0x46/0x89
Nov 28 11:53:14 node1 kernel:  [<c0179281>] lookup_one_len+0x54/0x63
Nov 28 11:53:14 node1 kernel:  [<f8b43a18>] compose_entry_fh+0x15d/0x1a9 [nfsd]
Nov 28 11:53:14 node1 kernel:  [<f8b43d0c>] encode_entry+0x2a8/0x65c [nfsd]
Nov 28 11:53:14 node1 kernel:  [<c027579e>] ide_build_sglist+0x19/0x7f
Nov 28 11:53:14 node1 kernel:  [<c01e6641>] __delay+0x9/0xa
Nov 28 11:53:14 node1 kernel:  [<f882a50f>] do_get_write_access+0x5c0/0x5dc [jbd]
Nov 28 11:53:14 node1 kernel:  [<c01481df>] find_lock_page+0x6a/0x1d9
Nov 28 11:53:14 node1 kernel:  [<c0147daf>] wake_up_page+0x9/0x29
Nov 28 11:53:14 node1 kernel:  [<c0164f2d>] shmem_getpage+0xa96/0xac2
Nov 28 11:53:14 node1 kernel:  [<c0126a00>] current_fs_time+0x44/0x4c
Nov 28 11:53:14 node1 kernel:  [<f8b440ea>] nfs3svc_encode_entry_plus+0x13/0x17 [nfsd]
Nov 28 11:53:14 node1 kernel:  [<f8ed59e4>] unionfs_filldir+0x144/0x1e0 [unionfs]
Nov 28 11:53:14 node1 kernel:  [<f8860e64>] call_filldir+0x98/0xb2 [ext3]
Nov 28 11:53:14 node1 kernel:  [<f8ed58a0>] unionfs_filldir+0x0/0x1e0 [unionfs]
Nov 28 11:53:14 node1 kernel:  [<f8860fc5>] ext3_dx_readdir+0x147/0x192 [ext3]
Nov 28 11:53:14 node1 kernel:  [<f8ed58a0>] unionfs_filldir+0x0/0x1e0 [unionfs]
Nov 28 11:53:14 node1 kernel:  [<f8860899>] ext3_readdir+0x8c/0x3a0 [ext3]
Nov 28 11:53:14 node1 kernel:  [<f8ed6204>] fist_dprint_internal+0x14/0x80 [unionfs]
Nov 28 11:53:14 node1 kernel:  [<f8ed58a0>] unionfs_filldir+0x0/0x1e0 [unionfs]
Nov 28 11:53:14 node1 kernel:  [<f8ed1070>] unionfs_file_revalidate+0x450/0x14a0 [unionfs]
Nov 28 11:53:14 node1 kernel:  [<f8ed6204>] fist_dprint_internal+0x14/0x80 [unionfs]
Nov 28 11:53:14 node1 kernel:  [<c030fbf0>] __cond_resched+0x14/0x3b
Nov 28 11:53:14 node1 kernel:  [<f8ed58a0>] unionfs_filldir+0x0/0x1e0 [unionfs]
Nov 28 11:53:14 node1 kernel:  [<c017cdd2>] vfs_readdir+0x8a/0xb7
Nov 28 11:53:14 node1 kernel:  [<f8ed5d98>] unionfs_readdir+0x318/0x480 [unionfs]
Nov 28 11:53:14 node1 kernel:  [<f8b440d7>] nfs3svc_encode_entry_plus+0x0/0x17 [nfsd]
Nov 28 11:53:14 node1 last message repeated 2 times
Nov 28 11:53:14 node1 kernel:  [<c017cdd2>] vfs_readdir+0x8a/0xb7
Nov 28 11:53:14 node1 kernel:  [<f8b38fad>] nfsd_readdir+0x62/0xc9 [nfsd]
Nov 28 11:53:14 node1 kernel:  [<f8b3f85e>] nfsd3_proc_readdirplus+0xdf/0x230 [nfsd]
Nov 28 11:53:14 node1 kernel:  [<f8b440d7>] nfs3svc_encode_entry_plus+0x0/0x17 [nfsd]
Nov 28 11:53:14 node1 kernel:  [<f8b42b02>] nfs3svc_decode_readdirplusargs+0x0/0x20f [nfsd]
Nov 28 11:53:14 node1 kernel:  [<f8b33947>] nfsd_dispatch+0xba/0x16f [nfsd]
Nov 28 11:53:14 node1 kernel:  [<f8add8ec>] svc_process+0x432/0x6da [sunrpc]
Nov 28 11:53:14 node1 kernel:  [<f8b335eb>] nfsd+0x2a7/0x549 [nfsd]
Nov 28 11:53:14 node1 kernel:  [<f8b33344>] nfsd+0x0/0x549 [nfsd]
Nov 28 11:53:14 node1 kernel:  [<c01041dd>] kernel_thread_helper+0x5/0xb
Nov 28 11:53:14 node1 kernel: Code: a4 94 ed f8 e9 aa fc ff ff 0f 0b 4a 00 a4 94 ed f8 0f 0b 41 00 a4 94 ed f8 e9 1d f2 ff ff 0f 0b 44 00 a4 94 ed f8 e9 86 f1 ff ff <0f> 0b 23 01 a4 94 ed f8 e9 24 fc ff ff 0f 0b 44 00 a4 94 ed f8 
Nov 28 11:53:14 node1 kernel:  <0>Fatal exception: panic in 5 seconds

-------------- next part --------------
Nov 28 15:23:47 node1 kernel: ------------[ cut here ]------------
Nov 28 15:23:47 node1 kernel: kernel BUG at /tmp/build.mmm/unionfs-tools-1.1.5/unionfs_debugmacros.h:291!
Nov 28 15:23:47 node1 kernel: invalid operand: 0000 [#1]
Nov 28 15:23:47 node1 kernel: Modules linked in: unionfs(U) i915 nfsd exportfs lockd nfs_acl sunrpc i2c_dev i2c_core ipt_REJECT ipt_state ip_conntrack iptable_filter ip_tables dm_mirror dm_mod md5 ipv6 uhci_hcd ehci_hcd hw_random e1000 ext3 jbd
Nov 28 15:23:47 node1 kernel: CPU:    0
Nov 28 15:23:47 node1 kernel: EIP:    0060:[<f8e9d6c9>]    Not tainted VLI
Nov 28 15:23:47 node1 kernel: EFLAGS: 00010246   (2.6.9-34.EL) 
Nov 28 15:23:47 node1 kernel: EIP is at unionfs_d_revalidate+0x1a79/0x1b00 [unionfs]
Nov 28 15:23:47 node1 kernel: eax: 00000000   ebx: f524b814   ecx: ed540c58   edx: 00000003
Nov 28 15:23:47 node1 kernel: esi: 00000002   edi: f4244c00   ebp: f524b814   esp: f54fda30
Nov 28 15:23:47 node1 kernel: ds: 007b   es: 007b   ss: 0068
Nov 28 15:23:47 node1 kernel: Process nfsd (pid: 2822, threadinfo=f54fd000 task=f6fa2030)
Nov 28 15:23:47 node1 kernel: Stack: f8ed9424 f8ed89e2 0000002c 00000006 f8edbe7b f8ee2600 f8ed89e2 f8ed9424 
Nov 28 15:23:47 node1 kernel:        0000002c 00000246 fffeac8a 00000002 c03eafbe 00000246 c0121b4f 0000000f 
Nov 28 15:23:47 node1 kernel:        00000000 00000001 00000001 00000000 ed540ef8 f524b814 00000002 ed540ef8 
Nov 28 15:23:47 node1 kernel: Call Trace:
Nov 28 15:23:47 node1 kernel:  [<c0121b4f>] vprintk+0x22d/0x29d
Nov 28 15:23:47 node1 kernel:  [<f8e9d839>] unionfs_d_revalidate_wrap+0xe9/0x220 [unionfs]
Nov 28 15:23:47 node1 kernel:  [<c0177ca0>] cached_lookup+0x37/0x56
Nov 28 15:23:47 node1 kernel:  [<c01791e3>] __lookup_hash+0x46/0x89
Nov 28 15:23:47 node1 kernel:  [<c0179281>] lookup_one_len+0x54/0x63
Nov 28 15:23:47 node1 kernel:  [<f8b43a18>] compose_entry_fh+0x15d/0x1a9 [nfsd]
Nov 28 15:23:47 node1 kernel:  [<f8b43d0c>] encode_entry+0x2a8/0x65c [nfsd]
Nov 28 15:23:47 node1 kernel:  [<c01e4338>] radix_tree_node_alloc+0x10/0x41
Nov 28 15:23:47 node1 kernel:  [<c0190628>] mpage_end_io_read+0x0/0x5e
Nov 28 15:23:47 node1 kernel:  [<c0251922>] submit_bio+0xa4/0xac
Nov 28 15:23:47 node1 kernel:  [<c01e44ca>] radix_tree_insert+0x6e/0xe7
Nov 28 15:23:47 node1 kernel:  [<c0190628>] mpage_end_io_read+0x0/0x5e
Nov 28 15:23:47 node1 kernel:  [<c010888f>] do_IRQ+0x232/0x2bf
Nov 28 15:23:47 node1 kernel:  [<c0311588>] common_interrupt+0x18/0x20
Nov 28 15:23:47 node1 kernel:  [<c01e5db1>] vsnprintf+0x448/0x488
Nov 28 15:23:47 node1 kernel:  [<f8b440ea>] nfs3svc_encode_entry_plus+0x13/0x17 [nfsd]
Nov 28 15:23:47 node1 kernel:  [<f8ed59e4>] unionfs_filldir+0x144/0x1e0 [unionfs]
Nov 28 15:23:47 node1 kernel:  [<f8860e64>] call_filldir+0x98/0xb2 [ext3]
Nov 28 15:23:47 node1 kernel:  [<f8ed58a0>] unionfs_filldir+0x0/0x1e0 [unionfs]
Nov 28 15:23:47 node1 kernel:  [<f8860fc5>] ext3_dx_readdir+0x147/0x192 [ext3]
Nov 28 15:23:47 node1 kernel:  [<f8ed58a0>] unionfs_filldir+0x0/0x1e0 [unionfs]
Nov 28 15:23:47 node1 kernel:  [<f8860899>] ext3_readdir+0x8c/0x3a0 [ext3]
Nov 28 15:23:47 node1 kernel:  [<c0121b4f>] vprintk+0x22d/0x29d
Nov 28 15:23:47 node1 kernel:  [<f8ed622f>] fist_dprint_internal+0x3f/0x80 [unionfs]
Nov 28 15:23:47 node1 kernel:  [<f8ed58a0>] unionfs_filldir+0x0/0x1e0 [unionfs]
Nov 28 15:23:47 node1 kernel:  [<f8ed1070>] unionfs_file_revalidate+0x450/0x14a0 [unionfs]
Nov 28 15:23:47 node1 kernel:  [<f8ed6204>] fist_dprint_internal+0x14/0x80 [unionfs]
Nov 28 15:23:47 node1 kernel:  [<c030fbf0>] __cond_resched+0x14/0x3b
Nov 28 15:23:47 node1 kernel:  [<f8ed58a0>] unionfs_filldir+0x0/0x1e0 [unionfs]
Nov 28 15:23:47 node1 kernel:  [<c017cdd2>] vfs_readdir+0x8a/0xb7
Nov 28 15:23:47 node1 kernel:  [<f8ed5d98>] unionfs_readdir+0x318/0x480 [unionfs]
Nov 28 15:23:47 node1 kernel:  [<f8b440d7>] nfs3svc_encode_entry_plus+0x0/0x17 [nfsd]
Nov 28 15:23:47 node1 last message repeated 2 times
Nov 28 15:23:47 node1 kernel:  [<c017cdd2>] vfs_readdir+0x8a/0xb7
Nov 28 15:23:47 node1 kernel:  [<f8b38fad>] nfsd_readdir+0x62/0xc9 [nfsd]
Nov 28 15:23:47 node1 kernel:  [<f8b3f85e>] nfsd3_proc_readdirplus+0xdf/0x230 [nfsd]
Nov 28 15:23:47 node1 kernel:  [<f8b440d7>] nfs3svc_encode_entry_plus+0x0/0x17 [nfsd]
Nov 28 15:23:47 node1 kernel:  [<f8b42b02>] nfs3svc_decode_readdirplusargs+0x0/0x20f [nfsd]
Nov 28 15:23:47 node1 kernel:  [<f8b33947>] nfsd_dispatch+0xba/0x16f [nfsd]
Nov 28 15:23:47 node1 kernel:  [<f8add8ec>] svc_process+0x432/0x6da [sunrpc]
Nov 28 15:23:47 node1 kernel:  [<f8b335eb>] nfsd+0x2a7/0x549 [nfsd]
Nov 28 15:23:47 node1 kernel:  [<f8b33344>] nfsd+0x0/0x549 [nfsd]
Nov 28 15:23:47 node1 kernel:  [<c01041dd>] kernel_thread_helper+0x5/0xb
Nov 28 15:23:47 node1 kernel: Code: a4 94 ed f8 e9 aa fc ff ff 0f 0b 4a 00 a4 94 ed f8 0f 0b 41 00 a4 94 ed f8 e9 1d f2 ff ff 0f 0b 44 00 a4 94 ed f8 e9 86 f1 ff ff <0f> 0b 23 01 a4 94 ed f8 e9 24 fc ff ff 0f 0b 44 00 a4 94 ed f8 
Nov 28 15:23:47 node1 kernel:  <0>Fatal exception: panic in 5 seconds


More information about the unionfs mailing list