RE: Strace

Tamar OK, the first thing I tried was this * cd testsuite/tests/plugins * make Note no “-j”, so this is single threaded. Output is below. Yes, fewer failures, so it does seem that many of the failures I see in a generic test suite run are to do with concurrency. So that’s Bug #1. But even if Bug #1 was solved, I seem to get three failures that happen even in the absence of concurrent testing. This is Bug #2 (or maybe 2,3,4). Happy to run more commands! Simon .../tests/plugins$ make PYTHON="python3" "python3" ../../driver/runtests.py -e "ghc_compiler_always_flags='-dcore-lint -dcmm-lint -no-user-package-db -rtsopts -fno-warn-missed-specialisations -fshow-warning-groups -fdiagnostics-color=never -fno-diagnostics-show-caret -dno-debug-output'" -e config.compiler_debugged=False -e ghc_with_native_codegen=1 -e config.have_vanilla=True -e config.have_dynamic=False -e config.have_profiling=False -e ghc_with_threaded_rts=1 -e ghc_with_dynamic_rts=0 -e config.have_interp=True -e config.unregisterised=False -e config.have_gdb=False -e config.have_readelf=True -e config.ghc_dynamic_by_default=False -e config.ghc_dynamic=False -e ghc_with_smp=1 -e ghc_with_llvm=0 -e windows=True -e darwin=False -e config.in_tree_compiler=True -e config.cleanup=True -e config.local=True --rootdir=. --config-file=../../config/ghc -e 'config.confdir="../../config"' -e 'config.platform="x86_64-unknown-mingw32"' -e 'config.os="mingw32"' -e 'config.arch="x86_64"' -e 'config.wordsize="64"' -e 'config.timeout=int() or config.timeout' -e 'config.exeext=".exe"' -e 'config.top="/c/code/HEAD/testsuite"' --config 'compiler="/c/code/HEAD/inplace/bin/ghc-stage2.exe"' --config 'ghc_pkg="/c/code/HEAD/inplace/bin/ghc-pkg.exe"' --config 'haddock=' --config 'hp2ps="/c/code/HEAD/inplace/bin/hp2ps.exe"' --config 'hpc="/c/code/HEAD/inplace/bin/hpc.exe"' --config 'gs="gs"' --config 'timeout_prog="../../timeout/install-inplace/bin/timeout.exe"' -e "config.stage=2" \ \ \ \ \ \ \ Timeout is 300 Found 1 .T files... Beginning test run at Mon Jun 18 11:24:57 2018 GMTST --- ./plugins09.run/plugins09.stdout.normalised 2018-06-18 11:27:47.971987800 +0100 +++ ./plugins09.run/plugins09.run.stdout.normalised 2018-06-18 11:27:47.972177400 +0100 @@ -1,9 +0,0 @@ -parsePlugin(a,b) -interfacePlugin: Prelude -interfacePlugin: GHC.Float -interfacePlugin: GHC.Base -interfacePlugin: GHC.Types -typeCheckPlugin (rn) -typeCheckPlugin (tc) -interfacePlugin: GHC.Integer.Type -interfacePlugin: GHC.Natural --- ./plugins11.run/plugins11.stdout.normalised 2018-06-18 11:28:40.307222400 +0100 +++ ./plugins11.run/plugins11.run.stdout.normalised 2018-06-18 11:28:40.307675400 +0100 @@ -1,9 +0,0 @@ -parsePlugin() -interfacePlugin: Prelude -interfacePlugin: GHC.Float -interfacePlugin: GHC.Base -interfacePlugin: GHC.Types -typeCheckPlugin (rn) -typeCheckPlugin (tc) -interfacePlugin: GHC.Integer.Type -interfacePlugin: GHC.Natural --- ./T11244.run/T11244.stderr.normalised 2018-06-18 11:32:21.142334600 +0100 +++ ./T11244.run/T11244.run.stderr.normalised 2018-06-18 11:32:21.145148100 +0100 @@ -1,4 +1,4 @@ -<command line>: Could not load module ‘RuleDefiningPlugin’ +<command line>: Could not find module ‘RuleDefiningPlugin’ It is a member of the hidden package ‘rule-defining-plugin-0.1’. You can run ‘:set -package rule-defining-plugin’ to expose it. (Note: this unloads all the modules in the current scope.) ====> Scanning ./all.T =====> plugins01(normal) 1 of 25 [0, 0, 0] cd "./plugins01.run" && $MAKE -s --no-print-directory -C simple-plugin package.plugins01 TOP=/c/code/HEAD/testsuite cd "./plugins01.run" && $MAKE -s --no-print-directory plugins01 =====> plugins02(normal) 2 of 25 [0, 0, 0] cd "./plugins02.run" && $MAKE -s --no-print-directory -C simple-plugin package.plugins02 TOP=/c/code/HEAD/testsuite cd "./plugins02.run" && "/c/code/HEAD/inplace/bin/ghc-stage2.exe" -c plugins02.hs -dcore-lint -dcmm-lint -no-user-package-db -rtsopts -fno-warn-missed-specialisations -fshow-warning-groups -fdiagnostics-color=never -fno-diagnostics-show-caret -dno-debug-output -package-db simple-plugin/pkg.plugins02/local.package.conf -fplugin Simple.BadlyTypedPlugin -package simple-plugin -static =====> plugins03(normal) 3 of 25 [0, 0, 0] cd "./plugins03.run" && $MAKE -s --no-print-directory -C simple-plugin package.plugins03 TOP=/c/code/HEAD/testsuite cd "./plugins03.run" && "/c/code/HEAD/inplace/bin/ghc-stage2.exe" -c plugins03.hs -dcore-lint -dcmm-lint -no-user-package-db -rtsopts -fno-warn-missed-specialisations -fshow-warning-groups -fdiagnostics-color=never -fno-diagnostics-show-caret -dno-debug-output -package-db simple-plugin/pkg.plugins03/local.package.conf -fplugin Simple.NonExistentPlugin -package simple-plugin =====> plugins04(normal) 4 of 25 [0, 0, 0] cd "./plugins04.run" && "/c/code/HEAD/inplace/bin/ghc-stage2.exe" --make plugins04 -dcore-lint -dcmm-lint -no-user-package-db -rtsopts -fno-warn-missed-specialisations -fshow-warning-groups -fdiagnostics-color=never -fno-diagnostics-show-caret -dno-debug-output -package ghc -fplugin HomePackagePlugin =====> plugins05(normal) 5 of 25 [0, 0, 0] cd "./plugins05.run" && "/c/code/HEAD/inplace/bin/ghc-stage2.exe" --make -o plugins05 plugins05 -dcore-lint -dcmm-lint -no-user-package-db -rtsopts -fno-warn-missed-specialisations -fshow-warning-groups -fdiagnostics-color=never -fno-diagnostics-show-caret -dno-debug-output -package ghc cd "./plugins05.run" && ./plugins05 =====> plugins07(normal) 7 of 25 [0, 0, 0] cd "./plugins07.run" && $MAKE -s --no-print-directory -C rule-defining-plugin package.plugins07 TOP=/c/code/HEAD/testsuite cd "./plugins07.run" && $MAKE -s --no-print-directory plugins07 =====> plugins08(normal) 8 of 25 [0, 0, 0] cd "./plugins08.run" && $MAKE -s --no-print-directory -C simple-plugin package.plugins08 TOP=/c/code/HEAD/testsuite cd "./plugins08.run" && $MAKE -s --no-print-directory plugins08 =====> plugins09(normal) 9 of 25 [0, 0, 0] cd "./plugins09.run" && $MAKE -s --no-print-directory -C simple-plugin package.plugins09 TOP=/c/code/HEAD/testsuite cd "./plugins09.run" && $MAKE -s --no-print-directory plugins09 Actual stdout output differs from expected: diff -uw "./plugins09.run/plugins09.stdout.normalised" "./plugins09.run/plugins09.run.stdout.normalised" *** unexpected failure for plugins09(normal) =====> plugins10(normal) 10 of 25 [0, 1, 0] cd "./plugins10.run" && $MAKE -s --no-print-directory -C simple-plugin package.plugins10 TOP=/c/code/HEAD/testsuite cd "./plugins10.run" && $MAKE -s --no-print-directory plugins10 =====> plugins11(normal) 11 of 25 [0, 1, 0] cd "./plugins11.run" && $MAKE -s --no-print-directory -C simple-plugin package.plugins11 TOP=/c/code/HEAD/testsuite cd "./plugins11.run" && $MAKE -s --no-print-directory plugins11 Actual stdout output differs from expected: diff -uw "./plugins11.run/plugins11.stdout.normalised" "./plugins11.run/plugins11.run.stdout.normalised" *** unexpected failure for plugins11(normal) =====> plugins12(normal) 12 of 25 [0, 2, 0] cd "./plugins12.run" && $MAKE -s --no-print-directory -C simple-plugin package.plugins12 TOP=/c/code/HEAD/testsuite cd "./plugins12.run" && $MAKE -s --no-print-directory plugins12 =====> plugins13(normal) 13 of 25 [0, 2, 0] cd "./plugins13.run" && $MAKE -s --no-print-directory -C simple-plugin package.plugins13 TOP=/c/code/HEAD/testsuite cd "./plugins13.run" && $MAKE -s --no-print-directory plugins13 =====> plugins14(normal) 14 of 25 [0, 2, 0] cd "./plugins14.run" && $MAKE -s --no-print-directory -C simple-plugin package.plugins14 TOP=/c/code/HEAD/testsuite cd "./plugins14.run" && $MAKE -s --no-print-directory plugins14 =====> plugins15(normal) 15 of 25 [0, 2, 0] cd "./plugins15.run" && $MAKE -s --no-print-directory -C simple-plugin package.plugins15 TOP=/c/code/HEAD/testsuite cd "./plugins15.run" && $MAKE -s --no-print-directory plugins15 =====> T10420(normal) 16 of 25 [0, 2, 0] cd "./T10420.run" && $MAKE -s --no-print-directory -C rule-defining-plugin package.T10420 TOP=/c/code/HEAD/testsuite cd "./T10420.run" && $MAKE -s --no-print-directory T10420 =====> T10294(normal) 17 of 25 [0, 2, 0] cd "./T10294.run" && $MAKE -s --no-print-directory -C annotation-plugin package.T10294 TOP=/c/code/HEAD/testsuite cd "./T10294.run" && $MAKE -s --no-print-directory T10294 =====> T10294a(normal) 18 of 25 [0, 2, 0] cd "./T10294a.run" && $MAKE -s --no-print-directory -C annotation-plugin package.T10294a TOP=/c/code/HEAD/testsuite cd "./T10294a.run" && $MAKE -s --no-print-directory T10294a =====> frontend01(normal) 19 of 25 [0, 2, 0] cd "./frontend01.run" && $MAKE -s --no-print-directory frontend01 =====> T11244(normal) 20 of 25 [0, 2, 0] cd "./T11244.run" && $MAKE -s --no-print-directory -C rule-defining-plugin package.T11244 TOP=/c/code/HEAD/testsuite cd "./T11244.run" && $MAKE -s --no-print-directory T11244 Actual stderr output differs from expected: diff -uw "./T11244.run/T11244.stderr.normalised" "./T11244.run/T11244.run.stderr.normalised" *** unexpected failure for T11244(normal) =====> T12567a(normal) 21 of 25 [0, 3, 0] cd "./T12567a.run" && $MAKE -s --no-print-directory -C simple-plugin package.T12567a TOP=/c/code/HEAD/testsuite cd "./T12567a.run" && $MAKE -s --no-print-directory T12567a =====> T14335(normal) 22 of 25 [0, 3, 0] cd "./T14335.run" && $MAKE -s --no-print-directory -C simple-plugin package.plugins01 TOP=/c/code/HEAD/testsuite cd "./T14335.run" && "/c/code/HEAD/inplace/bin/ghc-stage2.exe" -c T14335.hs -dcore-lint -dcmm-lint -no-user-package-db -rtsopts -fno-warn-missed-specialisations -fshow-warning-groups -fdiagnostics-color=never -fno-diagnostics-show-caret -dno-debug-output -package-db simple-plugin/pkg.plugins01/local.package.conf -fplugin Simple.Plugin -fexternal-interpreter -package simple-plugin -static =====> plugin-recomp-pure(normal) 23 of 25 [0, 3, 0] cd "./plugin-recomp-pure.run" && $MAKE -s --no-print-directory -C plugin-recomp package.plugins01 TOP=/c/code/HEAD/testsuite cd "./plugin-recomp-pure.run" && $MAKE -s --no-print-directory plugin-recomp-pure =====> plugin-recomp-impure(normal) 24 of 25 [0, 3, 0] cd "./plugin-recomp-impure.run" && $MAKE -s --no-print-directory -C plugin-recomp package.plugins01 TOP=/c/code/HEAD/testsuite cd "./plugin-recomp-impure.run" && $MAKE -s --no-print-directory plugin-recomp-impure =====> plugin-recomp-flags(normal) 25 of 25 [0, 3, 0] cd "./plugin-recomp-flags.run" && $MAKE -s --no-print-directory -C plugin-recomp package.plugins01 TOP=/c/code/HEAD/testsuite cd "./plugin-recomp-flags.run" && $MAKE -s --no-print-directory plugin-recomp-flags Unexpected results from: TEST="T11244 plugins09 plugins11" SUMMARY for test run started at Mon Jun 18 11:24:57 2018 GMTST 0:11:18 spent to go through 25 total tests, which gave rise to 35 test cases, of which 11 were skipped 0 had missing libraries 19 expected passes 2 expected failures 0 caused framework failures 0 caused framework warnings 0 unexpected passes 3 unexpected failures 0 unexpected stat failures Unexpected failures: plugins09.run plugins09 [bad stdout] (normal) plugins11.run plugins11 [bad stdout] (normal) T11244.run T11244 [bad stderr] (normal) make: *** [../../mk/test.mk:329: test] Error 1 .../tests/plugins$ From: Phyx Sent: 13 June 2018 20:47 To: Simon Peyton Jones Cc: ghc-devs@haskell.org Subject: Re: Strace Hi Simon, On Wed, Jun 13, 2018 at 5:24 PM, Simon Peyton Jones mailto:simonpj@microsoft.com> wrote: OK – so maybe the root cause is a framework failure – and indeed for the last few weeks I’ve seen Framework failures: plugins/plugins07.run plugins07 [normal] (pre_cmd failed: 2) plugins/T10420.run T10420 [normal] (pre_cmd failed: 2) plugins/T11244.run T11244 [normal] (pre_cmd failed: 2) I have just learned to live with these failures, because I knew you were working on making things better. But it sounds as if they are still taking place. The commit I made should have reduced the amount of failing tests to 0. framework failures are always quite unusual. So: * Yes, please make it not happen by default I've removed the code, if you update it should be gone. It was there and on by default because I was trying to debug failures on Harbormaster, I realized a switch isn't very useful as I won't be able to toggle it for Harbormaster anyway. * * If you don’t get these framework failures, can we work together to resolve them? These don't happen for me nor on Harbormaster, try picking a test, e.g T10420 run only that test to make sure it's not a threading issue: make TEST=T10420 test -C testsuite/tests If it still gives a framework error then do at the top level make VERBOSE=3 TEST=T10420 test -C testsuite/tests once it runs, the output should contain the command it ran as a pre_cmd, and the stdout and stderr from the pre_cmd output. Could you then send the error? if it doesn't show any of this, try make CLEANP=0 VERBOSE=3 TEST= T10420 test -C testsuite/tests --trace and copy and paste the pre_cmd command, which should just replay the action it did. Cheers, Tamar Thanks Simon From: Phyx mailto:lonetiger@gmail.com> Sent: 13 June 2018 17:19 To: Simon Peyton Jones mailto:simonpj@microsoft.com> Cc: ghc-devs@haskell.orgmailto:ghc-devs@haskell.org Subject: Re: Strace Hi Simon, The strace is only supposed to run when the normal test pre_cmd fails. If it's running that often it means your tests are all failing during pre_cmd with a framework failure https://git.haskell.org/ghc.git/blobdiff/4778cba1dbb6adf495930322d7f9e9db0af... But maybe I shouldn't turn this on my default. I'll pramaterize it when I get home. Tamar. On Wed, Jun 13, 2018, 17:09 Simon Peyton Jones mailto:simonpj@microsoft.com> wrote: Tamar I’m getting megabytes of output from ‘sh validate’ on windows. It looks like this 629 151745 [main] sh 2880 fhandler_base::fhaccess: returning 0 291 152036 [main] sh 2880 faccessat: returning 0 7757 159793 [main] sh 2880 fhandler_base_overlapped::wait_overlapped: wfres 0, wores 1, bytes 7 179457 1608947 [main] make 11484 fhandler_base_overlapped::wait_overlapped: wfres 0, wores 1, bytes 7 99 159892 [main] sh 2880 fhandler_base_overlapped::wait_overlapped: normal write, 7 bytes ispipe() 1 180 1609127 [main] make 11484 fhandler_base_overlapped::wait_overlapped: normal read, 7 bytes ispipe() 1 139 160031 [main] sh 2880 write: 7 = write(1, 0x6000396A0, 7) 142 1609269 [main] make 11484 fhandler_base::read: returning 7, binary mode 139 1609408 [main] make 11484 read: 7 = read(5, 0x60005B4B0, 7) 136 1609544 [main] make 11484 read: read(5, 0x60005B4B7, 193) blocking 4693 164724 [main] sh 2880 set_signal_mask: setmask 0, newmask 80000, mask_bits 0 but with hundreds of thousands of lines. (I have not counted) I believe that it may be the result of this line, earlier in the log cd "/c/Users/simonpj/AppData/Local/Temp/ghctest-8fa9s6rk/test spaces/./plugins/plugins07.run" && strace $MAKE -s --no-print-directory -C rule-defining-plugin package.plugins07 TOP=/c/code/HEAD/testsuite# Note the strace. That in turn was added in your commit commit 60fb2b2160aa16194b74262f4df8fad5af171b0f Author: Tamar Christina mailto:tamar@zhox.com> Date: Mon May 28 19:34:11 2018 +0100 Clean up Windows testsuite failures Summary: Another round and attempt at getting these down to 0. Could you perhaps have made a mistake here? Currently validate is unusable. Thanks! Simon