crash

thread

前回、たまたま収集出来たFreeBSDの姿体を腑分けしてる。

0x0102d895 in doadump (textdump=<optimized out>)
    at /usr/src/sys/kern/kern_shutdown.c:398
398             savectx(&dumppcb);
(kgdb) thread
[Current thread is 164 (Thread 100176)]
(kgdb) info threads 164
  Id   Target Id                      Frame
 * 164  Thread 100176 (PID=1116: tmux) 0x0102d895 in doadump (
    textdump=<optimized out>) at /usr/src/sys/kern/kern_shutdown.c:398

kgdbが出してきた報告。これはある一面でしかない。一面と言うのは、色々なプロセスが色々な事が発生するのを待っているって事。この待ちがスレッドって形で表現されてる。今はtmuxなプロセスの一部が応答したって事だ。

(kgdb) info threads
 :
  142  Thread 100133 (PID=1048: cron)                    0x0105b242 in sched_switch (td=0x2659eae0, flags=260) at /usr/src/sys/kern/sched_ule.c:2244
  143  Thread 100123 (PID=1060: login)                   0x0105b242 in sched_switch (td=0x1d4b73a0, flags=260) at /usr/src/sys/kern/sched_ule.c:2244
  :

じゃ、どんなスレッドが有るか確認。cronなんてのが有ったので、それに切り換えてみる。

(kgdb) thread 142
[Switching to thread 142 (Thread 100133)]
#0  0x0105b242 in sched_switch (td=0x2659eae0, flags=260)
    at /usr/src/sys/kern/sched_ule.c:2244
2244                    cpu_switch(td, newtd, mtx);
(kgdb) bt 5
#0  0x0105b242 in sched_switch (td=0x2659eae0, flags=260)
    at /usr/src/sys/kern/sched_ule.c:2244
#1  0x010399b3 in mi_switch (flags=260) at /usr/src/sys/kern/kern_synch.c:544
#2  0x01083bd5 in sleepq_switch (wchan=wchan@entry=0x1d6de4c <nanowait>,
    pri=pri@entry=108) at /usr/src/sys/kern/subr_sleepqueue.c:608
#3  0x01084045 in sleepq_catch_signals (wchan=0x1d6de4c <nanowait>,
    pri=<unavailable>) at /usr/src/sys/kern/subr_sleepqueue.c:524
#4  0x01084264 in sleepq_timedwait_sig (wchan=0x1d6de4c <nanowait>, pri=108)
    at /usr/src/sys/kern/subr_sleepqueue.c:704
(More stack frames follow...)

そして、どんな具合に待ちに入ってるか確認。まあ、cronの場合は指定時間に仕事をしてくれってのが想像出来る。そしてcronを起す方法としてシグナルが使われている。目覚まし時計と一緒だな。現実を模倣したモデルになってる。

今回の場合、スレッド数が182ヶ有った。それだけの仕事を見張て、切り換えてくれるカーネルって、なかなかの者だぞ。うちの女房は、キッチンタイマー2ヶを使ってるけど、どちらのタイマーを何に割当てたか(例えば、パズタのゆで時間と、卵のボイル時間)、ときたま遺失してしまいますから。。やけにパスタが伊勢うどん風になったりします。そんな時は、消化に良いと理屈が付けられますねどね。

xorg.conf

FreeBSDのパニック問題。どう対策する? インテルドライバーを削除してvesaにしちゃうってのが一番楽だけど、それじゃ負けている気がする。パッケージになってるリナ由来のDRMを削除して、様子を見る事にした。

で一つ問題が出た。startxしてXになってムフフを堪能した後、Xを落とすとコンソールモードに戻るはずなんだけど、画面制御が失われてしまって、どうにも困ったモードになっちゃうんだ。

自前でxorg.confを作ってみるかな。Xorg -configure なんて久し振り。出来上がった者を眺めると、何と、スクリーンが2つの仕様になってた。これがインテルさんの底力なんですかね。 Xorg.logを眺めると、一時vesaドライバーもロードされるんだけど、インテルさんによって排除されてるよ。

Section "ServerLayout"
        Identifier     "X.org Configured"
        Screen      0  "Screen0" 0 0
        Screen      1  "Screen1" RightOf "Screen0"
        InputDevice    "Mouse0" "CorePointer"
        InputDevice    "Keyboard0" "CoreKeyboard"
EndSection

