search

rcore-os / zCore

Zircon microkernel reimplemented in Rust.
MIT License
1.72k stars 210 forks source link

panicked at 'attempt to add with overflow' #56

Closed benpigchu closed 4 years ago

benpigchu commented 4 years ago

Call to sys_pci_init may panick due to overflow adding u8

UEFI Interactive Shell v2.2
EDK II
UEFI v2.70 (EDK II, 0x00010000)
Mapping table
      FS0: Alias(s):HD0a65535a1:;BLK1:
          PciRoot(0x0)/Pci(0x1F,0x2)/Sata(0x0,0xFFFF,0x0)/HD(1,MBR,0xBE1AFDFA,0x3F,0xFBFC1)
     BLK2: Alias(s):
          PciRoot(0x0)/Pci(0x2,0x0)/Sata(0x0,0xFFFF,0x0)
     BLK0: Alias(s):
          PciRoot(0x0)/Pci(0x1F,0x2)/Sata(0x0,0xFFFF,0x0)
Press ESC in 1 seconds to skip startup.nsh or any other key to continue.
Shell> \EFI\boot\bootx64.efi
INFO: bootloader is running
INFO: opening file: \EFI\Boot\rboot.conf
INFO: loading file to memory
INFO: switching graphic mode
INFO: config: Config {
INFO:     kernel_stack_address: 0xffffff0100000000,
INFO:     kernel_stack_size: 0x200,
INFO:     physical_memory_offset: 0xffff800000000000,
INFO:     kernel_path: "\\EFI\\zCore\\zcore.elf",
INFO:     resolution: Some(
INFO:         (
INFO:             0x400,
INFO:             0x300,
INFO:         ),
INFO:     ),
INFO:     initramfs: Some(
INFO:         "\\EFI\\zCore\\fuchsia.zbi",
INFO:     ),
INFO:     cmdline: "LOG=error",
INFO: }
INFO: acpi2: 0x7fbfa014
INFO: smbios: 0x7fbcc000
INFO: opening file: \EFI\zCore\zcore.elf
INFO: loading file to memory
INFO: opening file: \EFI\zCore\fuchsia.zbi
INFO: loading file to memory
INFO: mapping ELF
INFO: mapping stack at 0xffffff0100000000
INFO: mapping physical memory
INFO: exit boot services
userboot: option "LOG=error"
userboot: option "console.shell=true"
userboot: decompressed BOOTFS to VMO!
userboot: searching bootfs for 'bin/bootsvc'
userboot: 'bin/bootsvc' has PT_INTERP "lib/ld.so.1"
userboot: searching bootfs for 'lib/ld.so.1'
userboot: userboot: loaded lib/ld.so.1 at 0x28200000000, entry point 0x282000575cc
userboot: userboot: loaded vDSO at 0x282000ad000, entry point 0x282000b4e1a
userboot: process bin/bootsvc started.
userboot: waiting for loader-service requests...
userboot: searching bootfs for 'lib/liblaunchpad.so'
userboot: searching bootfs for 'lib/libfdio.so'
userboot: searching bootfs for 'lib/libtrace-engine.so'
userboot: searching bootfs for 'lib/libasync-default.so'
userboot: searching bootfs for 'lib/libmemfs.so'
userboot: searching bootfs for 'lib/libc++.so.2'
userboot: searching bootfs for 'lib/libc++abi.so.1'
userboot: searching bootfs for 'lib/libunwind.so.1'
{{{reset}}}
{{{module:0:<application>:elf:dbd5f97ed489b42b}}}
{{{mmap:0x20200000000:0x30000:load:0:r:0}}}
{{{mmap:0x20200030000:0xfd000:load:0:rx:0x30000}}}
{{{mmap:0x2020012d000:0xf000:load:0:rw:0x12d000}}}
{{{mmap:0x2020013c000:0x1000:load:0:rw:0x13c000}}}
dso: id=dbd5f97ed489b42b base=0x0000020200000000 name=<application>
{{{module:0x3:liblaunchpad.so:elf:b76f0d8110442057}}}
{{{mmap:0x282000f6000:0x3000:load:0x3:r:0}}}
{{{mmap:0x282000f9000:0x4000:load:0x3:rx:0x3000}}}
{{{mmap:0x282000fd000:0x1000:load:0x3:rw:0x7000}}}
{{{mmap:0x282000fe000:0x1000:load:0x3:rw:0x8000}}}
dso: id=b76f0d8110442057 base=0x00000282000f6000 name=liblaunchpad.so
{{{module:0x2:<vDSO>:elf:4eaf7db870868da0}}}
{{{mmap:0x282000ad000:0x7000:load:0x2:r:0}}}
{{{mmap:0x282000b4000:0x2000:load:0x2:rx:0x7000}}}
dso: id=4eaf7db870868da0 base=0x00000282000ad000 name=<vDSO>
{{{module:0x4:libfdio.so:elf:c3bf7a8a244e7287}}}
{{{mmap:0x282000ff000:0x12000:load:0x4:r:0}}}
{{{mmap:0x28200111000:0x3c000:load:0x4:rx:0x12000}}}
{{{mmap:0x2820014d000:0x7000:load:0x4:rw:0x4e000}}}
{{{mmap:0x28200154000:0x4000:load:0x4:rw:0x55000}}}
dso: id=c3bf7a8a244e7287 base=0x00000282000ff000 name=libfdio.so
{{{module:0x5:libtrace-engine.so:elf:f0dd4c361cb612f2}}}
{{{mmap:0x28200158000:0x4000:load:0x5:r:0}}}
{{{mmap:0x2820015c000:0x6000:load:0x5:rx:0x4000}}}
{{{mmap:0x28200162000:0x1000:load:0x5:rw:0xa000}}}
{{{mmap:0x28200163000:0x1000:load:0x5:rw:0xb000}}}
dso: id=f0dd4c361cb612f2 base=0x0000028200158000 name=libtrace-engine.so
{{{module:0x6:libasync-default.so:elf:99150f38cfad363e}}}
{{{mmap:0x28200164000:0x1000:load:0x6:r:0}}}
{{{mmap:0x28200165000:0x1000:load:0x6:rx:0x1000}}}
{{{mmap:0x28200166000:0x1000:load:0x6:rw:0x2000}}}
dso: id=99150f38cfad363e base=0x0000028200164000 name=libasync-default.so
{{{module:0x7:libmemfs.so:elf:c78ca7d6f498fbff}}}
{{{mmap:0x28200167000:0xc000:load:0x7:r:0}}}
{{{mmap:0x28200173000:0x2d000:load:0x7:rx:0xc000}}}
{{{mmap:0x282001a0000:0x5000:load:0x7:rw:0x39000}}}
{{{mmap:0x282001a5000:0x1000:load:0x7:rw:0x3e000}}}
dso: id=c78ca7d6f498fbff base=0x0000028200167000 name=libmemfs.so
{{{module:0x8:libc++.so.2:elf:b93b2e97bb80b9ea}}}
{{{mmap:0x282001a6000:0x53000:load:0x8:r:0}}}
{{{mmap:0x282001f9000:0x74000:load:0x8:rx:0x53000}}}
{{{mmap:0x2820026d000:0x6000:load:0x8:rw:0xc7000}}}
{{{mmap:0x28200273000:0x7000:load:0x8:rw:0xcd000}}}
dso: id=b93b2e97bb80b9ea base=0x00000282001a6000 name=libc++.so.2
{{{module:0x9:libc++abi.so.1:elf:50ce8a297362fa00}}}
{{{mmap:0x2820027a000:0x18000:load:0x9:r:0}}}
{{{mmap:0x28200292000:0x1c000:load:0x9:rx:0x18000}}}
{{{mmap:0x282002ae000:0x4000:load:0x9:rw:0x34000}}}
{{{mmap:0x282002b2000:0x1000:load:0x9:rw:0x38000}}}
dso: id=50ce8a297362fa00 base=0x000002820027a000 name=libc++abi.so.1
{{{module:0x1:libc.so:elf:0e81ca5ebfa5379b}}}
{{{mmap:0x28200000000:0x4f000:load:0x1:r:0}}}
{{{mmap:0x2820004f000:0x59000:load:0x1:rx:0x4f000}}}
{{{mmap:0x282000a8000:0x2000:load:0x1:rw:0xa8000}}}
{{{mmap:0x282000aa000:0x3000:load:0x1:rw:0xaa000}}}
dso: id=0e81ca5ebfa5379b base=0x0000028200000000 name=libc.so
{{{module:0xa:libunwind.so.1:elf:b38531532aba8b47}}}
{{{mmap:0x282002b3000:0x4000:load:0xa:r:0}}}
{{{mmap:0x282002b7000:0x6000:load:0xa:rx:0x4000}}}
{{{mmap:0x282002bd000:0x1000:load:0xa:rw:0xa000}}}
{{{mmap:0x282002be000:0x1000:load:0xa:rw:0xb000}}}
dso: id=b38531532aba8b47 base=0x00000282002b3000 name=libunwind.so.1
userboot: loader-service channel peer closed
bootsvc: Starting...
userboot: finished!
bootsvc: Taking root resource handle...
bootsvc: Creating bootfs service...
bootsvc: Retrieving boot image...
bootsvc: Decommitted BOOTDATA VMO from 0 to 0x4dbb000
bootsvc: Loading boot arguments...
bootsvc: Creating svcfs service...
bootsvc: Loading kernel VMOs...
bootsvc: Creating loader service...
bootsvc: Launching next process...
bootsvc: bootsvc.next = bin/component_manager,fuchsia-boot:///#meta/root.cm,--use-builtin-process-launcher
bootsvc: Launched bin/component_manager
[component_manager] INFO: Component manager is starting up...
fshost: watching for exit
driver_manager: launch /boot/bin/svchost (svchost) OK
console.shell: enabled
driver_manager: launch /boot/bin/pwrbtn-monitor (pwrbtn-monitor) OK
driver_manager: launch /boot/bin/miscsvc (miscsvc) OK
driver_manager: launch /boot/bin/device-name-provider (device-name-provider) OK
driver_manager: launch /boot/bin/virtual-console (virtual-console) OK
driver_manager: launch /boot/bin/sh (sh:console) OK
$ driver_manager: launch devhost 'driver_host:sys': pid=3499
driver_manager: launch devhost 'driver_host:test': pid=3548
driver_manager: launch devhost 'driver_host:root': pid=3613
driver_manager: launch devhost 'driver_host:misc': pid=3699
driver_host: create device drv='/boot/driver/platform-bus.so' args=''
Invalid zbi_board_info_t VMO
driver_host[sys/platform] bind driver '/boot/driver/platform-bus-x86.so'
driver_host[proxy] bind driver '/boot/driver/ethertap.so'
[113.321267243s ERROR 0:0] Skip IOPORTS_REQUEST
driver_host[proxy] bind driver '/boot/driver/test.so'
driver_host[proxy] bind driver '/boot/driver/virtual_audio_driver.so'
driver_host[proxy] bind driver '/boot/driver/builtin.so'
driver_host[proxy] bind driver '/boot/driver/demo-fifo.so'
Init: not using IOMMU
PlatformBus: set board name to "Standard PC (Q35 + ICH9, 2009)"
PlatformBus: set bootloader vendor to "EFI Development Kit II / OVMF"
driver_host[proxy] bind driver '/boot/driver/ktrace.so'
driver_host[sys/cpu-trace] bind driver '/boot/driver/cpu-trace.so'
driver_host[proxy] bind driver '/boot/driver/ram-nand.so'
[137.588546177s ERROR 0:0] syscall unimplemented: MTRACE_CONTROL
GetHwProperties: No PM support
IntelPT: No PT support
driver_host[sys/cpu-trace] bind driver '/boot/driver/cpu-trace.so' failed: -2
driver_host[sys/platform/00:00:1b] bind driver '/boot/driver/sysmem.so'
driver_host[proxy] bind driver '/boot/driver/ramdisk.so'
driver_manager: rpc: bind-driver 'cpu-trace' status -2
acpi-pwrbtn: initialized
driver_host[sys/platform/acpi/acpi-pwrbtn] bind driver '/boot/driver/hid.so'
driver_host[sys/platform/acpi/acpi-pwrbtn/hid-device-000] bind driver '/boot/driver/hid-input-report.so'
Can't process HID report descriptor for, all parsing attempts failed.
driver_host[sys/platform/acpi/acpi-pwrbtn/hid-device-000] bind driver '/boot/driver/hid-input-report.so' failed: -1
driver_manager: rpc: bind-driver 'hid-device-000' status -1
[149.262838831s ERROR 0:0] 

