[LOADER] Started
[LOADER] Found Multiboot information at 0x9500
[LOADER] Found module: [0x110000 - 0x1ba0798]
[LOADER] Found an ELF module at 0x110000
[LOADER] This is a supported HermitCore Application
[LOADER] Found TLS starts at 0x47f948 (size 264 Bytes)
[LOADER] File Size: 2627113 Bytes
[LOADER] Mem Size:  2636352 Bytes
[LOADER] Use 2 large pages for the application.
[LOADER] Clear BSS from 0x481629 to 0x483a40
[LOADER] BootInfo located at 0x10d0e0
[LOADER] Use stack address 0x1f8000
[LOADER] Jumping to HermitCore Application Entry Point at 0x3E8450
[0][INFO] Welcome to HermitCore-rs 0.3.27
[0][INFO] Kernel starts at 0x200000
[0][INFO] BSS starts at 0x481640
[0][INFO] TLS starts at 0x47f948 (size 264 Bytes)
[0][DEBUG] Set CR0 to 0x8001003b
[0][DEBUG] Set CR4 to 0x50660
[0][DEBUG] Create new view to the kernel space
[0][DEBUG] Found PML4 at 0x109000
[0][INFO] Found Multiboot info at 0x9500
[0][INFO] Found cmdline at 0x10f03e (size 62)
[0][INFO] Total memory size: 63 MB
[0][INFO] A pure Rust application is running on top of HermitCore!
[0][INFO] Heap: size 50 MB, start address 0x600000
[0][INFO] Heap is located at 0x600000 -- 0x3800000 (0 Bytes unmapped)
[0][INFO] 
[0][INFO] ===================== PHYSICAL MEMORY FREE LIST ======================
[0][INFO] 0x00000003800000 - 0x00000003FE0000
[0][INFO] ======================================================================
[0][INFO] 
[0][INFO] 
[0][INFO] ================== KERNEL VIRTUAL MEMORY FREE LIST ===================
[0][INFO] 0x00000003800000 - 0x00800000000000
[0][INFO] ======================================================================
[0][INFO] 
[0][DEBUG] Got cmdline tokens as ["loader/target/x86_64-unknown-hermit-loader/debug/rusty-loader"]
[0][INFO] 
[0][INFO] ========================== CPU INFORMATION ===========================
[0][INFO] Model:                   QEMU Virtual CPU version 2.5+
[0][INFO] Frequency:               3605 MHz (from Measurement)
[0][INFO] SpeedStep Technology:    Not Available
[0][INFO] Features:                MMX SSE SSE2 SSE3 RDRAND MCE FXSR XSAVE RDTSCP CLFLUSH FSGSBASE 
[0][INFO] Physical Address Width:  40 bits
[0][INFO] Linear Address Width:    48 bits
[0][INFO] Supports 1GiB Pages:     No
[0][INFO] ======================================================================
[0][INFO] 
[0][INFO] HermitCore-rs booted on 2020-05-13 at 06:55:06
[0][DEBUG] Scanning PCI Busses 0 to 31
[0][DEBUG] Bar 0 @1237:8086 is memory mapped, but treated as IO mapped! this will cause errors later..
[0][DEBUG] Bar 1 @1237:8086 is memory mapped, but treated as IO mapped! this will cause errors later..
[0][DEBUG] Bar 2 @1237:8086 is memory mapped, but treated as IO mapped! this will cause errors later..
[0][DEBUG] Bar 3 @1237:8086 is memory mapped, but treated as IO mapped! this will cause errors later..
[0][DEBUG] Bar 4 @1237:8086 is memory mapped, but treated as IO mapped! this will cause errors later..
[0][DEBUG] Bar 5 @1237:8086 is memory mapped, but treated as IO mapped! this will cause errors later..
[0][DEBUG] Bar 0 @7000:8086 is memory mapped, but treated as IO mapped! this will cause errors later..
[0][DEBUG] Bar 1 @7000:8086 is memory mapped, but treated as IO mapped! this will cause errors later..
[0][DEBUG] Bar 2 @7000:8086 is memory mapped, but treated as IO mapped! this will cause errors later..
[0][DEBUG] Bar 3 @7000:8086 is memory mapped, but treated as IO mapped! this will cause errors later..
[0][DEBUG] Bar 4 @7000:8086 is memory mapped, but treated as IO mapped! this will cause errors later..
[0][DEBUG] Bar 5 @7000:8086 is memory mapped, but treated as IO mapped! this will cause errors later..
[0][DEBUG] Bar 0 @1111:1234 is memory mapped, but treated as IO mapped! this will cause errors later..
[0][DEBUG] Bar 1 @1111:1234 is memory mapped, but treated as IO mapped! this will cause errors later..
[0][DEBUG] Bar 2 @1111:1234 is memory mapped, but treated as IO mapped! this will cause errors later..
[0][DEBUG] Bar 3 @1111:1234 is memory mapped, but treated as IO mapped! this will cause errors later..
[0][DEBUG] Bar 4 @1111:1234 is memory mapped, but treated as IO mapped! this will cause errors later..
[0][DEBUG] Bar 5 @1111:1234 is memory mapped, but treated as IO mapped! this will cause errors later..
[0][DEBUG] Bar 0 @100e:8086 is memory mapped, but treated as IO mapped! this will cause errors later..
[0][DEBUG] Bar 2 @100e:8086 is memory mapped, but treated as IO mapped! this will cause errors later..
[0][DEBUG] Bar 3 @100e:8086 is memory mapped, but treated as IO mapped! this will cause errors later..
[0][DEBUG] Bar 4 @100e:8086 is memory mapped, but treated as IO mapped! this will cause errors later..
[0][DEBUG] Bar 5 @100e:8086 is memory mapped, but treated as IO mapped! this will cause errors later..
[0][INFO] 
[0][INFO] ======================== PCI BUS INFORMATION =========================
[0][INFO] 00:00 Host bridge [0600]: Intel Corporation 440FX - 82441FX PMC [Natoma] [8086:1237], iobase 
[0][INFO] 00:01 ISA bridge [0601]: Intel Corporation 82371SB PIIX3 ISA [Natoma/Triton II] [8086:7000], iobase 
[0][INFO] 00:02 VGA compatible controller [0300]: Unknown Vendor Unknown Device [1234:1111], iobase 0xfd000008 (size 0x1000000) 0xfebf0000 (size 0x1000) 
[0][INFO] 00:03 Ethernet controller [0200]: Intel Corporation 82540EM Gigabit Ethernet Controller [8086:100E], IRQ 11, iobase 0xfebc0000 (size 0x20000) 0xc000 (size 0x40) 
[0][INFO] ======================================================================
[0][INFO] 
[0][INFO] Found an ACPI revision 0 table at 0xF5870 with OEM ID "BOCHS "
[0][DEBUG] Found ACPI table: FACP
[0][DEBUG] Found ACPI table: APIC
[0][DEBUG] Found ACPI table: HPET
[0][DEBUG] Found Processor Local APIC record: { acpi_processor_id: 0, apic_id: 0, flags: 1 }
[0][DEBUG] Found Processor Local APIC record: { acpi_processor_id: 1, apic_id: 1, flags: 1 }
[0][DEBUG] Found I/O APIC record: { id: 0, reserved: 0, address: 0xFEC00000, global_system_interrupt_base: 0 }
[0][DEBUG] Mapping IOAPIC at 0xFEC00000 to virtual address 0x3830000
[0][DEBUG] Mapping Local APIC at 0xFEE00000 to virtual address 0x3831000
[0][DEBUG] Calibrated APIC Timer with a counter value of 128 for 1 microsecond
[0][INFO] IOAPIC v32 has 24 entries
[0][INFO] Disable IOAPIC timer
[0][DEBUG] Creating idle task 0
[0][DEBUG] Using boot stack 0x1F8000
[0][DEBUG] IST0 is located at 0x3810000
[0][DEBUG] Initializing scheduler for core 0 with idle task 0
[0][DEBUG] SMP boot code is 231 bytes long
[0][DEBUG] Mapping SMP boot code to physical and virtual address 0x8000
[0][DEBUG] Set entry point for application processor to 0x3e8450
[0][DEBUG] Waking up CPU 1 with Local APIC ID 1
[0][DEBUG] Waiting for it to respond
[1][DEBUG] Set CR0 to 0x8001003b
[1][DEBUG] Set CR4 to 0x50660
[1][DEBUG] Creating idle task 1
[0][INFO] 
[1][DEBUG] Using boot stack 0x3834000
[0][INFO] ===================== MULTIPROCESSOR INFORMATION =====================
[1][DEBUG] IST0 is located at 0x383C000
[0][INFO] APIC in use:             xAPIC
[1][DEBUG] Initializing scheduler for core 1 with idle task 1
[0][INFO] Initialized CPUs:        2
[0][INFO] ======================================================================
[1][INFO] Entering idle loop for application processor
[0][INFO] 
[0][DEBUG] Creating new task 2
[0][DEBUG] Create stacks at 0x385C000 with a size of 1088 KB
[0][DEBUG] Set up TLS at 0x3970120, tdata_size 0x0, tls_size 0x108
[0][DEBUG] Creating task 2 with priority 2 on core 0
[0][DEBUG] Task is available.
[0][DEBUG] Switching task from 0 to 2 (stack 0x0 => 0x386DF60)
[0][INFO] HermitCore is running on common system!
[0][DEBUG] Switching FPU owner from task 0 to 2
[0][DEBUG] Creating new task 3
[0][DEBUG] Create stacks at 0x3971000 with a size of 1088 KB
[0][DEBUG] Set up TLS at 0x3a85120, tdata_size 0x0, tls_size 0x108
[0][DEBUG] Creating task 3 with priority 3 on core 0
[INFO] Spawn network thread with id 3
[0][DEBUG] Task with a higher priority is available.
[0][DEBUG] Switching task from 2 to 3 (stack 0x386DF60 => 0x3982F60)
[0][DEBUG] Switching FPU owner from task 2 to 3
[WARN] Ethernet interface not available
[0][DEBUG] Finishing task 3 with exit code 0
[0][DEBUG] Task is available.
[0][DEBUG] Switching task from 3 to 2 (stack 0x3982F60 => 0x386DE40)
[0][DEBUG] Switching FPU owner from task 3 to 2
[0][DEBUG] Deallocating stacks at 0x3971000 with a size of 1088 KB
[1][DEBUG] Received TLB Flush Interrupt
[0][DEBUG] Deallocate TLS at 0x3a85000 (size 0x1000)
[1][DEBUG] Received TLB Flush Interrupt
Hello, world!
Test hello ... ok
argument[0] = {name}
Test print_argv ... ok
Test print_env ... ok
[0][DEBUG] Open /etc/hostname, 0, 0
[0][DEBUG] Opening file /etc/hostname FilePerms { write: false, creat: false, excl: false, trunc: false, append: false, directio: false, raw: 0, mode: 0 }
[0][INFO] Trying to open file on non-existing mount point 'etc'!
Test read_file ... failed!
[0][DEBUG] Open /tmp/foo.txt, 577, 1911
[0][DEBUG] Opening file /tmp/foo.txt FilePerms { write: true, creat: true, excl: false, trunc: true, append: false, directio: false, raw: 577, mode: 511 }
[0][INFO] Trying to open file on non-existing mount point 'tmp'!
Test create_file ... failed!
[0][DEBUG] Creating new task 4
[0][DEBUG] Create stacks at 0x3971000 with a size of 1088 KB
[1][DEBUG] Received TLB Flush Interrupt
[1][DEBUG] Received TLB Flush Interrupt
[1][DEBUG] Received TLB Flush Interrupt
[0][DEBUG] Set up TLS at 0x3a85120, tdata_size 0x0, tls_size 0x108
[1][DEBUG] Received TLB Flush Interrupt
[0][DEBUG] Creating task 4 with priority 2 on core 1
[1][DEBUG] Received Wakeup Interrupt
[1][DEBUG] Task is available.
[1][DEBUG] Switching task from 1 to 4 (stack 0x0 => 0x3982F60)
[0][DEBUG] Creating new task 5
[0][DEBUG] Create stacks at 0x3A86000 with a size of 1088 KB
[1][DEBUG] Switching FPU owner from task 1 to 4
this is thread number 0
[1][DEBUG] Finishing task 4 with exit code 0
[1][DEBUG] Only Idle Task is available.
[1][DEBUG] Switching task from 4 to 1 (stack 0x3982F60 => 0x383BD50)
[1][DEBUG] Cleaning up task 4
[0][DEBUG] Set up TLS at 0x3b9a120, tdata_size 0x0, tls_size 0x108
[0][DEBUG] Creating task 5 with priority 2 on core 0
[0][DEBUG] Task 2 is waiting for task 4
[0][DEBUG] Task 2 is waiting for task 5
[0][DEBUG] Blocking task 2
[0][DEBUG] Cleaning up task 3
[0][DEBUG] Task is available.
[0][DEBUG] Switching task from 2 to 5 (stack 0x386DE40 => 0x3A97F60)
[0][DEBUG] Switching FPU owner from task 2 to 5
this is thread number 1
[0][DEBUG] Finishing task 5 with exit code 0
[0][DEBUG] Only Idle Task is available.
[0][DEBUG] Switching task from 5 to 0 (stack 0x3A97F60 => 0x1FFDD0)
[0][DEBUG] Cleaning up task 5
[0][DEBUG] Waking up task 2 on core 0
[0][DEBUG] Task is available.
[0][DEBUG] Switching task from 0 to 2 (stack 0x1FFDD0 => 0x386DDD0)
[0][DEBUG] Switching FPU owner from task 5 to 2
[0][DEBUG] Deallocating stacks at 0x3A86000 with a size of 1088 KB
[1][DEBUG] Received TLB Flush Interrupt
[0][DEBUG] Deallocate TLS at 0x3b9a000 (size 0x1000)
[1][DEBUG] Received TLB Flush Interrupt
Test threading ... ok
Pi: 3.141592653589587 (sequential)
Test pi_sequential ... ok
[0][DEBUG] Creating new task 6
[0][DEBUG] Create stacks at 0x3A86000 with a size of 1088 KB
[1][DEBUG] Received TLB Flush Interrupt
[1][DEBUG] Received TLB Flush Interrupt
[0][DEBUG] Set up TLS at 0x3b9a120, tdata_size 0x0, tls_size 0x108
[1][DEBUG] Received TLB Flush Interrupt
[0][DEBUG] Creating task 6 with priority 2 on core 1
[1][DEBUG] Received Wakeup Interrupt
[1][DEBUG] Task is available.
[1][DEBUG] Switching task from 1 to 6 (stack 0x383BD50 => 0x3A97F60)
[0][DEBUG] Creating new task 7
[1][DEBUG] Switching FPU owner from task 4 to 6
[0][DEBUG] Create stacks at 0x3B9B000 with a size of 1088 KB
[1][DEBUG] Deallocating stacks at 0x3971000 with a size of 1088 KB
[1][DEBUG] Deallocate TLS at 0x3a85000 (size 0x1000)
[0][DEBUG] Received TLB Flush Interrupt
[0][DEBUG] Received TLB Flush Interrupt
[0][DEBUG] Set up TLS at 0x3971120, tdata_size 0x0, tls_size 0x108
[1][DEBUG] Received TLB Flush Interrupt
[0][DEBUG] Creating task 7 with priority 2 on core 0
[0][DEBUG] Task 2 is waiting for task 6
[0][DEBUG] Blocking task 2
[0][DEBUG] Task is available.
[0][DEBUG] Switching task from 2 to 7 (stack 0x386DDD0 => 0x3BACF60)
[0][DEBUG] Switching FPU owner from task 2 to 7
[1][DEBUG] Finishing task 6 with exit code 0
[1][DEBUG] Only Idle Task is available.
[1][DEBUG] Switching task from 6 to 1 (stack 0x3A97F60 => 0x383BD50)
[1][DEBUG] Cleaning up task 6
[0][DEBUG] Received Wakeup Interrupt
[0][DEBUG] Waking up task 2 on core 0
[0][DEBUG] Finishing task 7 with exit code 0
[0][DEBUG] Task is available.
[0][DEBUG] Switching task from 7 to 2 (stack 0x3BACF60 => 0x386DDD0)
[0][DEBUG] Switching FPU owner from task 7 to 2
[0][DEBUG] Deallocating stacks at 0x3B9B000 with a size of 1088 KB
[1][DEBUG] Received TLB Flush Interrupt
[0][DEBUG] Deallocate TLS at 0x3971000 (size 0x1000)
[1][DEBUG] Received TLB Flush Interrupt
[0][DEBUG] Task 2 is waiting for task 7
[0][DEBUG] Blocking task 2
[0][DEBUG] Cleaning up task 7
[0][DEBUG] Waking up task 2 on core 0
[0][DEBUG] Task is available.
Pi: 3.1415926535897665 (with 2 threads)
Test pi_parallel ... ok
[0][DEBUG] Creating new task 8
[0][DEBUG] Create stacks at 0x3971000 with a size of 1088 KB
[1][DEBUG] Received TLB Flush Interrupt
[1][DEBUG] Received TLB Flush Interrupt
[1][DEBUG] Received TLB Flush Interrupt
[1][DEBUG] Received TLB Flush Interrupt
[0][DEBUG] Set up TLS at 0x3a85120, tdata_size 0x0, tls_size 0x108
[0][DEBUG] Creating task 8 with priority 2 on core 1
[1][DEBUG] Received Wakeup Interrupt
[1][DEBUG] Task is available.
[1][DEBUG] Switching task from 1 to 8 (stack 0x383BD50 => 0x3982F60)
[0][DEBUG] Creating new task 9
[1][DEBUG] Switching FPU owner from task 6 to 8
[0][DEBUG] Create stacks at 0x3B9B000 with a size of 1088 KB
[1][DEBUG] Deallocating stacks at 0x3A86000 with a size of 1088 KB
[0][DEBUG] Received TLB Flush Interrupt
[1][DEBUG] Deallocate TLS at 0x3b9a000 (size 0x1000)
[0][DEBUG] Received TLB Flush Interrupt
[1][DEBUG] Received TLB Flush Interrupt
[1][DEBUG] sys_notify: invalid address to condition variable
[0][DEBUG] Set up TLS at 0x3a86120, tdata_size 0x0, tls_size 0x108
[0][DEBUG] Creating task 9 with priority 2 on core 0
[1][DEBUG] Received TLB Flush Interrupt
[1][DEBUG] Create condition variable queue
[1][DEBUG] Blocking task 8
[1][DEBUG] Only Idle Task is available.
[1][DEBUG] Switching task from 8 to 1 (stack 0x3982F60 => 0x383BD50)
[1][DEBUG] Received Wakeup Interrupt
[0][DEBUG] Create condition variable queue
[1][DEBUG] Waking up task 8 on core 1
[0][DEBUG] Blocking task 2
[1][DEBUG] Task is available.
[0][DEBUG] Task is available.
[1][DEBUG] Switching task from 1 to 8 (stack 0x383BD50 => 0x3982E40)
[0][DEBUG] Switching task from 2 to 9 (stack 0x386DDD0 => 0x3BACF60)
[0][DEBUG] Switching FPU owner from task 2 to 9
[0][DEBUG] sys_notify: invalid address to condition variable
[1][DEBUG] Blocking task 8
[0][DEBUG] Waking up task 2 on core 0
[0][DEBUG] Blocking task 9
[0][DEBUG] Task is available.
[0][DEBUG] Switching task from 9 to 2 (stack 0x3BACF60 => 0x386DE40)
[1][DEBUG] Only Idle Task is available.
[1][DEBUG] Switching task from 8 to 1 (stack 0x3982E40 => 0x383BD50)
[0][DEBUG] Received Wakeup Interrupt
[0][DEBUG] Waking up task 9 on core 0
[0][DEBUG] Switching FPU owner from task 9 to 2
[0][DEBUG] Blocking task 2
[0][DEBUG] Task is available.
[0][DEBUG] Switching task from 2 to 9 (stack 0x386DE40 => 0x3BACDA0)
[1][DEBUG] Received Wakeup Interrupt
[0][DEBUG] Switching FPU owner from task 2 to 9
[1][DEBUG] Waking up task 8 on core 1
[1][DEBUG] Task is available.
[1][DEBUG] Switching task from 1 to 8 (stack 0x383BD50 => 0x3982E40)
[0][DEBUG] Waking up task 2 on core 0
[0][DEBUG] Time slice expired for current task.
[0][DEBUG] Switching task from 9 to 2 (stack 0x3BACDA0 => 0x386DE40)
[0][DEBUG] Switching FPU owner from task 9 to 2
[1][DEBUG] Blocking task 8
[0][DEBUG] Blocking task 2
[0][DEBUG] Task is available.
[1][DEBUG] Only Idle Task is available.
[0][DEBUG] Switching task from 2 to 9 (stack 0x386DE40 => 0x3BACE40)
[1][DEBUG] Switching task from 8 to 1 (stack 0x3982E40 => 0x383BD50)
[0][DEBUG] Received Wakeup Interrupt
[0][DEBUG] Waking up task 2 on core 0
[0][DEBUG] Switching FPU owner from task 2 to 9
[0][DEBUG] Time slice expired for current task.
[0][DEBUG] Switching task from 9 to 2 (stack 0x3BACE40 => 0x386DDA0)
[1][DEBUG] Received Wakeup Interrupt
[0][DEBUG] Switching FPU owner from task 9 to 2
[1][DEBUG] Waking up task 8 on core 1
[0][DEBUG] Blocking task 2
[1][DEBUG] Task is available.
[0][DEBUG] Task is available.
[1][DEBUG] Switching task from 1 to 8 (stack 0x383BD50 => 0x3982E40)
[0][DEBUG] Switching task from 2 to 9 (stack 0x386DDA0 => 0x3BACE40)
[0][DEBUG] Switching FPU owner from task 2 to 9
[0][DEBUG] Received Wakeup Interrupt
[0][DEBUG] Waking up task 2 on core 0
[1][DEBUG] Blocking task 8
[1][DEBUG] Only Idle Task is available.
[1][DEBUG] Switching task from 8 to 1 (stack 0x3982E40 => 0x383BD50)
[0][DEBUG] Blocking task 9
[0][DEBUG] Task is available.
[0][DEBUG] Switching task from 9 to 2 (stack 0x3BACE40 => 0x386DE40)
[0][DEBUG] Switching FPU owner from task 9 to 2
[1][DEBUG] Received Wakeup Interrupt
[0][DEBUG] Waking up task 9 on core 0
[1][DEBUG] Waking up task 8 on core 1
[0][DEBUG] Blocking task 2
[1][DEBUG] Task is available.
[0][DEBUG] Task is available.
[1][DEBUG] Switching task from 1 to 8 (stack 0x383BD50 => 0x3982E40)
[0][DEBUG] Switching task from 2 to 9 (stack 0x386DE40 => 0x3BACE40)
[0][DEBUG] Switching FPU owner from task 2 to 9
[1][DEBUG] Blocking task 8
[1][DEBUG] Only Idle Task is available.
[1][DEBUG] Switching task from 8 to 1 (stack 0x3982E40 => 0x383BD50)
[0][DEBUG] Blocking task 9
[0][DEBUG] Received Wakeup Interrupt
[0][DEBUG] Waking up task 2 on core 0
[0][DEBUG] Task is available.
[0][DEBUG] Switching task from 9 to 2 (stack 0x3BACE40 => 0x386DE40)
[0][DEBUG] Switching FPU owner from task 9 to 2
[1][DEBUG] Received Wakeup Interrupt
[0][DEBUG] Blocking task 2
[1][DEBUG] Waking up task 8 on core 1
[0][DEBUG] Only Idle Task is available.
[1][DEBUG] Task is available.
[0][DEBUG] Switching task from 2 to 0 (stack 0x386DE40 => 0x1FFDD0)
[1][DEBUG] Switching task from 1 to 8 (stack 0x383BD50 => 0x3982E40)
[0][DEBUG] Received Wakeup Interrupt
[1][DEBUG] Blocking task 8
[1][DEBUG] Only Idle Task is available.
[1][DEBUG] Switching task from 8 to 1 (stack 0x3982E40 => 0x383BD50)