トップ «前の日記(2003年03月29日) 最新 次の日記(2003年04月01日)» 編集
2003|01|02|03|04|05|06|07|08|09|10|11|12|
2004|01|02|03|04|05|06|07|08|09|10|11|12|
2005|01|02|03|04|05|06|07|08|09|10|11|12|
2006|01|02|03|04|05|06|07|08|09|10|11|12|
2007|01|02|03|04|05|06|07|08|09|10|11|12|
2008|01|02|03|04|05|06|07|08|10|12|
2009|02|03|06|07|10|11|12|
2010|01|02|03|04|07|09|10|11|12|
2011|01|03|04|05|06|07|08|10|
2012|01|06|08|09|10|12|
2013|01|02|03|04|07|09|11|12|
2014|01|03|04|05|06|09|
2015|04|
2016|01|08|
ここは旧えびめもです。えびめも2に移行します(2016/12/1)

2003年03月31日

CAT709

PPPの続き。Microdriveにフルのdebianを入れてダイヤルアップ接続に成功したので、必要なファイルをFLASHメモリに入れる作業を継続中。しかしpppdを直接起動させるとsegmentation faultが発生する。(Microdrive上のdebianで動作させると起こらない)

# pppd call airh
Segmentation fault
これだけではまったく原因の特定ができないのでstraceを使ってどこで落ちているか追跡をすることにする。というわけでまずstraceをコンパイルしてみたが arch=sh3 だとコンパイルできなかった。configureを見るとarch=sh ということになっているらしいので一部修正をして再コンパイルだ。
strace-4.4.94/configure  の 1908行付近
-sh)
+sh3)
         arch=sh
 cat >>confdefs.h <<\_ACEOF
 #define SH 1
strace-4.4.94/configure.ac  の 90行付近
-sh)
+sh3)
        arch=sh
        AC_DEFINE([SH], 1, [Define for the SH architecture.])
        ;;
