Re: [xen-unstable test] 11946: regressions - FAIL

[Daniel De Graaf <dgdegra@tycho.nsa.gov>]

On 02/14/2012 05:44 AM, Ian Campbell wrote:
> On Mon, 2012-02-13 at 20:16 +0000, xen.org wrote:
>> flight 11946 xen-unstable real [real]
>> http://www.chiark.greenend.org.uk/~xensrcts/logs/11946/
>>
>> Regressions :-(
>>
>> Tests which did not succeed and are blocking,
>> including tests which could not be run:
>>  test-amd64-i386-xl-credit2    7 debian-install            fail REGR. vs. 11944
> 
> Host crash:
> http://www.chiark.greenend.org.uk/~xensrcts/logs/11946/test-amd64-i386-xl-credit2/serial-woodlouse.log
> 
> This is the debug Andrew Cooper added recently to track down the IRQ
> assertion we've been seeing, sadly it looks like the debug code tries to
> call xfree from interrupt context and therefore doesn't produce full
> output :-(
> 
> Or is 24675:d82a1e3d3c65 ("xsm: Add security label to IRQ debug output")
> at fault for adding the xfree in what may be an IRQ context? (are
> keyhandlers run in IRQ context?)

Keyhandlers are not run in IRQ context (or at least, the primary methods of
invoking them don't run there - serial keypress, xl debug-key). The placement
of the xsm call and xfree was to avoid a similar backtrace from attempting
allocation while holding the irq's spinlock.

> A skanky quick "fix" follows.
> 
>         Feb 13 17:17:29.777522 (XEN) *** IRQ BUG found ***
>         Feb 13 17:19:32.594539 (XEN) CPU0 -Testing vector 229 from bitmap 34,48,57,64,72,75,80,83,88,97,104-105,113,120-121,129,136,144,152,160,168,176,184,192,202
>         Feb 13 17:19:32.617515 (XEN) Guest interrupt information:
>         Feb 13 17:19:32.617536 (XEN)    IRQ:   0 affinity:001 vec:f0 type=IO-APIC-edge    status=00000000 mapped, unbound
>         Feb 13 17:19:32.617567 (XEN) Assertion '!in_irq()' failed at xmalloc_tlsf.c:607
>         Feb 13 17:19:32.626489 (XEN) ----[ Xen-4.2-unstable  x86_64  debug=y  Not tainted ]----
>         Feb 13 17:19:32.626512 (XEN) CPU:    0
>         Feb 13 17:19:32.626525 (XEN) RIP:    e008:[<ffff82c48012c842>] xfree+0x33/0x121
>         Feb 13 17:19:32.641496 (XEN) RFLAGS: 0000000000010002   CONTEXT: hypervisor
>         Feb 13 17:19:32.641519 (XEN) rax: ffff82c4802d0800   rbx: ffff8301a7e00080   rcx: 0000000000000000
>         Feb 13 17:19:32.650560 (XEN) rdx: 0000000000000000   rsi: 0000000000000083   rdi: 0000000000000000
>         Feb 13 17:19:32.665510 (XEN) rbp: ffff82c4802afd18   rsp: ffff82c4802afcf8   r8:  0000000000000004
>         Feb 13 17:19:32.665550 (XEN) r9:  0000000000000000   r10: 0000000000000006   r11: ffff82c480224aa0
>         Feb 13 17:19:32.673509 (XEN) r12: ffff8301a7e00580   r13: 0000000000000005   r14: ffff82c4802aff18
>         Feb 13 17:19:32.685503 (XEN) r15: 0000000000000000   cr0: 000000008005003b   cr4: 00000000000006f0
>         Feb 13 17:19:32.685537 (XEN) cr3: 00000001a7f54000   cr2: 00000000c4b4ee84
>         Feb 13 17:19:32.697505 (XEN) ds: 007b   es: 007b   fs: 00d8   gs: 0000   ss: 0000   cs: e008
>         Feb 13 17:19:32.697540 (XEN) Xen stack trace from rsp=ffff82c4802afcf8:
>         Feb 13 17:19:32.706513 (XEN)    ffff8301a7e00080 ffff8301a7e00580 0000000000000005 ffff82c4802aff18
>         Feb 13 17:19:32.721495 (XEN)    ffff82c4802afd88 ffff82c4801658ee ffff82c4802afd38 ffff82c48010098a
>         Feb 13 17:19:32.721531 (XEN)    00000400802afd68 0000000000000083 ffff8301a7e000a8 0000000000000000
>         Feb 13 17:19:32.729495 (XEN)    00000000fffffffa 00000000000000e5 ffff8301a7e00580 0000000000000005
>         Feb 13 17:19:32.738490 (XEN)    ffff82c4802aff18 ffff8301a7e005a8 ffff82c4802afe28 ffff82c480167781
>         Feb 13 17:19:32.738515 (XEN)    ffff8301a7ece000 ffff82c4802afde8 0000000000000000 ffff82c4802aff18
>         Feb 13 17:19:32.750497 (XEN)    ffff82c4802aff18 0000000000000002 ffff82c4802aff18 ffff82c4802fa060
>         Feb 13 17:19:32.762568 (XEN)    000000e500000000 ffff82c4802fa060 ffff82c4802afe08 ffff82c48017bd51
>         Feb 13 17:19:32.762596 (XEN)    ffff82c4802aff18 ffff82c4802aff18 ffff82c48025e380 ffff82c4802aff18
>         Feb 13 17:19:32.773513 (XEN)    00000000ffffffff 0000000000000002 00007d3b7fd501a7 ffff82c4801525d0
>         Feb 13 17:19:32.785503 (XEN)    0000000000000002 00000000ffffffff ffff82c4802aff18 ffff82c48025e380
>         Feb 13 17:19:32.785539 (XEN)    ffff82c4802afee0 ffff82c4802aff18 0000001863058413 00000000000c0000
>         Feb 13 17:19:32.794514 (XEN)    000000000e1ff99c 000000000000c701 ffff82c4802f9a90 0000000000000000
>         Feb 13 17:19:32.809503 (XEN)    0000000000000000 ffff8301a7f5dc80 0000000000000000 0000002000000000
>         Feb 13 17:19:32.809529 (XEN)    ffff82c4801581a9 000000000000e008 0000000000000246 ffff82c4802afee0
>         Feb 13 17:19:32.814513 (XEN)    0000000000000000 ffff82c4802aff10 ffff82c48015a647 0000000000000000
>         Feb 13 17:19:32.829506 (XEN)    ffff8300d7cfb000 ffff8300d7af9000 0000000000000000 ffff82c4802afd88
>         Feb 13 17:19:32.829549 (XEN)    0000000000000000 0000000000000000 0000000000000000 0000000000000000
>         Feb 13 17:19:32.841510 (XEN)    00000000dfc91f90 00000000deadbeef 0000000000000000 0000000000000000
>         Feb 13 17:19:32.853508 (XEN)    0000000000000000 0000000000000000 0000000000000000 00000000deadbeef
>         Feb 13 17:19:32.858496 (XEN) Xen call trace:
>         Feb 13 17:19:32.858518 (XEN)    [<ffff82c48012c842>] xfree+0x33/0x121
>         Feb 13 17:19:32.858547 (XEN)    [<ffff82c4801658ee>] dump_irqs+0x2a3/0x2ca
>         Feb 13 17:19:32.870500 (XEN)    [<ffff82c480167781>] smp_irq_move_cleanup_interrupt+0x303/0x37b
>         Feb 13 17:19:32.870554 (XEN)    [<ffff82c4801525d0>] irq_move_cleanup_interrupt+0x30/0x40
>         Feb 13 17:19:32.885510 (XEN)    [<ffff82c4801581a9>] default_idle+0x99/0x9e
>         Feb 13 17:19:32.885541 (XEN)    [<ffff82c48015a647>] idle_loop+0x6c/0x7c
>         Feb 13 17:19:32.897496 (XEN)    
>         Feb 13 17:19:32.897510 (XEN) 
>         Feb 13 17:19:32.897520 (XEN) ****************************************
>         Feb 13 17:19:32.897537 (XEN) Panic on CPU 0:
>         Feb 13 17:19:32.905499 (XEN) Assertion '!in_irq()' failed at xmalloc_tlsf.c:607
>         Feb 13 17:19:32.905522 (XEN) ****************************************
>         Feb 13 17:19:32.913488 (XEN) 
>         Feb 13 17:19:32.913506 (XEN) Reboot in five seconds...
> 
> # HG changeset patch
> # User Ian Campbell <ian.campbell@citrix.com>
> # Date 1329216241 0
> # Node ID 738424a5e5a5053c75cfbe64f6675b5d756daf1b
> # Parent  0ba87b95e80bae059fe70b4b117dcc409f2471ef
> xen: don't try to print IRQ SSID in IRQ debug from irq context.
> 
> It is not possible to call xfree() in that context.
> 
> Signed-off-by: Ian Campbell <ian.campbell@citrix.com>
> 
> diff -r 0ba87b95e80b -r 738424a5e5a5 xen/arch/x86/irq.c
> --- a/xen/arch/x86/irq.c	Mon Feb 13 17:26:08 2012 +0000
> +++ b/xen/arch/x86/irq.c	Tue Feb 14 10:44:01 2012 +0000
> @@ -2026,7 +2026,7 @@ static void dump_irqs(unsigned char key)
>          if ( !irq_desc_initialized(desc) || desc->handler == &no_irq_type )
>              continue;
>  
> -        ssid = xsm_show_irq_sid(irq);
> +        ssid = in_irq() ? NULL : xsm_show_irq_sid(irq);
>  
>          spin_lock_irqsave(&desc->lock, flags);
>  
> @@ -2073,7 +2073,8 @@ static void dump_irqs(unsigned char key)
>  
>          spin_unlock_irqrestore(&desc->lock, flags);
>  
> -        xfree(ssid);
> +        if ( ssid )
> +                xfree(ssid);
>      }
>  
>      dump_ioapic_irq_info();
> 
> 
>