Lwt: test failure on armv7l

[olafhering]

ocaml-lwt on openSUSE_Tumbleweed/armv7l:

[ 193s] Command [81] exited with code 1: [ 193s] $ (cd _build/default/test/unix && ./main.exe) [ 193s] Testing library 'unix'... [ 193s] ..............................FF.............S........S.........SSS........................FF..........FF......................................................................SS.FFFF..F.S.S................F.FFF..FF. [ 193s] times: 1585732969.096655 0.000000 0.000000 [ 193s] start_time: 1585732970.248753, duration: 0.000000 [ 193s] [ 193s] 0.025127 0.025124 [ 193s] Test 'utimes: basic' in suite 'lwt_unix' produced 'false' [ 193s] Test 'utimes: current time' in suite 'lwt_unix' produced 'false' [ 193s] Test 'NumberIO.LE.read_float32' in suite 'lwt_io' produced 'false' [ 193s] Test 'NumberIO.BE.read_float32' in suite 'lwt_io' produced 'false' [ 193s] Test 'NumberIO.LE.write_float32' in suite 'lwt_io' produced 'false' [ 193s] Test 'NumberIO.BE.write_float32' in suite 'lwt_io' produced 'false' [ 193s] Test 'basic' in suite 'Lwt_timeout' produced 'false' [ 193s] Test 'double start' in suite 'Lwt_timeout' produced 'false' [ 193s] Test 'change' in suite 'Lwt_timeout' produced 'false' [ 193s] Test 'change after start' in suite 'Lwt_timeout' produced 'false' [ 193s] Test 'two' in suite 'Lwt_timeout' produced 'false' [ 193s] Test 'simultaneous' in suite 'Lwt_timeout' produced 'false' [ 193s] Test 'two, first stopped' in suite 'Lwt_timeout' produced 'false' [ 193s] Test 'sleep' in suite 'Lwt_unix sleep and timeout' produced 'false' [ 193s] Test 'timeout' in suite 'Lwt_unix sleep and timeout' produced 'false' [ 193s] Test 'with_timeout : timeout' in suite 'Lwt_unix sleep and timeout' produced 'false' [ 193s] Test 'auto_yield' in suite 'Lwt_unix sleep and timeout' produced 'false' [ 193s] + echo 'dune runtest failed' [ 193s] dune runtest failed [ 193s] + test -n '' [ 193s] + echo aborting [ 193s] aborting [ 193s] + exit 1 [ 193s] error: Bad exit status from /var/tmp/rpm-tmp.2vTcYD (%check)

According to the job history, there was at least one successful build a couple of weeks ago, with version 5.1.2. Even that one failed after a few days. It seems the failures start with the upgrade from ocaml 4.05 to 4.10. There are no logs for previous failures.

Just asking for more diagnostics.

The VM itself seems to run on aarch64, according to the build log:
[ 35s] linux64 /usr/bin/qemu-system-arm -nodefaults -no-reboot -nographic -vga none -cpu host -enable-kvm -M virt -object rng-random,filename=/dev/random,id=rng0 -device virtio-rng-device,rng=rng0 -runas qemu -mem-prealloc -mem-path /dev/hugepages -net none -kernel /var/cache/obs/worker/root_2/.mount/boot/kernel -initrd /var/cache/obs/worker/root_2/.mount/boot/initrd -append root=/dev/disk/by-id/virtio-0 rootfstype=ext4 rootflags=noatime ext4.allow_unsupported=1 kpti=off pti=off spectre_v2=off panic=1 quiet no-kvmclock elevator=noop nmi_watchdog=0 rw rd.driver.pre=binfmt_misc console=ttyAMA0 init=/.build/build -m 1020 -drive file=/var/cache/obs/worker/root_2/root,format=raw,if=none,id=disk,cache=unsafe -device virtio-blk-device,drive=disk,serial=0 -drive file=/var/cache/obs/worker/root_2/swap,format=raw,if=none,id=swap,cache=unsafe -device virtio-blk-device,drive=swap,serial=1 -serial stdio -chardev socket,id=monitor,server,nowait,path=/var/cache/obs/worker/root_2/root.qemu/monitor -mon chardev=monitor,mode=readline -smp 1

