/usr/share/doc/user-mode-linux-doc/html/UserModeLinux-HOWTO-12.html is in user-mode-linux-doc 20060501-1.
This file is owned by root:root, with mode 0o644.
The actual contents of the file can be viewed below.
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100 101 102 103 104 105 106 107 108 109 110 111 112 113 114 115 116 117 118 119 120 121 122 123 124 125 126 127 128 129 130 131 132 133 134 135 136 137 138 139 140 141 142 143 144 145 146 147 148 149 150 151 152 153 154 155 156 157 158 159 160 161 162 163 164 165 166 167 168 169 170 171 172 173 174 175 176 177 178 179 180 181 182 183 184 185 186 187 188 189 190 191 192 193 194 195 196 197 198 199 200 201 202 203 204 205 206 207 208 209 210 211 212 213 214 215 216 217 218 219 220 221 222 223 224 225 226 227 228 229 230 231 232 233 234 235 236 237 238 239 240 241 242 243 244 245 246 247 248 249 250 251 252 253 254 255 256 257 258 259 260 261 262 263 264 265 266 267 268 269 270 271 272 273 274 275 276 277 278 279 280 281 282 283 284 285 286 287 288 289 290 291 292 293 294 295 296 297 298 299 300 301 302 303 304 305 306 307 308 309 310 311 312 313 314 315 316 317 318 319 320 321 322 323 324 325 326 327 328 329 330 331 332 333 334 335 336 337 338 339 340 341 342 343 344 345 346 347 348 349 350 351 352 353 354 355 356 357 358 359 360 361 362 363 364 365 366 367 368 369 370 371 372 373 374 375 376 377 378 379 380 381 382 383 384 385 386 387 388 389 390 391 392 393 394 395 396 397 398 399 400 401 402 403 404 405 406 407 408 409 410 411 412 413 414 415 416 417 418 419 420 421 422 423 424 425 426 427 428 429 430 431 432 433 434 435 436 437 438 439 440 441 442 443 444 445 446 447 448 449 450 451 452 453 454 455 456 457 458 459 460 461 462 463 464 465 466 467 468 469 470 471 472 473 474 475 476 477 478 479 480 481 482 483 484 485 486 487 488 489 490 491 492 493 494 495 496 497 498 499 500 501 502 503 504 505 506 507 508 509 510 511 512 513 514 515 516 517 518 519 520 521 522 523 524 525 526 527 528 529 530 531 532 533 534 535 536 537 538 539 540 541 542 543 544 545 546 547 548 549 550 551 552 553 554 555 556 557 558 559 560 561 562 563 564 565 566 567 568 569 570 571 572 573 574 575 576 577 578 579 580 581 582 583 584 585 586 587 588 589 590 591 592 593 594 595 596 597 598 599 600 601 602 603 604 605 606 607 608 609 610 611 612 613 614 615 616 617 618 619 620 621 622 623 624 625 626 627 628 629 630 631 632 633 634 635 636 637 638 639 640 641 642 643 644 645 646 647 648 649 650 651 652 653 654 655 656 657 658 659 660 661 662 663 664 665 666 667 668 669 670 671 672 673 674 675 676 677 678 679 680 681 682 683 684 685 686 687 688 689 690 691 692 693 694 695 696 697 698 699 700 701 702 703 704 705 706 707 708 709 710 711 712 713 714 715 716 717 718 719 720 721 722 723 724 725 726 727 728 729 730 731 732 733 734 735 736 737 738 739 740 741 742 743 744 745 746 747 748 749 750 751 752 753 754 755 756 757 758 759 760 761 762 763 764 | <!DOCTYPE HTML PUBLIC "-//W3C//DTD HTML 3.2 Final//EN">
<HTML>
<HEAD>
<META NAME="GENERATOR" CONTENT="LinuxDoc-Tools 0.9.21">
<TITLE>User Mode Linux HOWTO : Kernel debugging examples</TITLE>
<LINK HREF="UserModeLinux-HOWTO-13.html" REL=next>
<LINK HREF="UserModeLinux-HOWTO-11.html" REL=previous>
<LINK HREF="UserModeLinux-HOWTO.html#toc12" REL=contents>
</HEAD>
<BODY>
<A HREF="UserModeLinux-HOWTO-13.html">Next</A>
<A HREF="UserModeLinux-HOWTO-11.html">Previous</A>
<A HREF="UserModeLinux-HOWTO.html#toc12">Contents</A>
<HR>
<H2><A NAME="s12">12.</A> <A HREF="UserModeLinux-HOWTO.html#toc12">Kernel debugging examples</A></H2>
<H2><A NAME="ss12.1">12.1</A> <A HREF="UserModeLinux-HOWTO.html#toc12.1">The case of the hung fsck</A>
</H2>
<P>When booting up the kernel, fsck failed, and dropped me into a shell to fix
things up. I ran fsck -y, which hung:</P>
<P>
<BLOCKQUOTE><CODE>
<PRE>
Setting hostname uml [ OK ]
Checking root filesystem
/dev/fhd0 was not cleanly unmounted, check forced.
Error reading block 86894 (Attempt to read block from filesystem resulted in short read) while reading indirect blocks of inode 19780.
/dev/fhd0: UNEXPECTED INCONSISTENCY; RUN fsck MANUALLY.
(i.e., without -a or -p options)
[ FAILED ]
*** An error occurred during the file system check.
*** Dropping you to a shell; the system will reboot
*** when you leave the shell.
Give root password for maintenance
(or type Control-D for normal startup):
[root@uml /root]# fsck -y /dev/fhd0
fsck -y /dev/fhd0
Parallelizing fsck version 1.14 (9-Jan-1999)
e2fsck 1.14, 9-Jan-1999 for EXT2 FS 0.5b, 95/08/09
/dev/fhd0 contains a file system with errors, check forced.
Pass 1: Checking inodes, blocks, and sizes
Error reading block 86894 (Attempt to read block from filesystem resulted in short read) while reading indirect blocks of inode 19780. Ignore error? yes
Inode 19780, i_blocks is 1548, should be 540. Fix? yes
Pass 2: Checking directory structure
Error reading block 49405 (Attempt to read block from filesystem resulted in short read). Ignore error? yes
Directory inode 11858, block 0, offset 0: directory corrupted
Salvage? yes
Missing '.' in directory inode 11858.
Fix? yes
Missing '..' in directory inode 11858.
Fix? yes
</PRE>
</CODE></BLOCKQUOTE>
</P>
<P>The standard drill in this sort of situation is to fire up gdb on the
signal thread, which, in this case, was pid 1935. In another window, I
run gdb and attach pid 1935.</P>
<P>
<BLOCKQUOTE><CODE>
<PRE>
~/linux/2.3.26/um 1016: gdb linux
GNU gdb 4.17.0.11 with Linux support
Copyright 1998 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-redhat-linux"...
(gdb) att 1935
Attaching to program `/home/dike/linux/2.3.26/um/linux', Pid 1935
0x100756d9 in __wait4 ()
</PRE>
</CODE></BLOCKQUOTE>
</P>
<P>Let's see what's currently running:</P>
<P>
<BLOCKQUOTE><CODE>
<PRE>
(gdb) p current_task.pid
$1 = 0
</PRE>
</CODE></BLOCKQUOTE>
</P>
<P>It's the idle thread, which means that fsck went to sleep for some
reason and never woke up.</P>
<P>Let's guess that the last process in the process list is fsck:</P>
<P>
<BLOCKQUOTE><CODE>
<PRE>
(gdb) p current_task.prev_task.comm
$13 = "fsck.ext2\000\000\000\000\000\000"
</PRE>
</CODE></BLOCKQUOTE>
</P>
<P>It is, so let's see what it thinks it's up to:</P>
<P>
<BLOCKQUOTE><CODE>
<PRE>
(gdb) p current_task.prev_task.thread
$14 = {extern_pid = 1980, tracing = 0, want_tracing = 0, forking = 0,
kernel_stack_page = 0, signal_stack = 1342627840, syscall = {id = 4, args = {
3, 134973440, 1024, 0, 1024}, have_result = 0, result = 50590720},
request = {op = 2, u = {exec = {ip = 1350467584, sp = 2952789424}, fork = {
regs = {1350467584, 2952789424, 0 <repeats 15 times>}, sigstack = 0,
pid = 0}, switch_to = 0x507e8000, thread = {proc = 0x507e8000,
arg = 0xaffffdb0, flags = 0, new_pid = 0}, input_request = {
op = 1350467584, fd = -1342177872, proc = 0, pid = 0}}}}
</PRE>
</CODE></BLOCKQUOTE>
</P>
<P>The interesting things here are the fact that its .thread.syscall.id
is __NR_write (see the big switch in arch/um/kernel/syscall_kern.c or the
defines in include/asm-um/arch/unistd.h), and that it never returned.
Also, its .request.op is OP_SWITCH (see arch/um/include/user_util.h).
These mean that it went into a write, and, for some reason, called
schedule().</P>
<P>The fact that it never returned from write means that its stack
should be fairly interesting. Its pid is 1980 (.thread.extern_pid).
That process is being ptraced by the signal thread, so it must be
detached before gdb can attach it:
<BLOCKQUOTE><CODE>
<PRE>
(gdb) call detach(1980)
Program received signal SIGSEGV, Segmentation fault.
<function called from gdb>
The program being debugged stopped while in a function called from GDB.
When the function (detach) is done executing, GDB will silently
stop (instead of continuing to evaluate the expression containing
the function call).
(gdb) call detach(1980)
$15 = 0
</PRE>
</CODE></BLOCKQUOTE>
</P>
<P>The first detach segfaults for some reason, and the second one
succeeds.</P>
<P>Now I detach from the signal thread, attach to the fsck thread, and
look at its stack:
<BLOCKQUOTE><CODE>
<PRE>
(gdb) det
Detaching from program: /home/dike/linux/2.3.26/um/linux Pid 1935
(gdb) att 1980
Attaching to program `/home/dike/linux/2.3.26/um/linux', Pid 1980
0x10070451 in __kill ()
(gdb) bt
#0 0x10070451 in __kill ()
#1 0x10068ccd in usr1_pid (pid=1980) at process.c:30
#2 0x1006a03f in _switch_to (prev=0x50072000, next=0x507e8000)
at process_kern.c:156
#3 0x1006a052 in switch_to (prev=0x50072000, next=0x507e8000, last=0x50072000)
at process_kern.c:161
#4 0x10001d12 in schedule () at sched.c:777
#5 0x1006a744 in __down (sem=0x507d241c) at semaphore.c:71
#6 0x1006aa10 in __down_failed () at semaphore.c:157
#7 0x1006c5d8 in segv_handler (sc=0x5006e940) at trap_user.c:174
#8 0x1006c5ec in kern_segv_handler (sig=11) at trap_user.c:182
#9 <signal handler called>
#10 0x10155404 in errno ()
#11 0x1006c0aa in segv (address=1342179328, is_write=2) at trap_kern.c:50
#12 0x1006c5d8 in segv_handler (sc=0x5006eaf8) at trap_user.c:174
#13 0x1006c5ec in kern_segv_handler (sig=11) at trap_user.c:182
#14 <signal handler called>
#15 0xc0fd in ?? ()
#16 0x10016647 in sys_write (fd=3,
buf=0x80b8800 <Address 0x80b8800 out of bounds>, count=1024)
at read_write.c:159
#17 0x1006d5b3 in execute_syscall (syscall=4, args=0x5006ef08)
at syscall_kern.c:254
#18 0x1006af87 in really_do_syscall (sig=12) at syscall_user.c:35
#19 <signal handler called>
#20 0x400dc8b0 in ?? ()
</PRE>
</CODE></BLOCKQUOTE>
</P>
<P>The interesting things here are :
<UL>
<LI>There are two segfaults on this stack (frames 9 and 14)</LI>
<LI>The first faulting address (frame 11) is 0x50000800
<BLOCKQUOTE><CODE>
<PRE>
(gdb) p (void *)1342179328
$16 = (void *) 0x50000800
</PRE>
</CODE></BLOCKQUOTE>
</LI>
</UL>
</P>
<P>The initial faulting address is interesting because it is on the idle
thread's stack. I had been seeing the idle thread segfault for no
apparent reason, and the cause looked like stack corruption. In hopes
of catching the culprit in the act, I had turned off all protections
to that stack while the idle thread wasn't running. This apparently
tripped that trap.</P>
<P>However, the more immediate problem is that second segfault and I'm
going to concentrate on that. First, I want to see where the fault
happened, so I have to go look at the sigcontent struct in frame 8: </P>
<P>
<BLOCKQUOTE><CODE>
<PRE>
(gdb) up
#1 0x10068ccd in usr1_pid (pid=1980) at process.c:30
30 kill(pid, SIGUSR1);
(gdb)
#2 0x1006a03f in _switch_to (prev=0x50072000, next=0x507e8000)
at process_kern.c:156
156 usr1_pid(getpid());
(gdb)
#3 0x1006a052 in switch_to (prev=0x50072000, next=0x507e8000, last=0x50072000)
at process_kern.c:161
161 _switch_to(prev, next);
(gdb)
#4 0x10001d12 in schedule () at sched.c:777
777 switch_to(prev, next, prev);
(gdb)
#5 0x1006a744 in __down (sem=0x507d241c) at semaphore.c:71
71 schedule();
(gdb)
#6 0x1006aa10 in __down_failed () at semaphore.c:157
157 }
(gdb)
#7 0x1006c5d8 in segv_handler (sc=0x5006e940) at trap_user.c:174
174 segv(sc->cr2, sc->err & 2);
(gdb)
#8 0x1006c5ec in kern_segv_handler (sig=11) at trap_user.c:182
182 segv_handler(sc);
(gdb) p *sc
Cannot access memory at address 0x0.
</PRE>
</CODE></BLOCKQUOTE>
</P>
<P>That's not very useful, so I'll try a more manual method:
<BLOCKQUOTE><CODE>
<PRE>
(gdb) p *((struct sigcontext *) (&sig + 1))
$19 = {gs = 0, __gsh = 0, fs = 0, __fsh = 0, es = 43, __esh = 0, ds = 43,
__dsh = 0, edi = 1342179328, esi = 1350378548, ebp = 1342630440,
esp = 1342630420, ebx = 1348150624, edx = 1280, ecx = 0, eax = 0,
trapno = 14, err = 4, eip = 268480945, cs = 35, __csh = 0, eflags = 66118,
esp_at_signal = 1342630420, ss = 43, __ssh = 0, fpstate = 0x0, oldmask = 0,
cr2 = 1280}
</PRE>
</CODE></BLOCKQUOTE>
</P>
<P>The ip is in handle_mm_fault:
<BLOCKQUOTE><CODE>
<PRE>
(gdb) p (void *)268480945
$20 = (void *) 0x1000b1b1
(gdb) i sym $20
handle_mm_fault + 57 in section .text
</PRE>
</CODE></BLOCKQUOTE>
</P>
<P>Specifically, it's in pte_alloc:
<BLOCKQUOTE><CODE>
<PRE>
(gdb) i line *$20
Line 124 of "/home/dike/linux/2.3.26/um/include/asm/pgalloc.h"
starts at address 0x1000b1b1 <handle_mm_fault+57>
and ends at 0x1000b1b7 <handle_mm_fault+63>.
</PRE>
</CODE></BLOCKQUOTE>
</P>
<P>To find where in handle_mm_fault this is, I'll jump forward in the
code until I see an address in that procedure:</P>
<P>
<BLOCKQUOTE><CODE>
<PRE>
(gdb) i line *0x1000b1c0
Line 126 of "/home/dike/linux/2.3.26/um/include/asm/pgalloc.h"
starts at address 0x1000b1b7 <handle_mm_fault+63>
and ends at 0x1000b1c3 <handle_mm_fault+75>.
(gdb) i line *0x1000b1d0
Line 131 of "/home/dike/linux/2.3.26/um/include/asm/pgalloc.h"
starts at address 0x1000b1d0 <handle_mm_fault+88>
and ends at 0x1000b1da <handle_mm_fault+98>.
(gdb) i line *0x1000b1e0
Line 61 of "/home/dike/linux/2.3.26/um/include/asm/pgalloc.h"
starts at address 0x1000b1da <handle_mm_fault+98>
and ends at 0x1000b1e1 <handle_mm_fault+105>.
(gdb) i line *0x1000b1f0
Line 134 of "/home/dike/linux/2.3.26/um/include/asm/pgalloc.h"
starts at address 0x1000b1f0 <handle_mm_fault+120>
and ends at 0x1000b200 <handle_mm_fault+136>.
(gdb) i line *0x1000b200
Line 135 of "/home/dike/linux/2.3.26/um/include/asm/pgalloc.h"
starts at address 0x1000b200 <handle_mm_fault+136>
and ends at 0x1000b208 <handle_mm_fault+144>.
(gdb) i line *0x1000b210
Line 139 of "/home/dike/linux/2.3.26/um/include/asm/pgalloc.h"
starts at address 0x1000b210 <handle_mm_fault+152>
and ends at 0x1000b219 <handle_mm_fault+161>.
(gdb) i line *0x1000b220
Line 1168 of "memory.c" starts at address 0x1000b21e <handle_mm_fault+166>
and ends at 0x1000b222 <handle_mm_fault+170>.
</PRE>
</CODE></BLOCKQUOTE>
</P>
<P>Something is apparently wrong with the page tables or vma_structs,
so lets go back to frame 11 and have a look at them:
<BLOCKQUOTE><CODE>
<PRE>
#11 0x1006c0aa in segv (address=1342179328, is_write=2) at trap_kern.c:50
50 handle_mm_fault(current, vma, address, is_write);
(gdb) call pgd_offset_proc(vma->vm_mm, address)
$22 = (pgd_t *) 0x80a548c
</PRE>
</CODE></BLOCKQUOTE>
</P>
<P>That's pretty bogus. Page tables aren't supposed to be in process
text or data areas. Let's see what's in the vma:
<BLOCKQUOTE><CODE>
<PRE>
(gdb) p *vma
$23 = {vm_mm = 0x507d2434, vm_start = 0, vm_end = 134512640,
vm_next = 0x80a4f8c, vm_page_prot = {pgprot = 0}, vm_flags = 31200,
vm_avl_height = 2058, vm_avl_left = 0x80a8c94, vm_avl_right = 0x80d1000,
vm_next_share = 0xaffffdb0, vm_pprev_share = 0xaffffe63,
vm_ops = 0xaffffe7a, vm_pgoff = 2952789626, vm_file = 0xafffffec,
vm_private_data = 0x62}
(gdb) p *vma.vm_mm
$24 = {mmap = 0x507d2434, mmap_avl = 0x0, mmap_cache = 0x8048000,
pgd = 0x80a4f8c, mm_users = {counter = 0}, mm_count = {counter = 134904288},
map_count = 134909076, mmap_sem = {count = {counter = 135073792},
sleepers = -1342177872, wait = {lock = <optimized out or zero length>,
task_list = {next = 0xaffffe63, prev = 0xaffffe7a},
__magic = -1342177670, __creator = -1342177300}, __magic = 98},
page_table_lock = {}, context = 138, start_code = 0, end_code = 0,
start_data = 0, end_data = 0, start_brk = 0, brk = 0, start_stack = 0,
arg_start = 0, arg_end = 0, env_start = 0, env_end = 0, rss = 1350381536,
total_vm = 0, locked_vm = 0, def_flags = 0, cpu_vm_mask = 0, swap_cnt = 0,
swap_address = 0, segments = 0x0}
</PRE>
</CODE></BLOCKQUOTE>
</P>
<P>This also pretty bogus. With all of the 0x80xxxxx and 0xaffffxxx
addresses, this is looking like a stack was plonked down on top of
these structures. Maybe it's a stack overflow from the next page:</P>
<P>
<BLOCKQUOTE><CODE>
<PRE>
(gdb) p vma
$25 = (struct vm_area_struct *) 0x507d2434
</PRE>
</CODE></BLOCKQUOTE>
</P>
<P>That's towards the lower quarter of the page, so that would have to
have been pretty heavy stack overflow:</P>
<P>
<BLOCKQUOTE><CODE>
<PRE>
(gdb) x/100x $25
0x507d2434: 0x507d2434 0x00000000 0x08048000 0x080a4f8c
0x507d2444: 0x00000000 0x080a79e0 0x080a8c94 0x080d1000
0x507d2454: 0xaffffdb0 0xaffffe63 0xaffffe7a 0xaffffe7a
0x507d2464: 0xafffffec 0x00000062 0x0000008a 0x00000000
0x507d2474: 0x00000000 0x00000000 0x00000000 0x00000000
0x507d2484: 0x00000000 0x00000000 0x00000000 0x00000000
0x507d2494: 0x00000000 0x00000000 0x507d2fe0 0x00000000
0x507d24a4: 0x00000000 0x00000000 0x00000000 0x00000000
0x507d24b4: 0x00000000 0x00000000 0x00000000 0x00000000
0x507d24c4: 0x00000000 0x00000000 0x00000000 0x00000000
0x507d24d4: 0x00000000 0x00000000 0x00000000 0x00000000
0x507d24e4: 0x00000000 0x00000000 0x00000000 0x00000000
0x507d24f4: 0x00000000 0x00000000 0x00000000 0x00000000
0x507d2504: 0x00000000 0x00000000 0x00000000 0x00000000
0x507d2514: 0x00000000 0x00000000 0x00000000 0x00000000
0x507d2524: 0x00000000 0x00000000 0x00000000 0x00000000
0x507d2534: 0x00000000 0x00000000 0x507d25dc 0x00000000
0x507d2544: 0x00000000 0x00000000 0x00000000 0x00000000
0x507d2554: 0x00000000 0x00000000 0x00000000 0x00000000
0x507d2564: 0x00000000 0x00000000 0x00000000 0x00000000
0x507d2574: 0x00000000 0x00000000 0x00000000 0x00000000
0x507d2584: 0x00000000 0x00000000 0x00000000 0x00000000
0x507d2594: 0x00000000 0x00000000 0x00000000 0x00000000
0x507d25a4: 0x00000000 0x00000000 0x00000000 0x00000000
0x507d25b4: 0x00000000 0x00000000 0x00000000 0x00000000
</PRE>
</CODE></BLOCKQUOTE>
</P>
<P>It's not stack overflow. The only "stack-like" piece of this data
is the vma_struct itself.</P>
<P>At this point, I don't see any avenues to pursue, so I just have to
admit that I have no idea what's going on. What I will do, though, is
stick a trap on the segfault handler which will stop if it sees any
writes to the idle thread's stack. That was the thing that happened
first, and it may be that if I can catch it immediately, what's going
on will be somewhat clearer.</P>
<H2><A NAME="ss12.2">12.2</A> <A HREF="UserModeLinux-HOWTO.html#toc12.2">Episode 2: The case of the hung fsck</A>
</H2>
<P>After setting a trap in the SEGV handler for accesses to the signal
thread's stack, I reran the kernel.</P>
<P>fsck hung again, this time by hitting the trap:</P>
<P>
<BLOCKQUOTE><CODE>
<PRE>
Setting hostname uml [ OK ]
Checking root filesystem
/dev/fhd0 contains a file system with errors, check forced.
Error reading block 86894 (Attempt to read block from filesystem resulted in short read) while reading indirect blocks of inode 19780.
/dev/fhd0: UNEXPECTED INCONSISTENCY; RUN fsck MANUALLY.
(i.e., without -a or -p options)
[ FAILED ]
*** An error occurred during the file system check.
*** Dropping you to a shell; the system will reboot
*** when you leave the shell.
Give root password for maintenance
(or type Control-D for normal startup):
[root@uml /root]# fsck -y /dev/fhd0
fsck -y /dev/fhd0
Parallelizing fsck version 1.14 (9-Jan-1999)
e2fsck 1.14, 9-Jan-1999 for EXT2 FS 0.5b, 95/08/09
/dev/fhd0 contains a file system with errors, check forced.
Pass 1: Checking inodes, blocks, and sizes
Error reading block 86894 (Attempt to read block from filesystem resulted in short read) while reading indirect blocks of inode 19780. Ignore error? yes
Pass 2: Checking directory structure
Error reading block 49405 (Attempt to read block from filesystem resulted in short read). Ignore error? yes
Directory inode 11858, block 0, offset 0: directory corrupted
Salvage? yes
Missing '.' in directory inode 11858.
Fix? yes
Missing '..' in directory inode 11858.
Fix? yes
Untested (4127) [100fe44c]: trap_kern.c line 31
</PRE>
</CODE></BLOCKQUOTE>
</P>
<P>I need to get the signal thread to detach from pid 4127 so that I can
attach to it with gdb. This is done by sending it a SIGUSR1, which is
caught by the signal thread, which detaches the process:
<BLOCKQUOTE><CODE>
<PRE>
kill -USR1 4127
</PRE>
</CODE></BLOCKQUOTE>
</P>
<P>Now I can run gdb on it:
<BLOCKQUOTE><CODE>
<PRE>
~/linux/2.3.26/um 1034: gdb linux
GNU gdb 4.17.0.11 with Linux support
Copyright 1998 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-redhat-linux"...
(gdb) att 4127
Attaching to program `/home/dike/linux/2.3.26/um/linux', Pid 4127
0x10075891 in __libc_nanosleep ()
</PRE>
</CODE></BLOCKQUOTE>
</P>
<P>The backtrace shows that it was in a write and that the fault
address (address in frame 3) is 0x50000800, which is right in the
middle of the signal thread's stack page:
<BLOCKQUOTE><CODE>
<PRE>
(gdb) bt
#0 0x10075891 in __libc_nanosleep ()
#1 0x1007584d in __sleep (seconds=1000000)
at ../sysdeps/unix/sysv/linux/sleep.c:78
#2 0x1006ce9a in stop () at user_util.c:191
#3 0x1006bf88 in segv (address=1342179328, is_write=2) at trap_kern.c:31
#4 0x1006c628 in segv_handler (sc=0x5006eaf8) at trap_user.c:174
#5 0x1006c63c in kern_segv_handler (sig=11) at trap_user.c:182
#6 <signal handler called>
#7 0xc0fd in ?? ()
#8 0x10016647 in sys_write (fd=3, buf=0x80b8800 "R.", count=1024)
at read_write.c:159
#9 0x1006d603 in execute_syscall (syscall=4, args=0x5006ef08)
at syscall_kern.c:254
#10 0x1006af87 in really_do_syscall (sig=12) at syscall_user.c:35
#11 <signal handler called>
#12 0x400dc8b0 in ?? ()
#13 <signal handler called>
#14 0x400dc8b0 in ?? ()
#15 0x80545fd in ?? ()
#16 0x804daae in ?? ()
#17 0x8054334 in ?? ()
#18 0x804d23e in ?? ()
#19 0x8049632 in ?? ()
#20 0x80491d2 in ?? ()
#21 0x80596b5 in ?? ()
(gdb) p (void *)1342179328
$3 = (void *) 0x50000800
</PRE>
</CODE></BLOCKQUOTE>
</P>
<P>Going up the stack to the segv_handler frame and looking at where
in the code the access happened shows that it happened near line 110
of block_dev.c:
<BLOCKQUOTE><CODE>
<PRE>
(gdb) up
#1 0x1007584d in __sleep (seconds=1000000)
at ../sysdeps/unix/sysv/linux/sleep.c:78
../sysdeps/unix/sysv/linux/sleep.c:78: No such file or directory.
(gdb)
#2 0x1006ce9a in stop () at user_util.c:191
191 while(1) sleep(1000000);
(gdb)
#3 0x1006bf88 in segv (address=1342179328, is_write=2) at trap_kern.c:31
31 KERN_UNTESTED();
(gdb)
#4 0x1006c628 in segv_handler (sc=0x5006eaf8) at trap_user.c:174
174 segv(sc->cr2, sc->err & 2);
(gdb) p *sc
$1 = {gs = 0, __gsh = 0, fs = 0, __fsh = 0, es = 43, __esh = 0, ds = 43,
__dsh = 0, edi = 1342179328, esi = 134973440, ebp = 1342631484,
esp = 1342630864, ebx = 256, edx = 0, ecx = 256, eax = 1024, trapno = 14,
err = 6, eip = 268550834, cs = 35, __csh = 0, eflags = 66070,
esp_at_signal = 1342630864, ss = 43, __ssh = 0, fpstate = 0x0, oldmask = 0,
cr2 = 1342179328}
(gdb) p (void *)268550834
$2 = (void *) 0x1001c2b2
(gdb) i sym $2
block_write + 1090 in section .text
(gdb) i line *$2
Line 209 of "/home/dike/linux/2.3.26/um/include/asm/arch/string.h"
starts at address 0x1001c2a1 <block_write+1073>
and ends at 0x1001c2bf <block_write+1103>.
(gdb) i line *0x1001c2c0
Line 110 of "block_dev.c" starts at address 0x1001c2bf <block_write+1103>
and ends at 0x1001c2e3 <block_write+1139>.
</PRE>
</CODE></BLOCKQUOTE>
</P>
<P>Looking at the source shows that the fault happened during a
call to copy_to_user to copy the data into the kernel:
<BLOCKQUOTE><CODE>
<PRE>
107 count -= chars;
108 copy_from_user(p,buf,chars);
109 p += chars;
110 buf += chars;
</PRE>
</CODE></BLOCKQUOTE>
</P>
<P>p is the pointer which must contain 0x50000800, since buf contains
0x80b8800 (frame 8 above). It is defined as:
<BLOCKQUOTE><CODE>
<PRE>
p = offset + bh->b_data;
</PRE>
</CODE></BLOCKQUOTE>
</P>
<P>I need to figure out what bh is, and it just so happens that bh is
passed as an argument to mark_buffer_uptodate and mark_buffer_dirty a
few lines later, so I do a little disassembly:</P>
<P>
<BLOCKQUOTE><CODE>
<PRE>
(gdb) disas 0x1001c2bf 0x1001c2e0
Dump of assembler code from 0x1001c2bf to 0x1001c2d0:
0x1001c2bf <block_write+1103>: addl %eax,0xc(%ebp)
0x1001c2c2 <block_write+1106>: movl 0xfffffdd4(%ebp),%edx
0x1001c2c8 <block_write+1112>: btsl $0x0,0x18(%edx)
0x1001c2cd <block_write+1117>: btsl $0x1,0x18(%edx)
0x1001c2d2 <block_write+1122>: sbbl %ecx,%ecx
0x1001c2d4 <block_write+1124>: testl %ecx,%ecx
0x1001c2d6 <block_write+1126>: jne 0x1001c2e3 <block_write+1139>
0x1001c2d8 <block_write+1128>: pushl $0x0
0x1001c2da <block_write+1130>: pushl %edx
0x1001c2db <block_write+1131>: call 0x1001819c <__mark_buffer_dirty>
End of assembler dump.
</PRE>
</CODE></BLOCKQUOTE>
</P>
<P>At that point, bh is in %edx (address 0x1001c2da), which is
calculated at 0x1001c2c2 as %ebp + 0xfffffdd4, so I figure exactly
what that is, taking %ebp from the sigcontext_struct above:
<BLOCKQUOTE><CODE>
<PRE>
(gdb) p (void *)1342631484
$5 = (void *) 0x5006ee3c
(gdb) p 0x5006ee3c+0xfffffdd4
$6 = 1342630928
(gdb) p (void *)$6
$7 = (void *) 0x5006ec10
(gdb) p *((void **)$7)
$8 = (void *) 0x50100200
</PRE>
</CODE></BLOCKQUOTE>
</P>
<P>Now, I look at the structure to see what's in it, and particularly,
what its b_data field contains:
<BLOCKQUOTE><CODE>
<PRE>
(gdb) p *((struct buffer_head *)0x50100200)
$13 = {b_next = 0x50289380, b_blocknr = 49405, b_size = 1024, b_list = 0,
b_dev = 15872, b_count = {counter = 1}, b_rdev = 15872, b_state = 24,
b_flushtime = 0, b_next_free = 0x501001a0, b_prev_free = 0x50100260,
b_this_page = 0x501001a0, b_reqnext = 0x0, b_pprev = 0x507fcf58,
b_data = 0x50000800 "", b_page = 0x50004000,
b_end_io = 0x10017f60 <end_buffer_io_sync>, b_dev_id = 0x0,
b_rsector = 98810, b_wait = {lock = <optimized out or zero length>,
task_list = {next = 0x50100248, prev = 0x50100248}, __magic = 1343226448,
__creator = 0}, b_kiobuf = 0x0}
</PRE>
</CODE></BLOCKQUOTE>
</P>
<P>The b_data field is indeed 0x50000800, so the question becomes how
that happened. The rest of the structure looks fine, so this probably is
not a case of data corruption. It happened on purpose somehow.</P>
<P>The b_page field is a pointer to the page_struct representing the
0x50000000 page. Looking at it shows the kernel's idea of the state
of that page:</P>
<P>
<BLOCKQUOTE><CODE>
<PRE>
(gdb) p *$13.b_page
$17 = {list = {next = 0x50004a5c, prev = 0x100c5174}, mapping = 0x0,
index = 0, next_hash = 0x0, count = {counter = 1}, flags = 132, lru = {
next = 0x50008460, prev = 0x50019350}, wait = {
lock = <optimized out or zero length>, task_list = {next = 0x50004024,
prev = 0x50004024}, __magic = 1342193708, __creator = 0},
pprev_hash = 0x0, buffers = 0x501002c0, virtual = 1342177280,
zone = 0x100c5160}
</PRE>
</CODE></BLOCKQUOTE>
</P>
<P>Some sanity-checking: the virtual field shows the "virtual" address
of this page, which in this kernel is the same as its "physical"
address, and the page_struct itself should be mem_map[0], since it
represents the first page of memory:</P>
<P>
<BLOCKQUOTE><CODE>
<PRE>
(gdb) p (void *)1342177280
$18 = (void *) 0x50000000
(gdb) p mem_map
$19 = (mem_map_t *) 0x50004000
</PRE>
</CODE></BLOCKQUOTE>
</P>
<P>These check out fine.</P>
<P>Now to check out the page_struct itself. In particular, the flags
field shows whether the page is considered free or not:
<BLOCKQUOTE><CODE>
<PRE>
(gdb) p (void *)132
$21 = (void *) 0x84
</PRE>
</CODE></BLOCKQUOTE>
</P>
<P>The "reserved" bit is the high bit, which is definitely not set, so
the kernel considers the signal stack page to be free and available to
be used.</P>
<P>At this point, I jump to conclusions and start looking at my early
boot code, because that's where that page is supposed to be reserved.</P>
<P>In my setup_arch procedure, I have the following code which looks
just fine:</P>
<P>
<BLOCKQUOTE><CODE>
<PRE>
bootmap_size = init_bootmem(start_pfn, end_pfn - start_pfn);
free_bootmem(__pa(low_physmem) + bootmap_size, high_physmem - low_physmem);
</PRE>
</CODE></BLOCKQUOTE>
</P>
<P>Two stack pages have already been allocated, and low_physmem points
to the third page, which is the beginning of free memory.</P>
<P>The init_bootmem call declares the entire memory to the boot memory
manager, which marks it all reserved. The free_bootmem call frees up
all of it, except for the first two pages. This looks correct to me.</P>
<P>So, I decide to see init_bootmem run and make sure that it is
marking those first two pages as reserved. I never get that far.</P>
<P>Stepping into init_bootmem, and looking at bootmem_map before
looking at what it contains shows the following:</P>
<P>
<BLOCKQUOTE><CODE>
<PRE>
(gdb) p bootmem_map
$3 = (void *) 0x50000000
</PRE>
</CODE></BLOCKQUOTE>
</P>
<P>Aha! The light dawns. That first page is doing double duty as a
stack and as the boot memory map. The last thing that the boot memory
manager does is to free the pages used by its memory map, so this page is
getting freed even its marked as reserved.</P>
<P>The fix was to initialize the boot memory manager before allocating
those two stack pages, and then allocate them through the boot memory
manager. After doing this, and fixing a couple of subsequent buglets,
the stack corruption problem disappeared.</P>
<HR>
<A HREF="UserModeLinux-HOWTO-13.html">Next</A>
<A HREF="UserModeLinux-HOWTO-11.html">Previous</A>
<A HREF="UserModeLinux-HOWTO.html#toc12">Contents</A>
</BODY>
</HTML>
|