sisp_debug stuck

Submitted by edrt on Thu, 2006-09-28 03:11.

Hello all,

I've just installed openclovis r2.2 on fc3. The installation is ok.
I tried to run csa101 followed by evaluation guide and encounter following
problem.

When I run debug.sh under /root/sisp/bin, the command just stuck there.
I strace sisp_debug (trace output attached at mail end), and found the
process seems stuck at

clIocUdpXportConfigInitialize
ioctl(udpXportfd, UDP_CONFIG_INIT, &udpConfig)<---

What might be the problem?

Thanks
Eddy

BTW, in ps output, sisp_amf & sisp_debug all have "defunct" flag attached,
but the forum posting system seems filter this word out (I'm using plain
text input format)

---------------------
[root@ed ~]# uname -a
Linux ed 2.6.9-1.667 #1 Tue Nov 2 14:41:25 EST 2004 i686 i686 i386 GNU/Linux

[root@ed ~]# sisp/etc/init.d/sisp start
Starting sisp_amf: [ OK ]

[root@ed ~]# ps aux | grep sisp
root 3157 5.4 1.3 10092 3584 pts/1 S 17:44 0:00 /root/sisp/bin/snmpd -DH -Lo -f -c /root/sisp/etc/snmpd.conf
root 3158 0.0 0.0 0 0 pts/1 Zl 17:44 0:00 [sisp_amf]
root 3159 0.0 0.4 5912 1212 pts/1 S 17:44 0:00 /bin/bash sisp/etc/init.d/sisp start
root 3166 0.0 0.2 5236 664 pts/1 S+ 17:45 0:00 grep -R --color sisp

[root@ed ~]# lsmod
Module Size Used by
clIocUdpKernelXport 9632 2
clIoc 194104 3 clIocUdpKernelXport