[aantron]

I added instrumentation in the linked commit. Could you try the tests again with the current master?

[olafhering]

There is either something wrong with arm32, or it just takes too long within such VM:

ocaml-benchmark [ 84s] Command [10] exited with code 2: [ 84s] $ (cd _build/default/tests && ./long_run.exe) [ 84s] Throughputs for "long" running for at least 1 CPU second: [ 84s] long: 2.12 WALL ( 2.12 usr 0.00 sys + 0.00 cusr 0.00 csys = 2.12 CPU) @ 0.47/s (n=1) [ 84s] (warning: too few iterations for a reliable count) [ 84s] Fatal error: exception Invalid_argument("Benchmark.tabulate: confidence < 0. or > 1.")
ocaml-biniou (might be wrong assumptions about float layout) [ 63s] Command [6] exited with code 2: [ 63s] $ (cd _build/default/test && ./test_biniou.exe) [ 63s] Fatal error: exception File "src/bi_io.ml", line 212, characters 11-17: Assertion failed

[olafhering]

I added instrumentation in the linked commit. Could you try the tests again with the current master?

Thanks, I have added the changes. Now we need to wait until arm32 builds again.

[olafhering]

[ 205s] ............................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................SSSSSSSSSSSSSSSSSSSSSSS........................................................................................................ [ 205s] Ok. 628 tests ran, 23 tests skipped in 0.10 seconds [ 210s] Command [81] exited with code 1: [ 210s] $ (cd _build/default/test/unix && ./main.exe) [ 210s] Testing library 'unix'... [ 210s] .................................SSSSS................ [ 210s] NumberIO.LE.read_float32: 0.000000 [ 210s] F [ 210s] NumberIO.BE.read_float32: 0.000000 [ 210s] F.......... [ 210s] NumberIO.LE.write_float32: 00 00 80 7F [ 210s] F [ 210s] NumberIO.BE.write_float32: 7F 80 00 00 [ 210s] F............................................................. [ 210s] utimes: basic: 0.000000 0.000000 [ 210s] F.........................SS..... [ 210s] utimes: current time: 1585896417.042198 0.000000 0.000000 [ 210s] F........... [ 210s] Lwt_unix sleep and timeout: auto_yield: false false false false false [ 210s] F [ 210s] Lwt_unix sleep and timeout: with_timeout : timeout: 0.043150 [ 210s] F [ 210s] Lwt_unix sleep and timeout: timeout: 0.043323 [ 210s] F [ 210s] Lwt_unix sleep and timeout: sleep: 0.043425 [ 210s] F.. [ 210s] Lwt_timeout: double start: 0 [ 210s] F.S........S..... [ 210s] Lwt_timeout: simultaneous: 1585896418.089491 0.064616 0.064615 [ 210s] F. [ 210s] Lwt_timeout: change after start: 1585896418.089367 0.064831 [ 210s] F [ 210s] Lwt_timeout: change: 1585896418.089318 0.064904 [ 210s] F [ 210s] Lwt_timeout: basic: 1585896418.088922 0.065302 [ 210s] F.......... [ 210s] Lwt_timeout: two, first stopped: true 1585896418.089518 0.703038 [ 210s] F [ 210s] Lwt_timeout: two: 1585896418.089466 0.064730 0.703220 [ 210s] F. [ 210s] Test 'utimes: basic' in suite 'lwt_unix' produced 'false' [ 210s] Test 'utimes: current time' in suite 'lwt_unix' produced 'false' [ 210s] Test 'NumberIO.LE.read_float32' in suite 'lwt_io' produced 'false' [ 210s] Test 'NumberIO.BE.read_float32' in suite 'lwt_io' produced 'false' [ 210s] Test 'NumberIO.LE.write_float32' in suite 'lwt_io' produced 'false' [ 210s] Test 'NumberIO.BE.write_float32' in suite 'lwt_io' produced 'false' [ 210s] Test 'basic' in suite 'Lwt_timeout' produced 'false' [ 210s] Test 'double start' in suite 'Lwt_timeout' produced 'false' [ 210s] Test 'change' in suite 'Lwt_timeout' produced 'false' [ 210s] Test 'change after start' in suite 'Lwt_timeout' produced 'false' [ 210s] Test 'two' in suite 'Lwt_timeout' produced 'false' [ 210s] Test 'simultaneous' in suite 'Lwt_timeout' produced 'false' [ 210s] Test 'two, first stopped' in suite 'Lwt_timeout' produced 'false' [ 210s] Test 'sleep' in suite 'Lwt_unix sleep and timeout' produced 'false' [ 210s] Test 'timeout' in suite 'Lwt_unix sleep and timeout' produced 'false' [ 210s] Test 'with_timeout : timeout' in suite 'Lwt_unix sleep and timeout' produced 'false' [ 210s] Test 'auto_yield' in suite 'Lwt_unix sleep and timeout' produced 'false' [ 210s] + echo 'dune runtest failed' [ 210s] dune runtest failed [ 210s] + test -n '' [ 210s] + echo aborting [ 210s] aborting [ 210s] + exit 1 [ 210s] error: Bad exit status from /var/tmp/rpm-tmp.JUxM5Z (%check)