という修正でコンパイルできた。さっそく実行してみる。
# strace pppd call airh
略
fstat64(0, {st_mode=S_IFCHR|0600, st_rdev=makedev(204, 8), ...}) = 0
fstat64(1, {st_mode=S_IFCHR|0600, st_rdev=makedev(204, 8), ...}) = 0
open("/dev/ppp", O_RDWR)                = 3
fcntl64(3, F_GETFL)                     = 0x2 (flags O_RDWR)
fcntl64(3, F_SETFL, O_RDWR|O_NONBLOCK)  = 0
socket(PF_INET, SOCK_DGRAM, IPPROTO_IP) = 4
socket(PF_INET6, SOCK_DGRAM, 0)         = -1 EAFNOSUPPORT (Address family not supported by protocol)
open("/var/run/pppd.tdb", O_RDWR|O_CREAT, 0644) = 5
fcntl64(5, F_SETLKW, {type=F_WRLCK, whence=SEEK_SET, start=0, len=1}) = 0
fcntl64(5, F_SETLKW, {type=F_RDLCK, whence=SEEK_SET, start=4, len=1}) = 0
read(5, "TDB file\n\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 40) = 40
fstat64(5, {st_mode=S_IFREG|0644, st_size=556, ...}) = 0
old_mmap()                              = -1 EINVAL (Invalid argument)
fcntl64(5, F_SETLKW, {type=F_UNLCK, whence=SEEK_SET, start=0, len=1}) = 0
getpid()                                = 136
fcntl64(5, F_SETLKW, {type=F_WRLCK, whence=SEEK_SET, start=1208, len=1}) = 0
--- SIGSEGV (Segmentation fault) @ 0 (0) ---
+++ killed by SIGSEGV +++
どこで落ちるかはわかった。なんだろ?old_mmap()がエラーな点がクサイ。ソース追いかけるか。

と思ったが、上のstraceの結果だけでは、まるで暗闇でカニを探すようなもので(?)埒が明かないのでgdbをインストールし、pppdを-gオプションつきでコンパイルしなおして細かく追いかけた。で、、、、
わーかった!!
疲れた。どうやって発見したかの説明は長くなるので端折るがpppdのバグを発見した。
正常に動作する時

(gdb) r call airh
Starting program: /mnt/root/build/ppp-2.4.1.uus/pppd/pppd call airh
Breakpoint 1, tdb_read (tdb=0x458088, offset=476, buf=0x7bfffa30 "\a", len=4)
    at tdb.c:241
241             if (tdb_oob(tdb, offset + len) != 0) {
(gdb) n
246             if (tdb->map_ptr) {
(gdb)
247                     memcpy(buf, offset + (char *)tdb->map_ptr, len);
(gdb) p *tdb
$3 = {name = 0x457458 "/var/run/pppd.tdb", map_ptr = 0x29569000, fd = 8,
  map_size = 8192, read_only = 0, locked = 0x458250, ecode = 0, header = {
    magic_food = "TDB file\n", '\000' , version = 637606248,
    hash_size = 128}}
落ちる時
(gdb) r call airh
Starting program: /mnt/root/build/ppp-2.4.1.uus/pppd/./pppd call airh
Breakpoint 1, tdb_read (tdb=0x458088, offset=60, buf=0x7bfffa20 "\a", len=4)
    at tdb.c:241
241             if (tdb_oob(tdb, offset + len) != 0) {
(gdb) n
246             if (tdb->map_ptr) {
(gdb) p *tdb
$1 = {name = 0x457458 "/var/run/pppd.tdb", map_ptr = 0xffffffff, fd = 7,
  map_size = 556, read_only = 0, locked = 0x458250, ecode = 0, header = {
    magic_food = "TDB file\n", '\000' , version = 637606248,
    hash_size = 128}}
(gdb) n
247                     memcpy(buf, offset + (char *)tdb->map_ptr, len);
(gdb) p offset + (char *)tdb->map_ptr
$2 = 0x3b <Address 0x3b out of bounds>
(gdb) n
Program received signal SIGSEGV, Segmentation fault.
0x2963a2cc in memcpy () from /lib/libc.so.6
落ちる時は tdb->map_ptr が 0xffffffff つまり -1 になっていることがわかった。map_ptr は mmap() の戻り値であるが、先ほどstraceで調べた時にわかったように、mmap()のエラー -1そのものだ。mmap()がエラーぶっこいているにもかかわらずpppdにエラー処理が抜けていて、のんきにpidなどを調べて先に進んでいるので、その先のmemcpy()で落ちていた。pppdのエラー処理ミスのbugだ。ちなみに、同時にわかることであるが map_ptr は "/var/run/pppd.tdb" のmmap()だ。

肝心なのはなぜmmap()がエラーになるかであるが、『jffs2上にファイルが置いてあるのでmmap()の挙動に問題があるのではないか?』と思いついたので /var を ramfsに置いて実験をしたところ、ppp接続に成功した!v(^-^)v

この結果から判断すると jffs2はmmap()できないようだが、いまいちしっくりこないので簡単なコードを書いて実験を行った。結果、O_RDONLYでopen()したときはmmap()に成功し、O_RDWDでopen()したときにmmap()に失敗した。googleで jffs2 mmap で調べたところ以下の文書を発見した。
http://www.handhelds.org/pipermail/intimate/2001-July/000028.html
The problem is that jffs2 does not support shared writeable mmap
というわけで原因もわかったことだし、この件は決着。長くなるが動作画面を貼っておく

supercat:~# modprobe sh3_ss
Using /lib/modules/2.4.19/pcmcia/pcmcia_core.o
Linux Kernel Card Services 3.1.22
  options:  none
Using /lib/modules/2.4.19/pcmcia/sh3_ss.o
Warning: loading sh3_ss will taint the sh3ss_ss: sh3ss_set_voltage(0, 0, 0)
ksh3ss_ss: sh3ss_init_socket(irq=34,mem_base=b8000000)
sh3ss_ss: sh3ss_reset_socket(0, 1)sh3ss_ss: sh3ss_set_voltage(1, 0, 0)
sh3ss_ss: sh3ss_init_socket(irq=32,mem_base=b8008000)
sh3ss_ss: sh3ss_reset_socket(1, 1)sh3ss_ss: sh3ss_init(0)
sh3ss_ss: sh3ss_set_voltage(0, 0, 0)
sh3ss_ss: sh3ss_inquire_socket(0)
sh3ss_ss: sh3ss_proc_setup(0)  XXX
sh3ss_ss: sh3ss_init(1)
sh3ss_ss: sh3ss_set_voltage(1, 0, 0)
sh3ss_ss: sh3ss_inquire_socket(1)
sh3ss_ss: sh3ss_proc_setup(1)  XXX
SH3 PCMCIA bridge:
e  socket 0 at 0xb8000000 irq 34 io window 20K@0xc0131000
r  socket 1 at 0xb8008000 irq 32 io window 20K@0xc0136000
nel: no license
  See http://www.tux.org/lkml/#export-tainted for information about tainted modules
supercat:~# modprobe ds
Using /lib/modules/2.4.19/pcmcia/pcmcia_core.o
Using /lib/modules/2.4.19/pcmcia/ds.o
sh3ss_ss: sh3ss_register_callback(0)
sh3ss_ss: sh3ss_get_status(0) = 10c0
sh3ss_ss: sh3ss_get_status(0) = 10c0
sh3ss_ss: sh3ss_set_socket(sock=0, flags=0, csc_mask=80, Vcc=33, Vpp=33, io_irq=0)
sh3ss_ss: sh3ss_set_voltage(0, 33, 33)
sh3ss_ss: sh3ss_set_socket(sock=0)SS_DETECT
sh3ss_ss: sh3ss_set_socket(sock=0, flags=240, csc_mask=80, Vcc=33, Vpp=33, io_irq=0)
sh3ss_ss: start reset card
sh3ss_ss: enabling card output
sh3ss_ss: sh3ss_set_socket(sock=0, flags=200, csc_mask=80, Vcc=33, Vpp=33, io_irq=0)
sh3ss_ss: stop reset card
sh3ss_ss: sh3ss_get_status(0) = 10c0
sh3ss_ss: sh3ss_register_callback(1)
sh3ss_ss: sh3ss_get_status(1) = 10c0
sh3ss_ss: sh3ss_get_status(1) = 10c0
sh3ss_ss: sh3ss_set_socket(sock=1, flags=0, csc_mask=80, Vcc=33, Vpp=33, io_irq=0)
sh3ss_ss: sh3ss_set_voltage(1, 33, 33)
sh3ss_ss: sh3ss_set_socket(sock=1)SS_DETECT
sh3ss_ss: sh3ss_set_socket(sock=1, flags=240, csc_mask=80, Vcc=33, Vpp=33, io_irq=0)
sh3ss_ss: start reset card
sh3ss_ss: enabling card output
sh3ss_ss: sh3ss_set_socket(sock=1, flags=200, csc_mask=80, Vcc=33, Vpp=33, io_irq=0)
sh3ss_ss: stop reset card
sh3ss_ss: sh3ss_get_status(1) = 10c0
supercat:~#
supercat:~#
supercat:~# cardmgr
cardmgr[146]: watching 2 cs: IO port probe 0x0000-0x0fff:sockets
 excluding excluding 0x08-0x0f 0x18-0x1f 0x28-0x2f 0x38-0x3f 0x48-0x4f 0x58-0x5f 0x68-0x77 0x80-0x87 0x90-0x9f 0xa8-0xa
f 0xb8-0xc7 0xd8-0xdf 0xe8-0xef 0xf8-0xff 0x108-0x10f 0x118-0x11f 0x128-0x12f 0x138-0x13f 0x148-0x157 0x160-0x167 0x170
-0x177 0x180-0x19f 0x1a8-0x1af 0x1b8-0x1cf 0x1d8-0x1ef 0x1f8-0x227 0x230-0x237 0x240-0x247 0x250-0x257 0x260-0x267 0x27
0-0x277 0x280-0x2af 0x2b8-0x2bf 0x2c8-0x2cf 0x2d8-0x2e7 0x2f0-0x327 0x330-0x347 0x350-0x357 0x360-0x37f 0x388-0x3cf 0x3
d8-0x3ef 0x3f8-0x3ff 0x408-0x40f 0x418-0x41f 0x428-0x42f 0x438-0x43f 0x448-0x467 0x470-0x497 0x4a0-0x4a7 0x4b0-0x4c7 0x
4d0-0x4ef 0x4f8-0x4ff 0x508-0x50f 0x518-0x51f 0x528-0x52f 0x538-0x53f 0x548-0x557 0x560-0x567 0x570-0x577 0x580-0x587 0
x590-0x5a7 0x5b0-0x637 0x640-0x647 0x650-0x667 0x670-0x687 0x690-0x697 0x6a0-0x6a7 0x6b0-0x6b7 0x6c0-0x6c7 0x6d0-0x717
0x720-0x727 0x730-0x737 0x740-0x747 0x750-0x75f 0x768-0x76f 0x778-0x77f 0x788-0x7a7 0x7b0-0x7cf 0x7d8-0x7ef 0x7f8-0x7ff
 0x808-0x80f 0x818-0x81f 0x828-0x82f 0x838-0x83f 0x848-0x84f 0x858-0x877 0x880-0x8c7 0x8d0-0x8ef 0x8f8-0x90f 0x918-0x96
7 0x970-0x977 0x980-0x987 0x990-0x99f 0x9a8-0x9af 0x9b8-0x9bf 0x9c8-0x9cf 0x9d8-0x9e7 0x9f0-0x9f7 0xa00-0xa07 0xa10-0xa
1f 0xa28-0xa2f 0xa38-0xa3f 0xa48-0xa4f 0xa58-0xa5f 0xa68-0xa77 0xa80-0xa87 0xa90-0xa97 0xaa0-0xaa7 0xab0-0xaf7 0xb00-0x
b07 0xb10-0xb1f 0xb28-0xb2f 0xb38-0xb3f 0xb48-0xb4f 0xb60-0xb67 0xb70-0xb77 0xb80-0xb87 0xb90-0xbbf 0xbc8-0xbcf 0xbd8-0
xbef 0xbf8-0xbff 0xc08-0xc0f 0xc18-0xc1f 0xc28-0xc2f 0xc38-0xc3f 0xc48-0xc4f 0xc58-0xc67 0xc70-0xc77 0xc80-0xc87 0xc98-
0xc9f 0xca8-0xcaf 0xcb8-0xcbf 0xcc8-0xccf 0xcd8-0xce7 0xcf0-0xcff 0xd08-0xd0f 0xd18-0xd27 0xd38-0xd3f 0xd48-0xd7f 0xd88
-0xd8f 0xd98-0xde7 0xdf0-0xdf7 0xe00-0xe07 0xe10-0xe17 0xe20-0xe27 0xe30-0xe37 0xe40-0xe77 0xe80-0xe97 0xea8-0xeaf 0xeb
8-0xebf 0xec8-0xecf 0xed8-0xee7 0xef8-0xeff 0xf08-0xf1f 0xf28-0xf2f 0xf38-0xf3f 0xf48-0xf67 0xf70-0xf77 0xf80-0xf87 0xf
90-0xf97 0xfa0-0xfb7 0xfc0-0xfc7 0xfd0-0xfd7 0xfe8-0xfef 0xff8-0xfff
supercat:~# sh3ss_ss: sh3ss_get_status(0) = 10c0
sh3ss_ss: sh3ss_set_socket(sock=0, flags=200, csc_mask=80, Vcc=33, Vpp=0, io_irq=0)
sh3ss_ss: sh3ss_set_voltage(0, 33, 0)
sh3ss_ss: sh3ss_set_socket(sock=0, flags=220, csc_mask=80, Vcc=33, Vpp=0, io_irq=9)
sh3ss_ss: sh3ss_set_socket(sock=0) sh3ss_map_irq(34,9)
cat709_make_irq_demux(34 -> 9)
sh3ss_ss: card type: i/o
cs: write_cis_mem(1, 0x103, 1)
write_cis_mem::bus_writeb(0,b8000206)
cs: write_cis_mem(1, 0x100, 1)
write_cis_mem::bus_writeb(41,b8000200)
cs: write_cis_mem(1, 0x101, 1)
write_cis_mem::bus_writeb(0,b8000202)
cs: write_cis_mem(1, 0x102, 1)
write_cis_mem::bus_writeb(0,b8000204)
sh3ss_ss: sh3ss_set_io_map(sock=0, map=0, flags=0x5, speed=0ns, start=0x0b50, stop=0x0b5f)
sh3ss_ss: port_map(start=0xb50,stop=0xb5f,physaddr=0xba000000)
cat709_port_map(start(0xb50),stop(0xb5f),offset(0xba000000))
supercat:~#
supercat:~# ide_cs: ide_register() at 0xb50 & 0xb5e, irq 9 failed
sh3ss_ss: sh3ss_set_socket(sock=0, flags=200, csc_mask=80, Vcc=33, Vpp=0, io_irq=0)
sh3ss_ss: sh3ss_set_socket(sock=0) sh3ss_unmap_irq(9)
cat709_make_irq_undemux(34)
sh3ss_ss: card type: memory
sh3ss_ss: sh3ss_set_io_map(sock=0, map=0, flags=0x0, speed=0ns, start=0x0000, stop=0x0001)
sh3ss_ss: port_unmap(start=0x000,stop=0x001)
cat709_port_unmap(start(0x000) or stop(0x001))
sh3ss_ss: sh3ss_get_status(1) = 10c0
sh3ss_ss: sh3ss_set_socket(sock=1, flags=200, csc_mask=80, Vcc=33, Vpp=0, io_irq=0)
sh3ss_ss: sh3ss_set_voltage(1, 33, 0)
sh3ss_ss: sh3ss_set_socket(sock=1, flags=320, csc_mask=80, Vcc=33, Vpp=0, io_irq=9)
sh3ss_ss: sh3ss_set_socket(sock=1) sh3ss_map_irq(32,9)
cat709_make_irq_demux(32 -> 9)
sh3ss_ss: card type: i/o
cs: write_cis_mem(1, 0x103, 1)
write_cis_mem::bus_writeb(0,b8008206)
cs: write_cis_mem(1, 0x100, 1)
write_cis_mem::bus_writeb(4b,b8008200)
cs: write_cis_mem(1, 0x101, 1)
write_cis_mem::bus_writeb(8,b8008202)
cs: write_cis_mem(1, 0x102, 1)
write_cis_mem::bus_writeb(0,b8008204)
cs: write_cis_mem(1, 0x104, 1)
write_cis_mem::bus_writeb(0,b8008208)
cs: write_cis_mem(1, 0x105, 1)
write_cis_mem::bus_writeb(e8,b800820a)
cs: write_cis_mem(1, 0x106, 1)
write_cis_mem::bus_writeb(2,b800820c)
sh3ss_ss: sh3ss_set_io_map(sock=1, map=0, flags=0x1, speed=0ns, start=0x02e8, stop=0x02ef)
sh3ss_ss: port_map(start=0x2e8,stop=0x2ef,physaddr=0xba008000)
cat709_port_map(start(0x2e8),stop(0x2ef),offset(0xba008000))
ttyS00 at port 0x02e8 (irq = 9) is a 16550A
supercat:~#
supercat:~#
supercat:~# pon airh
supercat:~# tail -f /var/log/syslog
Jan  4 08:45:08 supercat chat[175]: expect (CONNECT)
Jan  4 08:45:08 supercat chat[175]: ^M
Jan  4 08:45:10 supercat chat[175]: ATDT0570-570-635##61^M^M
Jan  4 08:45:10 supercat chat[175]: CONNECT
Jan  4 08:45:10 supercat chat[175]:  -- got it
Jan  4 08:45:10 supercat chat[175]: send (\d)
Jan  4 08:45:11 supercat pppd[174]: Serial connection established.
Jan  4 08:45:11 supercat pppd[174]: using channel 1
Jan  4 08:45:11 supercat pppd[174]: Using interface ppp0
Jan  4 08:45:11 supercat pppd[174]: Connect: ppp0 <--> /dev/ttyS0
Jan  4 08:45:12 supercat pppd[174]: sent [LCP ConfReq id=0x1    ]
Jan  4 08:45:12 supercat pppd[174]: rcvd [LCP ConfRej id=0x1   ]
Jan  4 08:45:12 supercat pppd[174]: sent [LCP ConfReq id=0x2 ]
Jan  4 08:45:13 supercat pppd[174]: rcvd [LCP ConfReq id=0x1   ]
Jan  4 08:45:13 supercat pppd[174]: sent [LCP ConfAck id=0x1   ]
Jan  4 08:45:13 supercat pppd[174]: rcvd [LCP ConfAck id=0x2 ]
Jan  4 08:45:13 supercat pppd[174]: sent [LCP EchoReq id=0x0 magic=0x25a868b6]
Jan  4 08:45:13 supercat pppd[174]: sent [PAP AuthReq id=0x1 user="xxxxxxxxx" password=]
Jan  4 08:45:13 supercat pppd[174]: rcvd [LCP EchoRep id=0x0 magic=0xc3c0bdb9]
Jan  4 08:45:13 supercat pppd[174]: rcvd [PAP AuthAck id=0x1 ""]
Jan  4 08:45:13 supercat pppd[174]: kernel does not support PPP filtering
Jan  4 08:45:13 supercat pppd[174]: sent [IPCP ConfReq id=0x1    ]
Jan  4 08:45:13 supercat pppd[174]: rcvd [IPCP ConfReq id=0x1 ]
Jan  4 08:45:13 supercat pppd[174]: sent [IPCP ConfAck id=0x1 ]
Jan  4 08:45:14 supercat pppd[174]: rcvd [IPCP ConfRej id=0x1 ]
Jan  4 08:45:14 supercat pppd[174]: sent [IPCP ConfReq id=0x2   ]
Jan  4 08:45:14 supercat pppd[174]: rcvd [IPCP ConfNak id=0x2   ]
Jan  4 08:45:14 supercat pppd[174]: sent [IPCP ConfReq id=0x3   ]
Jan  4 08:45:15 supercat pppd[174]: rcvd [IPCP ConfAck id=0x3   ]
Jan  4 08:45:15 supercat pppd[174]: not replacing existing default route to eth0 [192.168.7.1]
Jan  4 08:45:15 supercat pppd[174]: Cannot determine ethernet address for proxy ARP
Jan  4 08:45:15 supercat pppd[174]: local  IP address 61.193.64.236
Jan  4 08:45:15 supercat pppd[174]: remote IP address 61.204.7.254
Jan  4 08:45:15 supercat pppd[174]: primary   DNS address 202.225.94.247
Jan  4 08:45:15 supercat pppd[174]: secondary DNS address 210.147.240.193
Jan  4 08:45:15 supercat pppd[174]: Script /etc/ppp/ip-up started (pid 178)
Jan  4 08:45:15 supercat pppd[174]: Script /etc/ppp/ip-up finished (pid 178), status = 0x0
Jan  4 08:45:43 supercat pppd[174]: sent [LCP EchoReq id=0x1 magic=0x25a868b6]
Jan  4 08:45:43 supercat pppd[174]: rcvd [LCP EchoRep id=0x1 magic=0xc3c0bdb9]

XAX

月曜日はエグザスでbody pumpの日で楽しみにしてたんだけども、pppdのハッキングをしていて行けなかった。腕立てして寝ることにする。