sgx-lkl: [Tests] gettimeofday syscall test hangs with ETHREADS=1

This test fails in sgx-lkl nightly pipeline. In the pipeline it fails since test harness times out after 5 minutes. But when run locally it hangs forever. gettimeofday is called infinitely

Command: SGXLKL_ETHREADS=1 make run-hw-single-gdb test=/ltp/testcases/kernel/syscalls/gettimeofday/gettimeofday02

Output:

 SGXLKL_VERBOSE=1 SGXLKL_KERNEL_VERBOSE=1 SGXLKL_TRACE_LKL_SYSCALL=1 SGXLKL_TRACE_SIGNAL=1 SGXLKL_ETHREADS=1 make run-sw-single test=/ltp/testcases/kernel/syscalls/gettimeofday/gettimeofday02
/mnt/f1/sgx-lkl/build/sgx-lkl-run-oe --sw-debug sgxlkl-miniroot-fs.img /ltp/testcases/kernel/syscalls/gettimeofday/gettimeofday02
[   SGX-LKL  ] SGX-LKL (OE) Git version a674a8f-dirty LKL version 5.3.0 [DEBUG build (-O0)] [SOFTWARE DEBUG]
[   SGX-LKL  ] nproc=4 ETHREADS=1 CMDLINE="mem=32M"
[   SGX-LKL  ] HW TLS support: conf->fsgsbase=0
[   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=/mnt/f1/sgx-lkl/build_musl/./libsgxlkl.so.signed
[   SGX-LKL  ] oe_create_enclave... 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=0x7fe100000000 size=1.042 GB
[[  SGX-LKL ]] sgxlkl_enclave_show_attribute(): enclave heap base=0x7fe100b40000 size=1024.00 M end=0x7fe140b40000
[[  SGX-LKL ]] sgxlkl_enclave_init(): calling _dlstart_c()
[[  SGX-LKL ]] _register_enclave_signal_handlers(): Registering OE exception handler...
[[  SGX-LKL ]] lkl_start_init(): kernel command line: 'mem=32M console=hvc0'
[[  SGX-LKL ]] lkl_start_init(): lkl_start_kernel() called
[    0.000000] Linux version 5.3.0+ (hukoyu@test-8core) (gcc version 7.5.0 (Ubuntu 7.5.0-3ubuntu1~18.04)) #4 Thu Jun 4 21:29:19 UTC 2020
[    0.000000] memblock address range: 0x7fe13e8bf000 - 0x7fe1408bf000
[    0.000000] Built 1 zonelists, mobility grouping on.  Total pages: 8080
[    0.000000] Kernel command line: mem=32M console=hvc0 virtio_mmio.device=256@0x1000000:1
[    0.000000] Dentry cache hash table entries: 4096 (order: 3, 32768 bytes, linear)
[    0.000000] Inode-cache hash table entries: 2048 (order: 2, 16384 bytes, linear)
[    0.000000] mem auto-init: stack:off, heap alloc:off, heap free:off
[    0.000000] Memory available: 32176k/32768k 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.002022] printk: console [hvc0] enabled
[    0.002022] pid_max: default: 4096 minimum: 301
[    0.002022] Mount-cache hash table entries: 512 (order: 0, 4096 bytes, linear)
[    0.002022] Mountpoint-cache hash table entries: 512 (order: 0, 4096 bytes, linear)
[    0.002528] devtmpfs: initialized
[    0.004544] random: get_random_bytes called from 0x00007fe10065f6cc with crng_init=0
[    0.005049] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
[    0.005049] futex hash table entries: 16 (order: -4, 384 bytes, linear)
[    0.005049] xor: automatically using best checksumming function   8regs
[    0.005555] NET: Registered protocol family 16
[    0.006568] clocksource: Switched to clocksource lkl
[    0.006568] NET: Registered protocol family 2
[    0.006568] tcp_listen_portaddr_hash hash table entries: 256 (order: 0, 4096 bytes, linear)
[    0.007097] TCP established hash table entries: 512 (order: 0, 4096 bytes, linear)
[    0.007097] TCP bind hash table entries: 512 (order: 0, 4096 bytes, linear)
[    0.007097] TCP: Hash tables configured (established 512 bind 512)
[    0.007604] UDP hash table entries: 128 (order: 0, 4096 bytes, linear)
[    0.007604] UDP-Lite hash table entries: 128 (order: 0, 4096 bytes, linear)
[    0.007604] NET: Registered protocol family 1
[    0.007604] virtio-mmio: Registering device virtio-mmio.0 at 0x1000000-0x10000ff, IRQ 1.
[    0.008107] workingset: timestamp_bits=62 max_order=14 bucket_order=0
[    0.008614] NET: Registered protocol family 38
[    0.009119] io scheduler mq-deadline registered
[    0.009119] io scheduler kyber registered
[    0.012651] loop: module loaded
[    0.012651] device-mapper: ioctl: 4.40.0-ioctl (2019-01-18) initialised: dm-devel@redhat.com
[    0.013155] wireguard: WireGuard 0.0.20191219 loaded. See www.wireguard.com for information.
[    0.013155] wireguard: Copyright (C) 2015-2019 Jason A. Donenfeld <Jason@zx2c4.com>. All Rights Reserved.
[    0.013155] NET: Registered protocol family 10
[    0.013660] Segment Routing with IPv6
[    0.013660] sit: IPv6, IPv4 and MPLS over IPv4 tunneling driver
[    0.014166] This architecture does not have kernel memory protection.
[    0.014166] 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_virtial()
[[  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
[[ LKL SYSC ]] [tid=1  ] openat 56      (-100, /proc/sys/kernel/random/poolsize, 0, 438) = 3
[[ LKL SYSC ]] [tid=1  ] read   63      (3, 140605429903888, 1024, 0, 0, 0) = 5
[[ LKL SYSC ]] [tid=1  ] openat 56      (-100, /dev/random, 0, 0) = 4
[    0.014670] random: crng init done
[[ LKL SYSC ]] [tid=1  ] ioctl  29      (4, 1074287107, 140605429904928, 0, 0, 0) = 0
[[ LKL SYSC ]] [tid=1  ] close  57      (3, 0, 0, 0, 0, 0) = 0
[[ LKL SYSC ]] [tid=1  ] close  57      (4, 0, 0, 0, 0, 0) = 0
[[  SGX-LKL ]] init_enclave_clock(): Setting enclave realtime clock
[[ LKL SYSC ]] [tid=1  ] openat 56      (-100, /dev/urandom, 0, 0) = 3
[[ LKL SYSC ]] [tid=1  ] read   63      (3, 140605429902776, 32, 0, 0, 0) = 32
[[ LKL SYSC ]] [tid=1  ] close  57      (3, 0, 0, 0, 0, 0) = 0
[[ LKL SYSC ]] [tid=1  ] socket 198     (16, 3, 0, 0, 0, 0) = 3
[[ LKL SYSC ]] [tid=1  ] bind   200     (3, 140605429904420, 12, 0, 0, 0) = 0
[[ LKL SYSC ]] [tid=1  ] getsockname    204     (3, 140605429904420, 140605429902568, 0, 0, 0) = 0
[[ LKL SYSC ]] [tid=1  ] clock_gettime  113     (0, 140605429902560, 0, 0, 0, 0) = 0
[[ LKL SYSC ]] [tid=1  ] sendto 206     (3, 140605383233568, 60, 0, 140604351791216, 12) = 60
[[ LKL SYSC ]] [tid=1  ] recvmsg        212     (3, 140605429902336, 0, 0, 0, 0) = 36
[[ LKL SYSC ]] [tid=1  ] close  57      (3, 0, 0, 0, 0, 0) = 0
[[ LKL SYSC ]] [tid=1  ] socket 198     (16, 3, 16, 0, 0, 0) = 3
[[ LKL SYSC ]] [tid=1  ] bind   200     (3, 140605429904484, 12, 0, 0, 0) = 0
[[ LKL SYSC ]] [tid=1  ] getsockname    204     (3, 140605429904484, 140605429902488, 0, 0, 0) = 0
[[ LKL SYSC ]] [tid=1  ] clock_gettime  113     (0, 140605429902416, 0, 0, 0, 0) = 0
[[ LKL SYSC ]] [tid=1  ] sendto 206     (3, 140605383233568, 36, 0, 140604351791216, 12) = 36
[[ LKL SYSC ]] [tid=1  ] recvmsg        212     (3, 140605429902192, 0, 0, 0, 0) = 112
[[ LKL SYSC ]] [tid=1  ] recvmsg        212     (3, 140605429902192, 0, 0, 0, 0) = 36
[[ LKL SYSC ]] [tid=1  ] clock_gettime  113     (0, 140605429902464, 0, 0, 0, 0) = 0
[[ LKL SYSC ]] [tid=1  ] sendto 206     (3, 140605383233568, 72, 0, 140604351791216, 12) = 72
[[ LKL SYSC ]] [tid=1  ] recvmsg        212     (3, 140605429902272, 0, 0, 0, 0) = 36
[[ LKL SYSC ]] [tid=1  ] close  57      (3, 0, 0, 0, 0, 0) = 0
[[ LKL SYSC ]] [tid=1  ] sethostname    161     (140604356166232, 3, 0, 0, 0, 0) = 0
[[ LKL SYSC ]] [tid=1  ] socket 198     (16, 3, 16, 0, 0, 0) = 4
[[ LKL SYSC ]] [tid=1  ] bind   200     (4, 140605429904612, 12, 0, 0, 0) = 0
[[ LKL SYSC ]] [tid=1  ] getsockname    204     (4, 140605429904612, 140605429902904, 0, 0, 0) = 0
[[ LKL SYSC ]] [tid=1  ] clock_gettime  113     (0, 140605429902832, 0, 0, 0, 0) = 0
[[ LKL SYSC ]] [tid=1  ] sendto 206     (4, 140605383233568, 36, 0, 140604351791216, 12) = 36
[[ LKL SYSC ]] [tid=1  ] recvmsg        212     (4, 140605429902608, 0, 0, 0, 0) = 112
[[ LKL SYSC ]] [tid=1  ] recvmsg        212     (4, 140605429902608, 0, 0, 0, 0) = 36
[[ LKL SYSC ]] [tid=1  ] clock_gettime  113     (0, 140605429902880, 0, 0, 0, 0) = 0
[[ LKL SYSC ]] [tid=1  ] sendto 206     (4, 140605383233568, 28, 0, 140604351791216, 12) = 28
[[ LKL SYSC ]] [tid=1  ] recvmsg        212     (4, 140605429902688, 0, 0, 0, 0) = 144
[[ LKL SYSC ]] [tid=1  ] close  57      (4, 0, 0, 0, 0, 0) = 0
[[  SGX-LKL ]] wg0 has public key KGVeao+U0Z8tu/W0X+FjP8oEU1FpCeQHkPxTO5MC/BY=
[    0.016189] virtio_blk virtio1: [vda] 3072000 512-byte logical blocks (1.57 GB/1.46 GiB)
[    0.049087] software IO TLB: mapped [mem 0x7fe196973000-0x7fe19a973000] (64MB)
[[  SGX-LKL ]] lkl_mount_disk(): lkl_mount_disk(dev="/dev/vda", mnt="/mnt/vda", ro=0)
[    0.050099] EXT4-fs (vda): recovery complete
[    0.050099] EXT4-fs (vda): mounted filesystem with ordered data mode. Opts:
[[  SGX-LKL ]] lkl_mount_disks(): Set working directory: /
[[ LKL SYSC ]] [tid=1  ] openat 56      (-100, /ltp/testcases/kernel/syscalls/gettimeofday/gettimeofday02, 0, 0) = 4
[[ LKL SYSC ]] [tid=1  ] read   63      (4, 140605429901504, 960, 0, 0, 0) = 960
[[ LKL SYSC ]] [tid=1  ] lseek  62      (4, 0, 0, 0, 0, 0) = 0
[[ LKL SYSC ]] [tid=1  ] read   63      (4, 140605378904064, 110592, 0, 0, 0) = 110592
[[ LKL SYSC ]] [tid=1  ] lseek  62      (4, 110592, 0, 0, 0, 0) = 110592
[[ LKL SYSC ]] [tid=1  ] read   63      (4, 140605381111808, 24576, 0, 0, 0) = 24576
[[ LKL SYSC ]] [tid=1  ] close  57      (4, 0, 0, 0, 0, 0) = 0
[[ LKL SYSC ]] [tid=1  ] openat 56      (-100, /ltp/testcases/kernel/syscalls/gettimeofday/gettimeofday02, 0, 0) = 4
[[ LKL SYSC ]] [tid=1  ] prctl  167     (35, 13, 4, 0, 0, 0) = 0
[[ LKL SYSC ]] [tid=1  ] close  57      (4, 0, 0, 0, 0, 0) = 0
[[  SGX-LKL ]] libc_start_main_stage2(): Calling app main: /ltp/testcases/kernel/syscalls/gettimeofday/gettimeofday02
[[ LKL SYSC ]] [tid=1  ] getpid 172     (0, 0, 0, 0, 0, 0) = 36
[[ LKL SYSC ]] [tid=1  ] faccessat      48      (-100, 140605378983790, 0, 0, 0, 0) = 0
[[ LKL SYSC ]] [tid=1  ] getpid 172     (0, 0, 0, 0, 0, 0) = 36
[[ LKL SYSC ]] [tid=1  ] openat 56      (-100, /dev/shm/ltp_gettimeofday02_36, 194, 384) = 4
[[ LKL SYSC ]] [tid=1  ] fchmodat       53      (-100, 140605381120768, 438, 0, 0, 0) = 0
[[ LKL SYSC ]] [tid=1  ] ftruncate      46      (4, 4096, 0, 0, 0, 0) = 0
[[ LKL SYSC ]] [tid=1  ] mmap   222     (0, 4096, 3, 1, 4, 0) = 140605421158400
[[ LKL SYSC ]] [tid=1  ] unlinkat       35      (-100, 140605381120768, 0, 0, 0, 0) = 0
[[ LKL SYSC ]] [tid=1  ] close  57      (4, 0, 0, 0, 0, 0) = 0
[[ LKL SYSC ]] [tid=1  ] rt_sigaction   134     (14, 140605429902016, 140605429901984, 8, 0, 0) = 0
[[ LKL SYSC ]] [tid=1  ] rt_sigaction   134     (10, 140605429902016, 140605429901984, 8, 0, 0) = 0
[[ LKL SYSC ]] [tid=1  ] ioctl  29      (2, 21523, 140605429900944, 0, 0, 0) = 0
tst_test.c:1106: INFO: Timeout per run is 0h 05m 00s
[[ LKL SYSC ]] [tid=1  ] writev 66      (2, 140605429900720, 2, 0, 0, 0) = 64
[[ LKL SYSC ]] [tid=1  ] getpid 172     (0, 0, 0, 0, 0, 0) = 36
[[ LKL SYSC ]] [tid=1  ] setitimer      103     (0, 140605429902384, 140605429902384, 0, 0, 0) = 0
tst_test.c:1125: INFO: No fork support
[[ LKL SYSC ]] [tid=1  ] writev 66      (2, 140605429900784, 2, 0, 0, 0) = 50
[[ LKL SYSC ]] [tid=1  ] rt_sigaction   134     (14, 140605429901920, 140605429901888, 8, 0, 0) = 0
[[ LKL SYSC ]] [tid=1  ] rt_sigaction   134     (10, 140605429901920, 140605429901888, 8, 0, 0) = 0
[[ LKL SYSC ]] [tid=1  ] rt_sigaction   134     (2, 140605429901920, 140605429901888, 8, 0, 0) = 0
[[ LKL SYSC ]] [tid=1  ] setpgid        154     (0, 0, 0, 0, 0, 0) = 0
[[ LKL SYSC ]] [tid=1  ] clock_gettime  113     (1, 140605381122832, 0, 0, 0, 0) = 0
[[ LKL SYSC ]] [tid=1  ] getppid        173     (0, 0, 0, 0, 0, 0) = 1
[[ LKL SYSC ]] [tid=1  ] kill   129     (1, 10, 0, 0, 0, 0) = 0
[[ LKL SYSC ]] [tid=1  ] getpid 172     (0, 0, 0, 0, 0, 0) = 36
[[ LKL SYSC ]] [tid=1  ] rt_sigaction   134     (14, 140605429901952, 140605429901920, 8, 0, 0) = 0
[[ LKL SYSC ]] [tid=1  ] getpid 172     (0, 0, 0, 0, 0, 0) = 36
[[ LKL SYSC ]] [tid=1  ] setitimer      103     (0, 140605429902304, 140605429902304, 0, 0, 0) = 0
[[ LKL SYSC ]] [tid=1  ] gettimeofday   169     (140605429902352, 0, 0, 0, 0, 0) = 0
[[ LKL SYSC ]] [tid=1  ] gettimeofday   169     (140605429902368, 0, 0, 0, 0, 0) = 0
[[ LKL SYSC ]] [tid=1  ] gettimeofday   169     (140605429902368, 0, 0, 0, 0, 0) = 0
[[ LKL SYSC ]] [tid=1  ] gettimeofday   169     (140605429902368, 0, 0, 0, 0, 0) = 0
[[ LKL SYSC ]] [tid=1  ] gettimeofday   169     (140605429902368, 0, 0, 0, 0, 0) = 0
[[ LKL SYSC ]] [tid=1  ] gettimeofday   169     (140605429902368, 0, 0, 0, 0, 0) = 0