Note: This is a long and extremely detailed account of an esoteric problem. You have been warned.
What is it like to debug a kernel panic? Well, it’s a technical
and intellectual challenge, and it’s also emotional, with the
frustration of not knowing what happened, the thrill of
feeling like you’ve got it licked, and the disappointment of seeing
the symptom reappear after your so-called "fix."
When I’ve done this in the past, the experience could be shared only with
my fellow employees, because typically the problem lay in
proprietary software. On a recent occasion,
though, I found a problem in FreeBSD 8.1-RELEASE; its source code
is public, so at last I can share one of these with a wider audience.
My colleagues and I were running a program, maytag.Rd, under gdb,
on FreeBSD virtual machines (VMs), and the kernel was
panicking frequently. This meant that all programs running in that VM
would stop working, and the VM would then have to
be restarted. This was particularly annoying when it happened after a long sequence
of operations to get the maytag into a certain state, because the
maytag couldn't be resumed; all the setup operations needed
repeating.
There was nothing special about the maytag;
it didn't run as superuser
or anything shady like that, so the frequent crashes were puzzling.
It did use SIGALRM, but that shouldn't be able to crash the kernel.
I kept hitting the panic, and asked my colleagues about their experience;
yes, they also
hit it frequently. Rather than continuing to put up with it, I decided to
take a run at solving it.
The first step in debugging this problem was getting a
dump of main memory. Our excellent support
staff created a VM instance for me with enough disk-backed "swap" to dump primary memory,
or "core," and I ran the program on that VM, under gdb.
After a short while, I was rewarded with a coredump. I then ran
the kernel debugger, kgdb:
NOTE: Material in the green boxes is taken verbatim from notes/updates in the software defect report.
% kgdb /boot/kernel/kernel.symbols /var/crash/vmcore.0
GNU gdb 6.1.1 [FreeBSD]
Copyright 2004 Free Software Foundation, Inc.
(…FSF license info elided…)
Unread portion of the kernel message buffer:
Fatal trap 12: page fault while in kernel mode
cpuid = 0; apic id = 00
fault virtual address = 0x1e
fault code = supervisor read data, page not present
instruction pointer = 0x20:0xffffffff805a83cf
stack pointer = 0x28:0xffffff8077025af0
frame pointer = 0x28:0xffffff8077025b40
code segment = base 0x0, limit 0xfffff, type 0x1b
= DPL 0, pres 1, long 1, def32 0, gran 1
processor eflags = interrupt enabled, resume, IOPL = 0
current process = 1418 (initial thread)
trap number = 12
panic: page fault
cpuid = 0
Uptime: 37m21s
Physical memory: 4081 MB
Dumping 1639 MB: 1624 1608 1592 1576 1560 1544 …you get the idea… 88 72 56 40 24 8
Reading symbols from /boot/modules/vmxnet.ko...done.
Loaded symbols for /boot/modules/vmxnet.ko
Reading symbols from /boot/modules/vmmemctl.ko...done.
Loaded symbols for /boot/modules/vmmemctl.ko
#0 doadump () at pcpu.h:223
223 pcpu.h: No such file or directory.
in pcpu.h
(kgdb) bt
#0 doadump () at pcpu.h:223
#1 0xffffffff805a4d29 in boot (howto=260)
at /usr/src/sys/kern/kern_shutdown.c:416
#2 0xffffffff805a515c in panic (fmt=0xffffffff80964764 "%s")
at /usr/src/sys/kern/kern_shutdown.c:590
#3 0xffffffff8088b928 in trap_fatal (frame=0xffffff0001e00000,
eva=Variable "eva" is not available.)
at /usr/src/sys/amd64/amd64/trap.c:777
#4 0xffffffff8088bcf4 in trap_pfault (frame=0xffffff8077025a40, usermode=0)
at /usr/src/sys/amd64/amd64/trap.c:693
#5 0xffffffff8088c53a in trap (frame=0xffffff8077025a40)
at /usr/src/sys/amd64/amd64/trap.c:451
#6 0xffffffff80871f03 in calltrap ()
at /usr/src/sys/amd64/amd64/exception.S:223
#7 0xffffffff805a83cf in sigqueue_get (sq=0xffffff0001e00080, signo=14,
si=0xffffff8077025b70) at /usr/src/sys/kern/kern_sig.c:295
#8 0xffffffff805a855f in postsig (sig=14) at /usr/src/sys/kern/kern_sig.c:2717
#9 0xffffffff805e2777 in ast (framep=0xffffff8077025c80)
at /usr/src/sys/kern/subr_trap.c:234
#10 0xffffffff80872ec9 in doreti_ast ()
at /usr/src/sys/amd64/amd64/exception.S:633
#11 0x0000000000000002 in ?? ()
…
(Frame 11 is certainly wrong, so I elided everything after it.)
I felt
pretty happy about this. I caught the system in the act of doing something
really stupid. Now if I could figure out how we got to this silly place,
there would be…well, if not fame and fortune exactly, at least some
panic-free runs for my colleagues and me.
(bt is the gdb command to do a "backtrace".
Here's what I mean by that: when some code calls a routine,
the called routine usually writes a "stack frame" into memory,
which has information about where the caller was, parameters, etc.
A backtrace is the output
that comes from tracing back through those frames. In other words,
find the routine that was running, and see what
routine called it, then see what routine called that, and
so on. The convention in gdb is that the current frame is
numbered zero; its caller is described in frame 1, and so on.)
We hit the trap while in frame 7, frame 6 being the trap marker.
By the way, everybody was hitting the same trap
("Fatal trap 12: page fault while in kernel mode") at the same place
(instruction pointer = 0x20:0xffffffff805a83cf).
It was nice to know that I'd hit the same panic on the
machine with the modified configuration.
What's happening in that instruction?
0xffffffff805a83b5 <sigqueue_get+85>: mov 0x20(%r15),%rsi
0xffffffff805a83b9 <sigqueue_get+89>: test %rsi,%rsi
0xffffffff805a83bc <sigqueue_get+92>: jne 0xffffffff805a83cf <sigqueue_get+111>
0xffffffff805a83be <sigqueue_get+94>: jmpq 0xffffffff805a848a <sigqueue_get+298>
0xffffffff805a83c3 <sigqueue_get+99>: test %r12,%r12
0xffffffff805a83c6 <sigqueue_get+102>: mov %r12,%rsi
0xffffffff805a83c9 <sigqueue_get+105>: je 0xffffffff805a848a <sigqueue_get+298>
0xffffffff805a83cf <sigqueue_get+111>: cmp %r13d,0x10(%rsi)
0xffffffff805a83d3 <sigqueue_get+115>: mov (%rsi),%rdx
0xffffffff805a83d6 <sigqueue_get+118>: mov %rdx,%r12
0xffffffff805a83d9 <sigqueue_get+121>: jne 0xffffffff805a83c3 <sigqueue_get+99>
0xffffffff805a83db <sigqueue_get+123>: test %r14d,%r14d
0xffffffff805a83de <sigqueue_get+126>: jne 0xffffffff805a8466 <sigqueue_get+262>
…
(kgdb) info reg
rax 0x0 0
rbx 0xffffff8077025b70 -547759170704
rcx 0xffffff0001e72860 -1099479701408
rdx 0xe 14
rsi 0xe 14
rdi 0xffffff00018542a0 -1099486117216
rbp 0xffffff8077025b40 0xffffff8077025b40
rsp 0xffffff8077025b00 0xffffff8077025b00
r8 0x0 0
r9 0x2000 8192
r10 0x0 0
r11 0x0 0
r12 0xe 14
r13 0xe 14
r14 0x1 1
r15 0xffffff0001e00080 -1099480170368
rip 0xffffffff805a83cf 0xffffffff805a83cf <sigqueue_get+111>
(Note: To get the list of assembly instructions above, I typed
"disass sigqueue_get"; "info reg" means "show me
the registers." Assembly instructions can be decrypted by looking
at a document downloadable from Intel. For those who aren't sure
about the direction of Intel instructions, gdb seems to print them with
"left-to-right" semantics—e.g.,
"mov %r12,%rsi" means
"copy the contents of %r12 into %rsi.")
So we seem to be comparing the contents of %r13d vs. the memory located at
(%rsi+0x10),
highlighted like this;
since %rsi has 0xe, we'd expect the faulting address to be 0x1e, as indeed it is
(search backward for "fault virtual address"). That's the smoking gun, and
it's always nice to see
that the machine is consistent with itself, even in crashes. That was
progress, but not nearly enough.
What are we doing there? The backtrace says we're at line 295:
(kgdb) f 7
#7 0xffffffff805a83cf in sigqueue_get (sq=0xffffff0001e00080, signo=14,
si=0xffffff8077025b70) at /usr/src/sys/kern/kern_sig.c:295
295 TAILQ_FOREACH_SAFE(ksi, &sq->sq_list, ksi_link, next) {
(kgdb) ptype sq->sq_list
type = struct {
struct ksiginfo *tqh_first;
struct ksiginfo **tqh_last;
}
(kgdb) x/2xg &sq->sq_list
0xffffff0001e000a0: 0xffffff8077025b80 0xffffff8077025b80
I thought this was weird, since
tqh_last is supposed to be pointer-to-pointer.
(Actually, my intuition was completely wrong about that; in this particular queue,
it's perfectly OK for them to have the same value.)
More to the point, though, this piece of memory doesn't look like a
struct ksiginfo:
(kgdb) x/16xg 0xffffff8077025b80
0xffffff8077025b80: 0x000000000000000e 0x0000000000010006
0xffffff8077025b90: 0x0000000000000000 0x0000000000000000
0xffffff8077025ba0: 0x0000000000000000 0x0000000000000000
0xffffff8077025bb0: 0x0000000000000000 0x0000000000000000
0xffffff8077025bc0: 0x0000000000000000 0x0000000000000000
0xffffff8077025bd0: 0x0000000000000000 0x0000000000000000
0xffffff8077025be0: 0x0000000000000010 0x0000000000000246
0xffffff8077025bf0: 0x0000000000002000 0x0000000000000000
(kgdb) p *sq->sq_list.tqh_first
$8 = {ksi_link = {tqe_next = 0xe, tqe_prev = 0x10006}, ksi_info = {
si_signo = 0, si_errno = 0, si_code = 0, si_pid = 0, si_uid = 0,
si_status = 0, si_addr = 0x0, si_value = {sival_int = 0, sival_ptr = 0x0,
sigval_int = 0, sigval_ptr = 0x0}, _reason = {_fault = {_trapno = 0},
_timer = {_timerid = 0, _overrun = 0}, _mesgq = {_mqd = 0}, _poll = {
_band = 0}, __spare__ = {__spare1__ = 0, __spare2__ = {0, 0, 0, 0, 0,
0, 0}}}}, ksi_flags = 16, ksi_sigq = 0x246}
(kgdb)
When I saw this, I was pretty unhappy. It looked like the whole
structure was trashed, not just one part of it. How was I going to
figure this out?
Clearly 0xffffff8077025b80 was a bad pointer, or perhaps
memory there got corrupted. I needed to see how we got into
this mess.
(kgdb) p count
$10 = 1
(kgdb) l sigqueue_get
278 static int
279 sigqueue_get(sigqueue_t *sq, int signo, ksiginfo_t *si)
280 {
281 struct proc *p = sq->sq_proc;
282 struct ksiginfo *ksi, *next;
283 int count = 0;
284
…
290 if (SIGISMEMBER(sq->sq_kill, signo)) {
291 count++;
292 SIGDELSET(sq->sq_kill, signo);
293 }
294
295 TAILQ_FOREACH_SAFE(ksi, &sq->sq_list, ksi_link, next) {
296 if (ksi->ksi_signo == signo) {
297 if (count == 0) {
298 TAILQ_REMOVE(&sq->sq_list, ksi, ksi_link);
299 ksi->ksi_sigq = NULL;
300 ksiginfo_copy(ksi, si);
301 if (ksiginfo_tryfree(ksi) && p != NULL)
302 p->p_pendingcnt--;
303 }
304 if (++count > 1)
305 break;
306 }
307 }
count=1 (assuming gdb is telling the truth) says that either:
1. we ran 291; or
2. we ran 297-303 once, removing an element from the queue;
then we bumped count in 304. That's how we panicked
2nd time around in 295.
I reject #1 because the queue is plainly not what it was when we entered.
Why did I think I knew this? Because if it had been, we would have panicked
the first time through, or so I thought. Was I right? I suppose so; some
hours later I was sure that we executed line 300.
Now when we entered, we had si==0xffffff8077025b70 I guess.
At that time we would have assigned ksi to... umm, that value?
(kgdb) p *si
$16 = {ksi_link = {tqe_next = 0x0, tqe_prev = 0x0}, ksi_info = {si_signo = 14,
si_errno = 0, si_code = 65542, si_pid = 0, si_uid = 0, si_status = 0,
si_addr = 0x0, si_value = {sival_int = 0, sival_ptr = 0x0, sigval_int = 0,
sigval_ptr = 0x0}, _reason = {_fault = {_trapno = 0}, _timer = {
_timerid = 0, _overrun = 0}, _mesgq = {_mqd = 0}, _poll = {_band = 0},
__spare__ = {__spare1__ = 0, __spare2__ = {0, 0, 0, 0, 0, 0, 0}}}},
ksi_flags = 0, ksi_sigq = 0x0}
Now THAT looks completely reasonable.
But somehow we ended up like this??
(kgdb) p sq->sq_list
$15 = {tqh_first = 0xffffff8077025b80, tqh_last = 0xffffff8077025b80}
At this point I was completely
stumped. I hadn't yet noticed that 0xffffff8077025b80 was exactly
si+0x10 (i.e., a location
inside *si), so I concocted
a bunch of theories about how
si->ksi_link.tqe_next
might have been 0xffffff8077025b80, etc.
The above came from a report filed at 12:46pm Monday; within eleven minutes, I had
looked at the caller, in frame 8 of the backtrace.
(kgdb) up
#8 0xffffffff805a855f in postsig (sig=14) at /usr/src/sys/kern/kern_sig.c:2717
2717 if (sigqueue_get(&td->td_sigqueue, sig, &ksi) == 0 &&
2700 int
2701 postsig(sig)
2702 register int sig;
2703 {
2704 struct thread *td = curthread;
2705 register struct proc *p = td->td_proc;
2706 struct sigacts *ps;
2707 sig_t action;
2708 ksiginfo_t ksi;
2709 sigset_t returnmask, mask;
2710
2711 KASSERT(sig != 0, ("postsig"));
2712
2713 PROC_LOCK_ASSERT(p, MA_OWNED);
2714 ps = p->p_sigacts;
2715 mtx_assert(&ps->ps_mtx, MA_OWNED);
2716 ksiginfo_init(&ksi);
2717 if (sigqueue_get(&td->td_sigqueue, sig, &ksi) == 0 &&
2718 sigqueue_get(&p->p_sigqueue, sig, &ksi) == 0)
2719 return (0);
"/usr/src/sys/kern/kern_sig.c" [readonly]
The thing I observed here was that
ksi was on-stack. It was, in fact, at
the address noted earlier (0xffffff8077025b70). Somebody must have added
an on-stack element some time earlier, I thought. But I was at a loss as to
how that could have happened.
It would be another two hours before I noticed this; at 2:56pm I updated the report:
340 static int
341 sigqueue_add(sigqueue_t *sq, int signo, ksiginfo_t *si)
342 {
…
354 /* directly insert the ksi, don't copy it */
355 if (si->ksi_flags & KSI_INS) {
356 if (si->ksi_flags & KSI_HEAD)
357 TAILQ_INSERT_HEAD(&sq->sq_list, si, ksi_link);
358 else
359 TAILQ_INSERT_TAIL(&sq->sq_list, si, ksi_link);
360 si->ksi_sigq = sq;
361 goto out_set_bit;
362 }
The key thing here is that we would insert the element only if
KSI_INS is set in
ksi_flags. I suspected at this
time that
KSI_INS might have been set erroneously. Quoting
from the report:
sigqueue_add() is called by tdsignal() and issignal().
Sure enough, issignal() has an on-stack ksi whose flags are not initialized.
2490 static int
2491 issignal(struct thread *td, int stop_allowed)
2492 {
2493 struct proc *p;
2494 struct sigacts *ps;
2495 struct sigqueue *queue;
2496 sigset_t sigpending;
2497 ksiginfo_t ksi;
...
2570 if (ksi.ksi_signo != 0) {
2571 ksi.ksi_flags |= KSI_HEAD;
2572 if (sigqueue_add(&td->td_sigqueue, sig,
2573 &ksi) != 0)
2574 ksi.ksi_signo = 0;
2575 }
2576 if (ksi.ksi_signo == 0)
2577 sigqueue_add(&td->td_sigqueue, sig,
2578 NULL);
Nothing modifies ksi.ksi_flags between 2497 and 2570. That's an invitation
to disaster, because whatever random value happens to be in ksi_flags
is the value that will be interpreted by the callee. In particular,
though line 2570 sets the
KSI_HEAD bit, we have no idea
whether any other bit is set.
Half an hour later, I decided that was wrong—at 3:25pm I posted this:
NEVERMIND --- if we get to 2572 it means ksi_signo is nonzero,
which means we must have done 2541 and maybe 2543:
2540 ksi.ksi_signo = 0;
2541 if (sigqueue_get(queue, sig, &ksi) == 0) {
2542 queue = &p->p_sigqueue;
2543 sigqueue_get(queue, sig, &ksi);
2544 }
sigqueue_get() always zaps the flags (killing KSI_INS) if setting
ksi_signo.
static __inline void
ksiginfo_copy(ksiginfo_t *src, ksiginfo_t *dst)
{
(dst)->ksi_info = src->ksi_info;
(dst)->ksi_flags = (src->ksi_flags & KSI_COPYMASK);
}
Another 90 minutes later, about 5:00pm, I decided I was wrong yet again:
Dang, that's not quite true. sigqueue_get() can update ksi_signo
without updating ksi_flags.
I think if one does a sigqueue_add(sq, SIGALRM, NULL);
then we'll SIGADDSET(sq->sq_kill, SIGALRM) then
SIGADDSET(sq->sq_signals, SIGALRM) then return 0.
Much as I'd like to tell you that the process is orderly and methodical,
proceeding from what's known to what's unknown through a sequence of
logical steps, the truth is that it usually starts with some
observations, followed by some hypotheses. The hypotheses are
investigated, but at various points, important details
go unnoticed; tentative conclusions are then reversed, and so on.
So it was in this case.
My 5pm update continued:
Now the maytag.Rd process is traced, which means we could enter this part of
issignal():
2505 int traced = (p->p_flag & P_TRACED) || (p->p_stops & S_SIG);
...
2532 if (p->p_flag & P_TRACED && (p->p_flag & P_PPWAIT) == 0) {
2533 /*
2534 * If traced, always stop.
2535 * Remove old signal from queue before the stop.
2536 * XXX shrug off debugger, it causes siginfo to
2537 * be thrown away.
2538 */
2539 queue = &td->td_sigqueue;
2540 ksi.ksi_signo = 0;
2541 if (sigqueue_get(queue, sig, &ksi) == 0) {
2542 queue = &p->p_sigqueue;
2543 sigqueue_get(queue, sig, &ksi);
2544 }
...
2565 sigqueue_add(queue, sig, NULL);
2566 if (SIGISMEMBER(td->td_sigmask, sig))
2567 continue;
2568 signotify(td);
The sigqueue_get() might not find anything in
the queue, but just find the bit set.
(kgdb) p/x p->p_flag
$2 = 0x10004882
566 #define P_CONTROLT 0x00002 /* Has a controlling terminal. */
572 #define P_HADTHREADS 0x00080 /* Has had threads (no cleanup shortcuts) */
576 #define P_TRACED 0x00800 /* Debugged process being traced. */
579 #define P_EXEC 0x04000 /* Process called exec. */
593 #define P_INMEM 0x10000000 /* Loaded into memory. */
What that last part means is that sure enough, P_TRACED is set but P_PPWAIT is clear, so
we likely did enter the block starting at 2539.
At this point, i.e., at 5pm Monday, I had only a rough idea of how everything
happened, but I felt quite sure that the bad code in issignal() (that is,
random bits in ksi->ksi_flags) had something to do with it. It was
easy enough to create a kernel modified as follows:
2540 ksi.ksi_signo = 0;
2540 ksiginfo_init(&ksi);
I ran some experiments and proved that this change made the symptom go away.
So here's where I was at that point:
- I'd found some code that was definitely bad;
- I had a plausible explanation, albeit
an incomplete one, for how that bad code might have resulted in an on-stack
ksiginfo_t to be added to the current thread's queue (and thus
caused the panic);
- I had devised a fix and tried it. The symptom, which I formerly
could reproduce at will,
disappeared convincingly after the aforementioned bad
code was corrected.
In other words, I was done.
Looking at all of this today, though,
over 1½ years later, I was somewhat more anxious to work out a
more complete explanation of the original problem. Here's today's shot at it:
The problem happens because issignal() erroneously
adds an on-stack structure to a thread's td_sigqueue, then
returns. Shortly afterward, postsig() is called, which
called sigqueue_get();
the latter routine copied one siginfo_t into postsig()'s
local variable, corrupting the bogus siginfo_t enqueued by
issignal(). In particular, ksi_link.tqe_next was
corrupted, causing a queue-scanning loop to dereference an invalid
pointer and panicking the box. Specifically:
- ast() calls cursig() (which in turn calls
issignal()), then postsig(), in rapid succession:
229 if (flags & TDF_NEEDSIGCHK || p->p_pendingcnt > 0 ||
230 !SIGISEMPTY(p->p_siglist)) {
231 PROC_LOCK(p);
232 mtx_lock(&p->p_sigacts->ps_mtx);
233 while ((sig = cursig(td, SIG_STOP_ALLOWED)) != 0)
234 postsig(sig);
235 mtx_unlock(&p->p_sigacts->ps_mtx);
236 PROC_UNLOCK(p);
237 }
- issignal() calls sigqueue_get(), passing its ksi struct with its
uninitialized (random) flags. The KSI_INS flag happens to be unintentionally set to 1.
Now, sigqueue_get() may set si->ksi_signo (parameter si, i.e.,
issignal()'s local variable ksi), without touching anything else in the
struct—that is, leaving ksi.ksi_flags with random bits set.
Which signal was it? I'm not sure. I was going to say something other than
SIGALRM (maybe SIGTRAP?) but I didn't look that far because I was hot
on the trail—or so I hoped!
- The trap (sorry) is now set: we have ksi.ksi_signo nonzero.
By the way, I believe sq->sq_list had one other element on it, an element
whose address we no longer have. Probably that element was the SIGALRM (14 or 0xe).
Now we execute 2570-2573 in issignal():
2550 if (sig != newsig) {
...
2569 } else {
2570 if (ksi.ksi_signo != 0) {
2571 ksi.ksi_flags |= KSI_HEAD;
2572 if (sigqueue_add(&td->td_sigqueue, sig,
2573 &ksi) != 0)
2574 ksi.ksi_signo = 0;
2575 }
Now sigqueue_add() will oblige us by... well, you can see it:
340 static int
341 sigqueue_add(sigqueue_t *sq, int signo, ksiginfo_t *si)
342 {
...
354 /* directly insert the ksi, don't copy it */
355 if (si->ksi_flags & KSI_INS) {
356 if (si->ksi_flags & KSI_HEAD)
357 TAILQ_INSERT_HEAD(&sq->sq_list, si, ksi_link);
358 else
359 TAILQ_INSERT_TAIL(&sq->sq_list, si, ksi_link);
360 si->ksi_sigq = sq;
In particular, ksi (the local variable of issignal()) could
very well have been at 0xffffff8077025b80.
- As noted in step 1 above, ast() soon calls postsig(14);
which in turn calls sigqueue_get(&td->td_sigqueue, sig, &ksi),
where ksi was located at 0xffffff8077025b70.
sigqueue_get() I guess did the following:
- examined sq->sq_kill (line 290) and concluded we
didn't have a match; thus skipped 291;
- at 295–296, found the first element, which matched;
- with count==0, executed 298 to remove this
element from the list, and crucially 300,
copying the contents of the mystery element into the
struct pointed to by (parameter) si;
in doing this, we overwrote whatever had been
at 0xffffff8077025b80
290 if (SIGISMEMBER(sq->sq_kill, signo)) {
291 count++;
292 SIGDELSET(sq->sq_kill, signo);
293 }
294
295 TAILQ_FOREACH_SAFE(ksi, &sq->sq_list, ksi_link, next) {
296 if (ksi->ksi_signo == signo) {
297 if (count == 0) {
298 TAILQ_REMOVE(&sq->sq_list, ksi, ksi_link);
299 ksi->ksi_sigq = NULL;
300 ksiginfo_copy(ksi, si);
301 if (ksiginfo_tryfree(ksi) && p != NULL)
302 p->p_pendingcnt--;
303 }
304 if (++count > 1)
305 break;
306 }
307 }
- We continued to 304 and incremented count, then looped
around to returned to 295 in sigqueue_get().
- Still in sigqueue_get(), we went to the next element in
the queue (which we knew from before was 0xffffff8077025b80) and
repeated the test of line 296. This failed because si_signo
didn't match:
$8 = {ksi_link = {tqe_next = 0xe, tqe_prev = 0x10006}, ksi_info = {
si_signo = 0, si_errno = 0, si_code = 0, si_pid = 0, si_uid = 0,
si_status = 0, si_addr = 0x0, si_value = {sival_int = 0, sival_ptr = 0x0,
sigval_int = 0, sigval_ptr = 0x0}, _reason = {_fault = {_trapno = 0},
_timer = {_timerid = 0, _overrun = 0}, _mesgq = {_mqd = 0}, _poll = {
_band = 0}, __spare__ = {__spare1__ = 0, __spare2__ = {0, 0, 0, 0, 0,
0, 0}}}}, ksi_flags = 16, ksi_sigq = 0x246}
so we went to the next element in the queue.
- But of course, ksi_link.tqe_next has been corrupted, and
so when we try to load ksi->ksi_signo, we get the
segfault.
One thing remains unexplained: In
issignal(), we have
to execute 2572–2573 I think, so that
sigqueue_add()
gets called with the address of (local variable)
ksi.
However, to get there, we must have executed 2571, which would force
the new element (the one I think was incorrectly inserted) to be
inserted at the
head of the queue (
sigqueue_add()
lines 356–357 above).
Perhaps the bad element was inserted some time ago, and
we're only now corrupting the queue? Or we did two of them,
one after another, with the good one... second?
I'm not quite sure, but I think we've gotten a little further
than I had in 2012. Has this been debugged enough? Well, in one sense it
was debugged enough in 2012: I saw bad code, I had a plausible
if incomplete explanation of how it could have caused the symptom,
and so on. If I had to stand in front of a classroom and explain
that this is absolutely what happened, I couldn't give a complete
explanation.
We could go further—for example, we could look at the stack frame
sizes and local variable layouts for issignal() and sigqueue_get() to see
if they're consistent with the idea
that ksi in one routine could be 0x10 bytes from ksi in
the other. But I think you've got the idea, and this post is too long already.
