search

lsds / sgx-lkl

SGX-LKL Library OS for running Linux applications inside of Intel SGX enclaves
MIT License
256 stars 89 forks source link

[Tests] fallocate test fails to clean up correctly #715

Open prp opened 4 years ago

prp commented 4 years ago

The LTP test kernel-syscalls-fallocate-fallocate05-(debug)-(run-hw)-(8-ethreads) can show the following failure:

[   SGX-LKL  ] nproc=4 ETHREADS=8 CMDLINE="mem=512m"
[   SGX-LKL  ] HW TLS support: econf->fsgsbase=1
[   SGX-LKL  ] Registering disk 0 (path='sgxlkl-miniroot-fs.img', mnt='/', [RW])
[   SGX-LKL  ] No tap device specified, networking will not be available.
[   SGX-LKL  ] get_signed_libsgxlkl_path... result=/opt/sgx-lkl-debug/bin/../lib/libsgxlkl.so.signed
[   SGX-LKL  ] oe_create_enclave...
[   SGX-LKL  ] Enclave config: {"args":["/ltp/testcases/kernel/syscalls/fallocate/fallocate05"],"clock_res":[{"resolution":"0000000000000001"},{"resolution":"0000000000000001"},{"resolution":"0000000000000000"},{"resolution":"0000000000000000"},{"resolution":"0000000000000001"},{"resolution":"00000000003d0900"},{"resolution":"00000000003d0900"},{"resolution":"0000000000000001"}],"cwd":"/","env":[],"esleep":"16000","espins":"500","ethreads":"8","exit_status":"full","format_version":"1","fsgsbase":true,"host_import_env":[],"hostname":"lkl","hostnet":false,"image_sizes":{"num_heap_pages":"262144","num_stack_pages":"1024"},"io":{"block":true,"console":true,"network":true},"kernel_cmd":"mem=512m","kernel_verbose":true,"max_user_threads":"256","mmap_files":"shared","mode":"hw_debug","mounts":[],"net_gw4":"10.0.1.254","net_ip4":"10.0.1.1","net_mask4":"24","oe_heap_pagecount":"8192","root":{"key":"","key_id":null,"overlay":false,"readonly":false,"roothash":null,"roothash_offset":"0"},"stacksize":"524288","swiotlb":true,"sysctl":null,"tap_mtu":"0","verbose":true,"wg":{"ip":"10.0.2.1","key":null,"listen_port":"56002","peers":[]}}
result=0 (OE_OK)
[   SGX-LKL  ] sgxlkl_enclave_init(ethread_id=0)
[[  SGX-LKL ]] sgxlkl_enclave_init(): enter
[[  SGX-LKL ]] _sgxlkl_enclave_show_attribute(): enclave base=0x7fc000000000 size=64.0 GiB
[[  SGX-LKL ]] _sgxlkl_enclave_show_attribute(): enclave heap base=0x7fc000b04000 size=1024.0 MiB end=0x7fc040b04000
[[  SGX-LKL ]] sgxlkl_enclave_init(): calling _dlstart_c()
[[  SGX-LKL ]] _register_enclave_signal_handlers(): Registering OE exception handler...
[[  SGX-LKL ]] __libc_init_enclave(): calling enclave_mman_init()
[[  SGX-LKL ]] __libc_init_enclave(): calling _lthread_sched_init()
[[  SGX-LKL ]] lkl_start_init(): calling register_lkl_syscall_overrides()
[[  SGX-LKL ]] lkl_start_init(): calling initialize_enclave_event_channel()
[[  SGX-LKL ]] lkl_start_init(): kernel command line: 'mem=512m console=hvc0'
[[  SGX-LKL ]] lkl_start_init(): Disk 0: Disk encryption: no
[[  SGX-LKL ]] lkl_start_init(): Disk 0: Disk is writable: yes
[[  SGX-LKL ]] lkl_start_init(): lkl_start_kernel() called
[    0.000000] Linux version 5.3.0+ (AzDevOps@cisca24ba0002S1) (gcc version 7.5.0 (Ubuntu 7.5.0-3ubuntu1~18.04)) #1 Tue Aug 4 00:07:50 UTC 2020
[    0.000000] memblock address range: 0x7fc020883000 - 0x7fc040883000
[    0.000000] Built 1 zonelists, mobility grouping on.  Total pages: 129280
[    0.000000] Kernel command line: mem=512m console=hvc0 virtio_mmio.device=256@0x1000000:1
[    0.000000] Dentry cache hash table entries: 65536 (order: 7, 524288 bytes, linear)
[    0.000000] Inode-cache hash table entries: 32768 (order: 6, 262144 bytes, linear)
[    0.000000] mem auto-init: stack:off, heap alloc:off, heap free:off
[    0.000000] Memory available: 516256k/524288k RAM
[    0.000000] SLUB: HWalign=32, Order=0-3, MinObjects=0, CPUs=1, Nodes=1
[    0.000000] NR_IRQS: 4096
[    0.000000] lkl: irqs initialized
[    0.000000] clocksource: lkl: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns
[    0.000000] lkl: time and timers initialized (irq2)
[    0.000506] printk: console [hvc0] enabled
[    0.000506] pid_max: default: 4096 minimum: 301
[    0.000507] Mount-cache hash table entries: 1024 (order: 1, 8192 bytes, linear)
[    0.000507] Mountpoint-cache hash table entries: 1024 (order: 1, 8192 bytes, linear)
[    0.002575] devtmpfs: initialized
[    0.009245] random: get_random_bytes called from 0x00007fc000631982 with crng_init=0
[    0.009246] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
[    0.009247] futex hash table entries: 16 (order: -4, 384 bytes, linear)
[    0.009247] xor: automatically using best checksumming function   8regs     
[    0.009800] NET: Registered protocol family 16
[    0.015273] clocksource: Switched to clocksource lkl
[    0.015276] NET: Registered protocol family 2
[    0.016390] tcp_listen_portaddr_hash hash table entries: 256 (order: 0, 4096 bytes, linear)
[    0.016947] TCP established hash table entries: 4096 (order: 3, 32768 bytes, linear)
[    0.017494] TCP bind hash table entries: 4096 (order: 3, 32768 bytes, linear)
[    0.017494] TCP: Hash tables configured (established 4096 bind 4096)
[    0.017496] UDP hash table entries: 256 (order: 1, 8192 bytes, linear)
[    0.017497] UDP-Lite hash table entries: 256 (order: 1, 8192 bytes, linear)
[    0.018053] NET: Registered protocol family 1
[    0.018054] virtio-mmio: Registering device virtio-mmio.0 at 0x1000000-0x10000ff, IRQ 1.
[    0.018611] workingset: timestamp_bits=62 max_order=18 bucket_order=0
[    0.021954] NET: Registered protocol family 38
[    0.021954] io scheduler mq-deadline registered
[    0.021954] io scheduler kyber registered
[    0.189144] software IO TLB: mapped [mem 0x7fda611f1000-0x7fda651f1000] (64MB)
[    0.197375] loop: module loaded
[    0.197880] device-mapper: ioctl: 4.40.0-ioctl (2019-01-18) initialised: dm-devel@redhat.com
[    0.202819] wireguard: WireGuard 0.0.20191219 loaded. See www.wireguard.com for information.
[    0.203375] wireguard: Copyright (C) 2015-2019 Jason A. Donenfeld <Jason@zx2c4.com>. All Rights Reserved.
[    0.204476] NET: Registered protocol family 10
[    0.204980] Segment Routing with IPv6
[    0.204980] sit: IPv6, IPv4 and MPLS over IPv4 tunneling driver
[    0.205535] This architecture does not have kernel memory protection.
[    0.211028] Run /init as init process
[[  SGX-LKL ]] lkl_start_init(): lkl_start_kernel() finished
[[  SGX-LKL ]] lkl_start_init(): creating LKL termination thread
[[  SGX-LKL ]] create_lkl_termination_thread(): enter
[[  SGX-LKL ]] lkl_start_init(): calling lkl_mount_virtual()
[[  SGX-LKL ]] lkl_termination_thread(): enter
[[  SGX-LKL ]] lkl_termination_thread(): Performed LKL syscall to get host task allocated (pid=36)
[[  SGX-LKL ]] lkl_start_init(): calling init_random()
[[  SGX-LKL ]] init_random(): Adding entropy to entropy pool
[    0.211588] random: crng init done
[[  SGX-LKL ]] init_enclave_clock(): Setting enclave realtime clock
[[  SGX-LKL ]] wg0 has public key bYOc5iazOB4OSWQ/Dm7MbGH5vEa4ci23pyzqZdEJnEQ=
[    0.216572] virtio_blk virtio1: [vda] 3072000 512-byte logical blocks (1.57 GB/1.46 GiB)
[[  SGX-LKL ]] lkl_mount_disk(): lkl_mount_disk(dev="/dev/vda", mnt="/mnt/vda", ro=0)
[    0.235187] EXT4-fs (vda): mounted filesystem with ordered data mode. Opts: 
[[  SGX-LKL ]] lkl_mount_disks(): Set working directory: /
[[  SGX-LKL ]] libc_start_main_stage2(): Calling app main: /ltp/testcases/kernel/syscalls/fallocate/fallocate05
tst_test.c:1106: [1;34mINFO: [0mTimeout per run is 0h 05m 00s
tst_test.c:1125: [1;34mINFO: [0mNo fork support
tst_fill_fs.c:29: [1;34mINFO: [0mCreating file mntpoint/file0 size 53121707
tst_fill_fs.c:29: [1;34mINFO: [0mCreating file mntpoint/file1 size 30471145
tst_fill_fs.c:29: [1;34mINFO: [0mCreating file mntpoint/file2 size 98150909
tst_fill_fs.c:29: [1;34mINFO: [0mCreating file mntpoint/file3 size 91247207
tst_fill_fs.c:29: [1;34mINFO: [0mCreating file mntpoint/file4 size 23437525
tst_fill_fs.c:29: [1;34mINFO: [0mCreating file mntpoint/file5 size 18763313
tst_fill_fs.c:29: [1;34mINFO: [0mCreating file mntpoint/file6 size 3276218
tst_fill_fs.c:29: [1;34mINFO: [0mCreating file mntpoint/file7 size 17595605
tst_fill_fs.c:29: [1;34mINFO: [0mCreating file mntpoint/file8 size 14301264
tst_fill_fs.c:29: [1;34mINFO: [0mCreating file mntpoint/file9 size 4444240
tst_fill_fs.c:29: [1;34mINFO: [0mCreating file mntpoint/file10 size 20896333
tst_fill_fs.c:29: [1;34mINFO: [0mCreating file mntpoint/file11 size 98294094
tst_fill_fs.c:29: [1;34mINFO: [0mCreating file mntpoint/file12 size 70551612
tst_fill_fs.c:29: [1;34mINFO: [0mCreating file mntpoint/file13 size 51737098
tst_fill_fs.c:47: [1;31mBROK: [0mwrite(): SUCCESS (0)
safe_macros.c:184: [1;35mWARN: [0mfallocate05.c:91: rmdir(mntpoint) failed: ENOTEMPTY (39)

Summary:
passed   0
failed   0
skipped  0
warnings 1
[[  SGX-LKL ]] lkl_terminate(): terminating LKL (exit_status=6)
[[  SGX-LKL ]] lkl_termination_thread(): termination thread unblocked
[[  SGX-LKL ]] lkl_termination_thread(): calling lkl_sys_chdir(/)
[[  SGX-LKL ]] display_mount_table(): ========= /proc/mounts ===========
/dev/vda / ext4 rw,relatime 0 0
devtmpfs /dev devtmpfs rw,relatime 0 0
tmpfs /dev/shm tmpfs rw,relatime 0 0
tmpfs /tmp tmpfs rw,relatime,mode=777 0 0
tmpfs /mnt tmpfs rw,relatime,mode=777 0 0
none /sys sysfs rw,relatime 0 0
tmpfs /run tmpfs rw,relatime,mode=700 0 0
proc /proc proc rw,relatime 0 0
[[  SGX-LKL ]] display_mount_table(): ==================================
[[  SGX-LKL ]] display_mount_table(): ========= /proc/mounts ===========
/dev/vda / ext4 rw,relatime 0 0
devtmpfs /dev devtmpfs rw,relatime 0 0
tmpfs /dev/shm tmpfs rw,relatime 0 0
tmpfs /tmp tmpfs rw,relatime,mode=777 0 0
tmpfs /mnt tmpfs rw,relatime,mode=777 0 0
none /sys sysfs rw,relatime 0 0
tmpfs /run tmpfs rw,relatime,mode=700 0 0
proc /proc proc rw,relatime 0 0
[[  SGX-LKL ]] display_mount_table(): ==================================
[[  SGX-LKL ]] lkl_termination_thread(): calling lkl_umount_timeout("/", MNT_DETACH, 2000)
[[  SGX-LKL ]] lkl_termination_thread(): calling lkl_virtio_netdev_remove()
[[  SGX-LKL ]] lkl_termination_thread(): calling lkl_sys_halt()
[    4.920344] reboot: Restarting system
[[  SGX-LKL ]] lkl_termination_thread(): lthread_detach2() done
[   SGX-LKL  ] ethread (2: 0) ethread (3: 0) ethread (4: 0) ethread (6: 0) ethread (1: 0) init (0: 0 exit=6) ethread (5: 0) ethread (7: 0) 
[   SGX-LKL  ] oe_terminate_enclave... done
[   SGX-LKL  ] SGX-LKL-OE exit: exit_status=6
TEST_FAILED EXIT CODE: 6

I believe that this is a problem with the test. Looking at the code here, it doesn't seem that all the created files are deleted before the directory is removed.

(cc: @hukoyu)

hukoyu commented 4 years ago

@shaikshavali1 can you investigate this and add your finding here.

hukoyu commented 4 years ago

@prp here is the test run history of fallocate05 test. https://tfsproduks1.visualstudio.com/Ab5352d9a-5ed5-48f2-b767-7f273b55b53c/sgx-lkl/_TestManagement/Runs?runId=28158&resultId=100077&contributionId=ms.vss-test-web.test-result-history&_a=contribution

fallocate05 test was enabled 7 days ago with this PR https://github.com/lsds/sgx-lkl/pull/675

shaikshavali1 commented 4 years ago

@prp

Summary: 1.tst_fill_fs() created 14 files in the error scenario. 2.cleanup() delete a fixed number of files i.e., 13 files. Hence, one file has still remained in the "mntpoint".

Analysis in detail: I tried to reproduce the issue locally but the issue is not reproduced. Observation: This test case invokes "tst_fill_fs" which creates 'n' number of files with random size to fill empty space on the filesystem. This function exit when there is no space on fs.

Link to "tst_fill_fs()": https://github.com/lsds/ltp/blob/933335b9dd6aa730d4803ef2456e6c8081aa57c7/lib/tst_fill_fs.c#L14

This 'n' number of files typically 13 files. which is removed in the cleanup function.

Link to "cleanup()": https://github.com/lsds/ltp/blob/933335b9dd6aa730d4803ef2456e6c8081aa57c7/testcases/kernel/syscalls/fallocate/fallocate05.c#L85

As per the logs shared in the issue description, the "tst_fill_fs" has created 14 files to fill the filesystem space. In PASS scenario "tst_fill_fs" creates 13 files to fill the space in the filesystem.

[[  SGX-LKL ]] libc_start_main_stage2(): Calling app main: /ltp/testcases/kernel/syscalls/fallocate/fallocate05
tst_test.c:1106: INFO: Timeout per run is 0h 05m 00s
tst_test.c:1125: INFO: No fork support
tst_fill_fs.c:29: INFO: Creating file mntpoint/file0 size 53121707
tst_fill_fs.c:29: INFO: Creating file mntpoint/file1 size 30471145
tst_fill_fs.c:29: INFO: Creating file mntpoint/file2 size 98150909
tst_fill_fs.c:29: INFO: Creating file mntpoint/file3 size 91247207
tst_fill_fs.c:29: INFO: Creating file mntpoint/file4 size 23437525
tst_fill_fs.c:29: INFO: Creating file mntpoint/file5 size 18763313
tst_fill_fs.c:29: INFO: Creating file mntpoint/file6 size 3276218
tst_fill_fs.c:29: INFO: Creating file mntpoint/file7 size 17595605
tst_fill_fs.c:29: INFO: Creating file mntpoint/file8 size 14301264
tst_fill_fs.c:29: INFO: Creating file mntpoint/file9 size 4444240
tst_fill_fs.c:29: INFO: Creating file mntpoint/file10 size 20896333
tst_fill_fs.c:29: INFO: Creating file mntpoint/file11 size 98294094
tst_fill_fs.c:29: INFO: Creating file mntpoint/file12 size 70551612
tst_fill_fs.c:49: INFO: write(): ENOSPC (28)
fallocate05.c:51: PASS: write() wrote 8192 bytes
fallocate05.c:60: PASS: fallocate() on full FS: ENOSPC (28)
fallocate05.c:69: PASS: fallocate(FALLOC_FL_PUNCH_HOLE | FALLOC_FL_KEEP_SIZE)
fallocate05.c:75: PASS: write()
[[  SGX-LKL ]] lkl_terminate(): terminating LKL (exit_status=0)
[[  SGX-LKL ]] lkl_termination_thread(): termination thread unblocked
[[  SGX-LKL ]] lkl_termination_thread(): calling lkl_sys_chdir(/)

The cleanup() function removes only 13 files created by "tst_fill_fs" . It left one file in "mntpoint". Because of this reason SAFE_RMDIR of "mntpoint" is causing failure.

Link to problematic code: https://github.com/lsds/ltp/blob/933335b9dd6aa730d4803ef2456e6c8081aa57c7/testcases/kernel/syscalls/fallocate/fallocate05.c#L91

Error Logs (taken from the issue's description):

tst_fill_fs.c:47: [1;31mBROK: [0mwrite(): SUCCESS (0)
safe_macros.c:184: [1;35mWARN: [0mfallocate05.c:91: rmdir(mntpoint) failed: ENOTEMPTY (39)

(cc: @hukoyu)