panicked at 'attempt to add with overflow', /mnt/c/root/works/code/git/zCore/zircon-syscall/src/pci.rs:111:33
[149.275560197s ERROR 0:0] KCounters {
    "exceptions.user": 30570,
    "exceptions.timer": 3469,
    "exceptions.pgfault": 0,
    "Process.create": 19,
    "Process.destroy": 1,
    "Thread.create": 45,
    "Thread.destroy": 4,
    "Channel.create": 1710,
    "Channel.destroy": 1190,
    "Job.create": 11,
    "Job.destroy": 0,
    "Event.create": 9,
    "Event.destroy": 2,
    "Timer.create": 25,
    "Timer.destroy": 0,
    "EventPair.create": 44,
    "EventPair.destroy": 0,
    "vmo.page_alloc": 1193348,
    "vmo.page_dealloc": 1066167,
    "VmObject.create": 1134,
    "VmObject.destroy": 72,
    "VmAddressRegion.create": 387,
    "VmAddressRegion.destroy": 23,
}
benpigchu commented 4 years ago

Here is what happened after this and #57

Before I start, I merged the rcore-os/driver-qemu branch to get some bug fixed by @wangrunji0408

The first bug in this issue can be simply fixed by convert before add, see this . Also, this only happens on debug build.

After that, a second bug happens: we recieved a 0x01 interrupt after a ZX_SYS_pci_map_interrupt syscall. After some logging I found it's using the MSI, which needs the kernel to allocate interrupt number for devices. So I look into the interrupt number allocating code, and ......