Section "Device"
        Identifier  "Card0"
        Driver      "intel"
        BusID       "PCI:0:2:0"
EndSection

Section "Device"
        Identifier  "Card1"
        Driver      "intel"
        BusID       "PCI:0:2:1"
EndSection

Section "Screen"
        Identifier "Screen0"
        Device     "Card0"
        Monitor    "Monitor0"
         :

論理的には、カードの2枚刺しに設定されるのね。で、これを/usr/local/etc/X11/xorg.confとして配置。だがやはりX終了後にコンソールに戻らない。困ったものだ。

ddb in OpenBSD

自由にパニックを興して、遊んでみたい。ddbを呼び出す。FreeBSDだと前回も書いたように、カーネルのコンパイルが必要。で、そんな面倒いらずなのがOpenBSD。ちょいと仕掛けが必要。

vbox# cat /etc/boot.conf
set tty com0
set timeout 1
vbox# cat /sysctl.conf
ddb.console=1

シリアルコンソールを用意して、そこから起動するのさ。それから忘れてはいけない ddb.consoleの設定もね。

alias inddb='sysctl -w ddb.trigger=1'

2016/11 あたりにddbって事でやってるな。

boot how
    Reboot the machine depending on how:

    boot sync
        Sync disks and reboot.
    boot crash
        Dump core and reboot.
    boot dump
        Sync disks, dump core and reboot.
    boot halt
        Just halt.
    boot reboot
        Just reboot.
    boot poweroff
        Power down the machine whenever possible; if it fails, just halt.

boot dumpすればいいのかな。

crash(8)が親切な道標になってる。

実際にcrash

inddbでddbを呼出、パニックさせる。

ddb{0}> call panic
panic: uvm_fault(0xd58e3b40, 0x0, 0, 1) -> e
Stopped at      db_enter+0x4:   popl    %ebp
    TID    PID    UID     PRFLAGS     PFLAGS  CPU  COMMAND
*303083  64282      0         0x3          0    0K sysctl
db_enter() at db_enter+0x4
panic(d0c64bf2) at panic+0x7a
kpageflttrap(f578fe5c,0) at kpageflttrap+0x138
trap(f578fe5c) at trap+0x260
calltrap() at calltrap+0xc
kprintf() at kprintf+0xa0
panic(0) at panic+0x55
db_fncall(d0824e84,0,0,f578ffe4) at db_fncall+0x2dd
db_command(d0eabfcc,d0e54d00) at db_command+0x313
db_command_loop() at db_command_loop+0x7e
db_trap(1,0) at db_trap+0x10f
db_ktrap(1,0,f579010c) at db_ktrap+0x12f
trap(f579010c) at trap+0x495
calltrap() at calltrap+0xc
https://www.openbsd.org/ddb.html describes the minimum info required in bug
reports.  Insufficient info makes it difficult to find and fix bugs.

これでddbはcoredumpする理由が出来た(少々強引だけど)。早速ddbのbootコマンドを使って、dumpさせ、自動起動に持っていく。

ddb{0}> boot dump
syncing disks...13 11  done
WARNING: not updating battery clock

dumping to dev 1, offset 8
dump 132 131 130 129 128 127 126 125 124 123 122 121 120 119 118 117 116 115 114 113 112 111 110 109 108 107 106 105 104 103 102 101 100 99 98 97 96 95 94 93 92 91 90 89 88 87 86 85 84 83 82 81 80 79 78 77 76 75 74 73 72 71 70 69 68 67 66 65 64 63 62 61 60 59 58 57 56 55 54 53 52 51 50 49 48 47 46 45 44 43 42 41 40 39 38 37 36 35 34 33 32 31 30 29 28 27 26 25 24 23 22 21 20 19 18 17 16 15 14 13 12 11 10 9 8 7 6 5 4 3 2 1 0 area improper

rebooting...
>> OpenBSD/i386 BOOT 3.44
boot>
booting hd0a:/bsd: 10435355+2479108+245780+0+1134592 [710097+107+587008+631014]=0xf7ae64
entry point at 0x201000
  :
avecore: reboot after panic: uvm_fault(0xd58e3b40, 0x0, 0, 1) -> e
savecore: system went down at Tue Sep 20 16:00:48 2022
savecore: /var/crash/bounds: No such file or directory
savecore: writing core to /var/crash/bsd.0.core
savecore: writing kernel to /var/crash/bsd.0
checking quotas: done.
clearing /tmp
kern.securelevel: 0 -> 1
creating runtime link editor directory cache.