[root@ed ~]# cd sisp/bin/
[root@ed bin]# ./debug.sh
execve("/root/sisp/bin/sisp_debug", ["/root/sisp/bin/sisp_debug"], [/* 34 vars */]) = 0
uname({sys="Linux", node="ed", ...}) = 0
brk(0) = 0x8bf6000
access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
open("/etc/ld.so.cache", O_RDONLY) = 3
fstat64(3, {st_mode=S_IFREG|0644, st_size=64906, ...}) = 0
old_mmap(NULL, 64906, PROT_READ, MAP_PRIVATE, 3, 0) = 0xf6ff0000
close(3) = 0
open("/lib/tls/libpthread.so.0", O_RDONLY) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\20x\22"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=108424, ...}) = 0
old_mmap(0x123000, 70132, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x123000
old_mmap(0x131000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0xd000) = 0x131000
old_mmap(0x133000, 4596, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x133000
close(3) = 0
open("/lib/tls/libc.so.6", O_RDONLY) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0 O\277\000"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=1512400, ...}) = 0
old_mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xf6fef000
old_mmap(0xbe0000, 1207532, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xbe0000
old_mmap(0xd01000, 16384, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x120000) = 0xd01000
old_mmap(0xd05000, 7404, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xd05000
close(3) = 0
old_mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xf6fee000
mprotect(0xd01000, 8192, PROT_READ) = 0
mprotect(0x131000, 4096, PROT_READ) = 0
mprotect(0xbdc000, 4096, PROT_READ) = 0
set_thread_area({entry_number:-1 -> 6, base_addr:0xf6fee6c0, limit:1048575, seg_32bit:1, contents:0, read_exec_only:0, limit_in_pages:1, seg_not_present:0, useable:1}) = 0
munmap(0xf6ff0000, 64906) = 0
set_tid_address(0xf6fee708) = 3171
rt_sigaction(SIGRTMIN, {0x1273a0, [], SA_RESTORER|SA_SIGINFO, 0x12e8a0}, NULL, 8) = 0
rt_sigaction(SIGRT_1, {0x127410, [], SA_RESTORER|SA_RESTART|SA_SIGINFO, 0x12e8a0}, NULL, 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [RTMIN], NULL, 8) = 0
getrlimit(RLIMIT_STACK, {rlim_cur=10240*1024, rlim_max=RLIM_INFINITY}) = 0
_sysctl({{CTL_KERN, KERN_VERSION}, 2, 0xfef4d1e8, 30, (nil), 0}) = 0
brk(0) = 0x8bf6000
brk(0x8c17000) = 0x8c17000
brk(0x8c3b000) = 0x8c3b000
mmap2(NULL, 69632, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xf6fdd000
mprotect(0xf6fdd000, 4096, PROT_NONE) = 0
clone(child_stack=0xf6fed4c8, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID|CLONE_DETACHED, parent_tidptr=0xf6fedbf8, {entry_number:6, base_addr:0xf6fedbb0, limit:1048575, seg_32bit:1, contents:0, read_exec_only:0, limit_in_pages:1, seg_not_present:0, useable:1}, child_tidptr=0xf6fedbf8) = 3172
mmap2(NULL, 266240, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xf6f9c000
mmap2(NULL, 266240, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xf6f5b000
mmap2(NULL, 528384, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xf6eda000
mmap2(NULL, 720896, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xf6e2a000
open("/dev/iocDevice", O_RDWR) = 3
fcntl64(3, F_SETFD, FD_CLOEXEC) = 0
ioctl(3, 0, 0xfef4d310) = 0
open("/root/sisp/etc/clIocConfig.xml", O_RDONLY) = 4
fstat64(4, {st_mode=S_IFREG|0644, st_size=637, ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE, 4, 0) = 0xf6e29000
madvise(0xf6e29000, 4096, MADV_SEQUENTIAL) = 0
madvise(0xf6e29000, 4096, MADV_NORMAL) = 0
close(4) = 0
munmap(0xf6e29000, 4096) = 0
socket(PF_INET, SOCK_DGRAM, IPPROTO_IP) = 4
ioctl(4, SIOCGIFADDR, 0xfef4d150) = 0
close(4) = 0
futex(0xd06144, FUTEX_WAKE, 2147483647) = 0
socket(PF_INET, SOCK_DGRAM, IPPROTO_IP) = 4
ioctl(4, SIOCGIFBRDADDR, 0xfef4d150) = 0
close(4) = 0
open("/dev/udpDevice", O_RDWR) = 4
ioctl(4, 0

[root@ed ~]# ps aux | grep sisp <--command issued on another session
root 3157 0.5 1.4 10172 3660 pts/1 S 17:44 0:00 /root/sisp/bin/snmpd -DH -Lo -f -c /root/sisp/etc/snmpd.conf
root 3158 0.0 0.0 0 0 pts/1 Zl 17:44 0:00 [sisp_amf]
root 3170 0.0 0.2 2944 572 pts/1 S+ 17:46 0:00 strace /root/sisp/bin/sisp_debug
root 3171 0.0 0.0 0 0 pts/1 Zl+ 17:46 0:00 [sisp_debug]
root 3210 0.0 0.2 4628 652 pts/2 R+ 17:46 0:00 grep -R --color sisp

Submitted by nv on Thu, 2006-09-28 08:37.

Hi,

Is the kernel enabled for SMP and preemption and was the IOC module compiled with the right tool chain?

#zcat /proc/config.gz | grep -i preempt
#zcat /proc/config.gz | grep -i smp

Were there any errors/warnings in dmesg or /var/log/messages output when SISP was started and/or when IOC kernel modules were loaded? If necessary, add a '-v' to the modprobe commands in the SISP startup script.

One of our observations is that there can be large changes across minor versions of the linux kernel. Is it possible for you to use another kernel beyond 2.6.9-1? (just asking, not suggesting that you do this) Most of our testing is 2.6.9-5 or later.

/nv

Submitted by edrt on Thu, 2006-09-28 22:30.

Hi nv,

It seems the problem caused by kernel (see log attached at mail end), I've
upgraded to 2.6.12 and the problem disappears.

Thanks
Eddy

-----------------
[root@ed ~]# sisp/etc/init.d/sisp start
Starting sisp_amf: [ OK ]

[root@ed ~]# tail -f /var/log/messages
Sep 29 10:44:09 ed kernel: clIoc: module license '
Sep 29 10:44:09 ed kernel:
Sep 29 10:44:09 ed kernel: Copyright (C) 2002-2006 by Clovis Solutions, Inc.
Sep 29 10:44:09 ed kernel: All rights reserved.
Sep 29 10:44:09 ed kernel:
Sep 29 10:44:09 ed kernel: MODULE : IOC
Sep 29 10:44:09 ed kernel: AUTHOR : CLOVIS SOLUTIONS INC
Sep 29 10:44:09 ed kernel: DESCRIPTION :
Sep 29 10:44:09 ed kernel: This module implements IOC as a kernel module.
Sep 29 10:44:09 ed kernel:
Sep 29 10:44:09 ed kernel: The source code for this program is not published or otherwise
Sep 29 10:44:09 ed kernel: divested of its trade secrets, irrespective of what has been deposited
Sep 29 10:44:09 ed kernel: with the U.S. Copyright office.
Sep 29 10:44:09 ed kernel:
Sep 29 10:44:09 ed kernel: All Rights Reserved. US Government Users Restricted Rights - Use,
Sep 29 10:44:09 ed kernel: duplication or disclosure restricted unless granted by formal written
Sep 29 10:44:09 ed kernel: contract with Clovis Solutions, Inc.
Sep 29 10:44:09 ed kernel: ' taints kernel.
Sep 29 10:44:09 ed kernel:
Sep 29 10:44:09 ed kernel: Loaded IOC kernel module successfully 254
Sep 29 10:44:09 ed kernel:
Sep 29 10:44:09 ed kernel: Loaded UDP kernel module successfully 253
Sep 29 10:44:09 ed sisp: succeeded
Sep 29 10:44:09 ed kernel: Unable to handle kernel paging request at virtual address fef7c6b0
Sep 29 10:44:09 ed kernel: printing eip:
Sep 29 10:44:09 ed kernel: 12944286
Sep 29 10:44:09 ed kernel: *pde = 00000000
Sep 29 10:44:09 ed kernel: Oops: 0000 [#1]
Sep 29 10:44:09 ed kernel: Modules linked in: clIocUdpKernelXport(U) clIoc(U) radeon parport_pc lp parport autofs4 i2c_dev i2c_core sunrpc dm_mod button battery ac md5 ipv6 uhci_hcd snd_intel8x0 snd_ac97_codec snd_pcm_oss snd_mixer_oss snd_pcm snd_timer snd_page_alloc gameport snd_mpu401_uart snd_rawmidi snd_seq_device snd soundcore 3c59x via_rhine mii floppy ext3 jbd
Sep 29 10:44:09 ed kernel: CPU: 0
Sep 29 10:44:09 ed kernel: EIP: 0060:[<12944286>] Tainted: P VLI
Sep 29 10:44:09 ed kernel: EFLAGS: 00010202 (2.6.9-1.667)
Sep 29 10:44:09 ed kernel: EIP is at iocKernelUdpXportConfigInit+0x26/0xf0 [clIocUdpKernelXport]
Sep 29 10:44:09 ed kernel: eax: 11fdd980 ebx: 11fdd980 ecx: 0000008c edx: 11fdd980
Sep 29 10:44:09 ed kernel: esi: 00000000 edi: 00000000 ebp: fef7c6b0 esp: 07cb7f78
Sep 29 10:44:09 ed kernel: ds: 007b es: 007b ss: 0068
Sep 29 10:44:09 ed kernel: Process sisp_amf (pid: 3200, threadinfo=07cb7000 task=07cc32f0)
Sep 29 10:44:09 ed kernel: Stack: 00000000 081eef7b 12946220 00000000 07c95680 ffffffe7 12944245 0217a147
Sep 29 10:44:09 ed kernel: fef7c6b0 087d42c4 07c95680 00000004 07cb7fc0 00000004 07cb7fc4 fef7c894
Sep 29 10:44:09 ed kernel: fef7c820 07cb7000 ffff4200 00000004 00000000 fef7c6b0 fef7c894 fef7c820
Sep 29 10:44:09 ed kernel: Call Trace:
Sep 29 10:44:09 ed kernel: [<12944245>] ioctl_device+0x15/0x30 [clIocUdpKernelXport]
Sep 29 10:44:09 ed kernel: [<0217a147>] sys_ioctl+0x296/0x337
Sep 29 10:44:09 ed kernel: Code: <3>Debug: sleeping function called from invalid context at include/linux/rwsem.h:43
Sep 29 10:44:09 ed kernel: in_atomic():0[expected: 0], irqs_disabled():1
Sep 29 10:44:09 ed kernel: [<0211c8b9>] __might_sleep+0x7d/0x88
Sep 29 10:44:09 ed kernel: [<0215e27e>] rw_vm+0x216/0x482
Sep 29 10:44:09 ed kernel: [<1294425b>] ioctl_device+0x2b/0x30 [clIocUdpKernelXport]
Sep 29 10:44:09 ed kernel: [<1294425b>] ioctl_device+0x2b/0x30 [clIocUdpKernelXport]
Sep 29 10:44:09 ed kernel: [<0215e9d0>] get_user_size+0x30/0x57
Sep 29 10:44:09 ed kernel: [<1294425b>] ioctl_device+0x2b/0x30 [clIocUdpKernelXport]
Sep 29 10:44:09 ed kernel: [<0210682b>] show_registers+0x109/0x15e
Sep 29 10:44:09 ed kernel: [<02106a2f>] die+0x14a/0x241
Sep 29 10:44:09 ed kernel: [<0211937e>] do_page_fault+0x0/0x511
Sep 29 10:44:09 ed kernel: [<0211937e>] do_page_fault+0x0/0x511
Sep 29 10:44:09 ed kernel: [<02119733>] do_page_fault+0x3b5/0x511
Sep 29 10:44:09 ed kernel: [<12944286>] iocKernelUdpXportConfigInit+0x26/0xf0 [clIocUdpKernelXport]
Sep 29 10:44:09 ed kernel: [<02153a04>] do_no_page+0x3b5/0x434
Sep 29 10:44:09 ed kernel: [<02175183>] do_lookup+0x1f/0x8f
Sep 29 10:44:09 ed kernel: [<02153c78>] handle_mm_fault+0xe4/0x21e
Sep 29 10:44:09 ed kernel: [<0211953a>] do_page_fault+0x1bc/0x511
Sep 29 10:44:09 ed kernel: [<02170106>] chrdev_open+0x3bd/0x458
Sep 29 10:44:09 ed kernel: [<0211937e>] do_page_fault+0x0/0x511
Sep 29 10:44:09 ed kernel: [<12944286>] iocKernelUdpXportConfigInit+0x26/0xf0 [clIocUdpKernelXport]
Sep 29 10:44:09 ed kernel: [<12944245>] ioctl_device+0x15/0x30 [clIocUdpKernelXport]
Sep 29 10:44:09 ed kernel: [<0217a147>] sys_ioctl+0x296/0x337
Sep 29 10:44:09 ed kernel: Bad EIP value.

Submitted by nv on Fri, 2006-09-29 06:36.

Glad you are up and running. The owners of the IOC module will take a look at the log you provided. Thanks.