https://github.com/rcore-os/zCore/blob/15a68b88742de47cee0c2e2dd6de6cdc1adc0285/kernel-hal-bare/src/arch/x86_64/interrupt.rs#L176-L194

Look at the irq_start = (irq_cur & (irq_num - 1)) + irq_num; line, it is absolutely wrong. There should be a ! before the (irq_num - 1) . To be clear, I use % instead of bit operation.

After that, here come the third bug: The allocted interrupt number is 0x27 (which is correct), but we recieved a 0x7 interrupt instead! Also, the code that set interrupt number set the 0x27 as interrupt number correctly!

So I found some article about the PCI MSI (https://example61560.wordpress.com/2016/06/30/pcipcie-%E6%80%BB%E7%BA%BF%E6%A6%82%E8%BF%B06/) and use the qemu -trace to log all pci config operations. And what I see is:

103964@1592058745.690736:pci_cfg_write ich9-ahci 02:0 @0x8c <- 0x27
103964@1592058745.692715:pci_cfg_read ich9-ahci 02:0 @0x8c -> 0x27
103964@1592058745.693714:pci_cfg_write ich9-ahci 02:0 @0x8c <- 0x7

It is overrided by another thing. So I read the code after setting the interrupt number, and then......

https://github.com/rcore-os/zCore/blob/15a68b88742de47cee0c2e2dd6de6cdc1adc0285/zircon-object/src/dev/pci/nodes.rs#L995-L1005

This is not right. This field should in the Message Control field.

After fixing that, we get a page fault from the sysmem driver.(I add some addition log to print it, see this )

It's hard to debug user process, but by reading the log, I know that this page fault happens after the virtual-console found a display device and request some memory from sysmem. So I disabled virtual-console as a workaround. (https://github.com/rcore-os/zCore/pull/57/commits/f87e2a5b3f6f4ebdc511bb433ed3886fb6541289)

After that, I tested the hard disk on PCI. See #57 . There are still some issue, but we can just merge it since doing nothing will not break the kernal know.