起動の途中でcoreが出来ている事に気付きsavecoreを発動。/var/crashにセーブしてくれる。

savecoreの仕事

仕事の出来栄えを確認

vbox$ ls -lh /var/crash/
total 302792
-rw-------  1 root  wheel     2B Sep 20 16:04 bounds
-rw-------  1 root  wheel  14.4M Sep 20 16:04 bsd.0
-rw-------  1 root  wheel   133M Sep 20 16:04 bsd.0.core
-rw-r--r--  1 root  wheel     5B May  8  2020 minfree
vbox# cmp bsd.0 /bsd
vbox# cd /var/crash
vbox# cat minfree
4096
vbox# cat bounds
1

bsd.0ってのは、現在のカーネルのコピー。boundsは、次の通し番号。

次はgdbを起動して …

(gdb) file /var/crash/bsd.0
Reading symbols from /var/crash/bsd.0...(no debugging symbols found)...done.
(gdb) target kvm /var/crash/bsd.0.core
Cannot access memory at address 0xf578fc10

あれ、おかしいぞ。

[Note that the “kvm” target is currently only supported by gdb(1) on some
architectures.]

crash(8)にある、この説明に引掛ったんかな? 別の手段で

vbox# gdb bsd.0 bsd.0.core
GNU gdb 6.3
Copyright 2004 Free Software Foundation, Inc.
GDB is free software, covered by the GNU General Public License, and you are
welcome to change it and/or distribute copies of it under certain conditions.
Type "show copying" to see the conditions.
There is absolutely no warranty for GDB.  Type "show warranty" for details.
This GDB was configured as "i386-unknown-openbsd7.1"...
(no debugging symbols found)

"/var/crash/bsd.0.core" is not a core dump: File format not recognized

認識しないフォーマットみたい。じゃ、FreeBSD時代を思い出して

vbox# ps -N /var/crash/bsd.0 -M /var/crash/bsd.0.core -O paddr
ps: can't read process at f57b95f8

これもだめだな。

other machine

余りやりたくないけど、64Bitなマシンでも実験。

ddb{0}> call panic
uvm_fault(0xfffffd80887bc228, 0x0, 0, 1) -> e
kernel: page fault trap, code=0
Faulted in DDB; continuing...
syncing disks...2 2 2 2 2 2 2 2 2 2 2 2 2 2 2 2 2 2 2 2  giving up
WARNING: not updating battery clock

dump to dev 0,1 not possible
rebooting...

どうも、sync diskが失敗してる。それからダンプも出来ていない。syncは、どのあたりで行われている? 検索したら、 kern/vfs_subr.c

/*
 * Sync and unmount file systems before shutting down.
 */
void
vfs_shutdown(struct proc *p) {

        printf("syncing disks...");

        if (panicstr == NULL) {
                /* Sync before unmount, in case we hang on something. */
                sys_sync(p, NULL, NULL);
                vfs_unmountall();
        }

#if NSOFTRAID > 0
        sr_quiesce();
#endif

        if (vfs_syncwait(p, 1))
                printf(" giving up\n");
        else
        else
                printf(" done\n");
}

マウントされてるデバイスを全部syncで書き出し、全てをアンマウントするんだな。 それが失敗してるってどうよ。ここで足踏みしてもしょうがないので全体を俯瞰する意味で、 実際のダンプ・ルーチンも見ておく。 arch/amd64/amd64/machdep.c とかだ。