[aantron]

Ok, these results suggest real underlying problems, and need genuine debugging on the target platform, which I don't have access to.

• The two read_float32 tests should not produce zero. Can you experiment with code like this? The module Endian is from ocplib-endian.

  https://github.com/ocsigen/lwt/blob/b81ebbf786ca1129b8d5ab6decd0ca2c1da0275b/src/unix/lwt_io.ml#L1004-L1015

• Likewise, the two write_float32 tests seem to produce completely incorrect results.

  https://github.com/ocsigen/lwt/blob/b81ebbf786ca1129b8d5ab6decd0ca2c1da0275b/src/unix/lwt_io.ml#L1035-L1047

• The failures in the two utimes tests suggest that either Lwt_unix.utimes or Unix.stat isn't working on the target platform, because stat is returning the times as zero. Here is the simpler test:

  https://github.com/ocsigen/lwt/blob/b81ebbf786ca1129b8d5ab6decd0ca2c1da0275b/test/unix/test_lwt_unix.cppo.ml#L138-L148

  and the two functions:

  https://github.com/ocaml/ocaml/blob/1d76e2ca91633ac63759c4672e9a8dddabac8a31/otherlibs/unix/stat.c#L81

  https://github.com/ocsigen/lwt/blob/master/src/unix/unix_c/unix_utimes_job.c

• The remaining tests are timing tests, and the output suggests that Lwt time delays aren't working at all. I added more instrumentation to these tests, including displaying whether libev is present, because the time delay engine is different between the select(2)-based loop and the libev-based loop.

  Could you run a program like

  let () =
    let now = Unix.gettimeofday () in
    Lwt_main.run (Lwt_unix.sleep 1.);
    Printf.printf "%f\n" (Unix.gettimeofday () -. now)
  

  (executable
    (name foo)
    (libraries lwt.unix))
  

  dune exec ./foo.exe
  

  Does this print a value greater than 1?

[olafhering]

It happens to work with ocaml-4.05 and ocaml-4.07.
Failed with 4.08, have to see where it broke in ocaml.git.

[olafhering]

I guess this can be closed as "not a bug in lwt".

[aantron]

Thanks for investigating that. I suppose all the observed issues were due to problems with floating-point numbers.