dumpsys(void)
{
  :
        /*
         * For dumps during autoconfiguration,
         * if dump device has already configured...
         */
        if (dumpsize == 0)
                dumpconf();
        if (dumplo <= 0 || dumpsize == 0) {
                printf("\ndump to dev %u,%u not possible\n", major(dumpdev),
                    minor(dumpdev));
                return;
        }
        printf("\ndumping to dev %u,%u offset %ld\n", major(dumpdev),
            minor(dumpdev), dumplo);
         :
                        /* Print out how many MBs we have left to go. */
                        if ((totalbytesleft % (1024*1024)) < BYTES_PER_DUMP)
                                printf("%ld ", totalbytesleft / (1024 * 1024));
         :
                        error = (*dump)(dumpdev, blkno, va, n);
                        if (error)
                                goto err;
          :
 err:
        switch (error) {
        case EINVAL:
                printf("area improper\n");
                break;
        case 0:
                printf("succeeded\n");
                break;

dumploは、パーテションの先頭を飛すしかけだな。だから1を期待。それから実際にダンプしたいサイズをメモリーマネージャのデータから計算。それがZEROならダンプする意味ネェって判断。どういう訳がZEROになってるっぽい。

それからついでに、ダンプが成功した(と思われる)32Bitマシンもよく見ると、エリアが不適当のエラーを発している。このおかげで、正しいsavecoreが作成されないのかな。

savecore

/usr/src/sbinに置いてある。OS起動中に/etc/rcから呼び出されるので、普通のユーザーランドプログラムだ。

void
save_core(void)
{
  :
        if (kvm_dump_wrtheader(kd_dump, fp, dumpsize) == -1) {
                syslog(LOG_ERR, "kvm_dump_wrtheader: %s : %s", path,
                        kvm_geterr(kd_dump));
                exit(1);
        }

        /* Copy the core file. */
        syslog(LOG_NOTICE, "writing %score to %s",
            zcompress ? "compressed " : "", path);
        for (; dumpsize != 0; dumpsize -= nr) {

核の部分は、切り出してある。 KVM_DUMP_MKHEADER(3) keme_setup で、お膳立をやっていてくれるので、すっきりいっている。

kvm_dump_wrtheader().  This function takes care ofs generating the generic
header, the CORE_CPU section and the section header of the CORE_DATA
section.  The data is written to the file pointed at by fp.  The dumpsize
argument is only used to properly set the segment size of the CORE_DATA
section.  Note that this function assumes that fp is positioned at file
location 0.  This function will not seek and therefore allows fp to be a
file pointer obtained by zopen().

try

どうも64Bitなマシンは、思ったように動かないので、再びVirrtulaBoxな設備上の32Bitで確認。どうもスワップエリアが足りない疑惑が有るので、極小のマシンで確認。2CPUで動かしていたのを1CPUに変更。それからメモリー消費を抑える為、余分なプロセスをあらかじめ殺しておく。(ex: sshd,syslogd,cron, etc …)

small

vbox# top
load averages:  0.00,  0.00,  0.00                       vbox.local.jp 07:34:12
4 processes: 3 idle, 1 on processor                                    up  0:12
CPU:  0.0% user,  0.0% nice,  0.0% sys,  0.0% spin,  0.0% intr,  100% idle
Memory: Real: 3576K/37M act/tot Free: 1957M Cache: 17M Swap: 0K/133M

  PID USERNAME PRI NICE  SIZE   RES STATE     WAIT      TIME    CPU COMMAND
    1 root      10    0  604K  556K idle      wait      0:01  0.00% init
13902 root      18    0  856K  828K idle      sigsusp   0:00  0.00% ksh
98932 root      28    0  900K 1932K onproc    -         0:00  0.00% top
12437 root       3    0  500K 1312K idle      ttyin     0:00  0.00% getty

もうinitとログインシェルだけっていうとんでもないシステムです。これでswapサイズの133M内に収まるかな。じゃ、実行します。

vbox# inddb
Stopped at      db_enter+0x4:   popl    %ebp
ddb{0}> boot crash

dumping to dev 1, offset 8
dump 132 131 130  ...  8 7 6 5 4 3 2 1 0 area improper

rebooting...
>> OpenBSD/i386 BOOT 3.44
boot>
  :
savecore: reboot
savecore: system went down at Thu Sep 22 07:35:51 2022
savecore: writing core to /var/crash/bsd.2.core
savecore: writing kernel to /var/crash/bsd.2
checking quotas: done.
clearing /tmp
kern.securelevel: 0 -> 1
 :

相変わらず、area improperになってるなあ。期待薄。

確認

vbox# ls -l /var/crash/
total 908360
-rw-------  1 root  wheel          2 Sep 22 07:36 bounds
-rw-------  1 root  wheel   15093330 Sep 20 16:04 bsd.0
-rw-------  1 root  wheel  139792916 Sep 20 16:04 bsd.0.core
-rw-------  1 root  wheel   15093330 Sep 22 06:52 bsd.1
-rw-------  1 root  wheel  139792916 Sep 22 06:52 bsd.1.core
-rw-------  1 root  wheel   15093330 Sep 22 07:36 bsd.2
-rw-------  1 root  wheel  139792916 Sep 22 07:36 bsd.2.core
-rw-r--r--  1 root  wheel          5 May  8  2020 minfree
vbox# ps -N /var/crash/bsd.2 -M /var/crash/bsd.2.core -O paddr
ps: can't read process at ff7ff864

これだけ努力してもswapエリアを喰い潰しているなあ。そして、やっぱりエラーだわさ。

ddb

ちょいといじけて、リナのカーネルには入っていないだろう、カーネルに内蔵してるローレベルなデバッガーを調べておく。

sakae@deb:/usr/src/sys/ddb$ ls
db_access.c   db_dwarf.c    db_input.c      db_run.c     db_variables.c
db_access.h   db_elf.c      db_interface.h  db_run.h     db_variables.h
db_break.c    db_elf.h      db_lex.c        db_sym.c     db_watch.c
db_break.h    db_examine.c  db_lex.h        db_sym.h     db_watch.h
db_command.c  db_expr.c     db_output.c     db_trap.c
db_command.h  db_extern.h   db_output.h     db_usrreq.c
db_ctf.c      db_hangman.c  db_prof.c       db_var.h

全部見ると大変なので、お世話になった boot crashの挙動。ソース名前なら念力で場所を推定。そう、きっと、 db_command.c のあたりに有るはず。デバッガーのREPLでしょうから。

struct db_command db_boot_cmds[] = {
        { "sync",       db_boot_sync_cmd,       0,      0 },
        { "crash",      db_boot_crash_cmd,      0,      0 },
        { "dump",       db_boot_dump_cmd,       0,      0 },
        { "halt",       db_boot_halt_cmd,       0,      0 },
        { "reboot",     db_boot_reboot_cmd,     0,      0 },
        { "poweroff",   db_boot_poweroff_cmd,   0,      0 },
        { NULL, }
};

void
db_reboot(int howto)
{
        spl0();
        if (!curproc)
                curproc = &proc0;
        reboot(howto);
}

void
db_boot_crash_cmd(db_expr_t addr, int haddr, db_expr_t count, char *modif)
{
        db_reboot(RB_NOSYNC | RB_DUMP | RB_TIMEBAD | RB_USERREQ);
}

ビンゴでした、カーネルのrebootを呼び出している。引数にはどうするかって要求の載せておくんだな。

rebootはkernに共通な名称。実際はbootって名前で、それぞれのarchに依存する。i386なら、 sys/arch/i386/i386/machdep.c

__dead void
boot(int howto)
{
   :
        if ((howto & RB_NOSYNC) == 0 && waittime < 0) {
                waittime = 0;
                vfs_shutdown(curproc);

                if ((howto & RB_TIMEBAD) == 0) {
                        resettodr();
                } else {
                        printf("WARNING: not updating battery clock\n");
                }
        }
        if_downall();

        uvm_shutdown();
        splhigh();
        cold = 1;

        if ((howto & RB_DUMP) != 0)
                dumpsys();
        :
doreset:
        printf("rebooting...\n");
        cpu_reset();
        for (;;)
                continue;
        /* NOTREACHED */

dumpsys()もここに有るぞ。

long long ago

今回ddbへ突入する為のアイリアスを設置してて、昔の事を思い出した。MAC信者だった頃、MacSEの左手奧にデバッガー突入用のプラスティック部品を取り付けたんだ。 マザーボードについていた押しボタンを押す棒だ。

そのスイッチが押されると、MC68000に割込みが入り、それを契機にデバッガーが起動するしかけになっていた。

綺麗な白黒のGUI画面に変って、無骨なCUIっぽいデバッガー画面が見えると、何だかワクワクして、何度もこの操作をやったよ。ええ、プロテクト外しとかね。プロテクト部分をすっとばしてしまうと言う楽しい技。どこにそのルーチンが潜んでいるか見付るのが楽しかったねぇ。

今は不細工なインテルが入っているから、そんなアセンブラの領域までは入っていかないけどね。まあ、C言語ぐらいだったら見てもいいかなってレベルだ。

今はリナが主流になってしまって、こういう楽しい事をやる人は余りいないんだろうね。みんな飼い馴らされてしまっているよ。

2歩進め

余り古い話ばかりだといけないので、現在より2歩先の話

「Linux」、バージョン6.1でRustを導入へ

こうなったら、gccはどうなる? リナスの要求で色々gcc限定って機能が追加されてきたって言う蜜月は終りか。

どこかの人もgcc限定機能を使って、とある言語をスピードアップしてた。 オイラーはgccにロックインされるのが嫌なんで、手を出さなかったけどね。


This year's Index

Home