frequent CI failure of Test

[vtjnash]

https://build.julialang.org/#/builders/79/builds/4064
https://build.julialang.org/#/builders/34/builds/4063
https://build.julialang.org/#/builders/34/builds/4068
https://build.julialang.org/#/builders/4/builds/4066
(and that's just this morning—it seems to have been failing on almost every commit)

Test                               (5) |        started at 2020-09-24T14:54:38.208
Test                               (5) |         failed at 2020-09-24T14:55:28.683
      From worker 5:	�[?25h

Error in testset Test:
Error During Test at none:1
  Test threw exception
  Expression: Test
  Error deserializing a remote exception from worker 5
  Remote(original) exception of type TestSetException
  Remote stacktrace : 
  Stacktrace:
    [1] finish
      @ /buildworker/worker/package_linux32/build/usr/share/julia/stdlib/v1.6/Test/src/Test.jl:877
    [2] macro expansion
      @ /buildworker/worker/package_linux32/build/usr/share/julia/stdlib/v1.6/Test/src/Test.jl:1123 [inlined]
    [3] macro expansion
      @ /buildworker/worker/tester_linux32/build/share/julia/test/testdefs.jl:24 [inlined]
    [4] macro expansion
      @ ./timing.jl:310 [inlined]
    [5] top-level scope
      @ /buildworker/worker/tester_linux32/build/share/julia/test/testdefs.jl:22
    [6] eval
      @ ./boot.jl:360 [inlined]
    [7] #runtests#1
      @ /buildworker/worker/tester_linux32/build/share/julia/test/testdefs.jl:28
    [8] #106
      @ /buildworker/worker/package_linux32/build/usr/share/julia/stdlib/v1.6/Distributed/src/process_messages.jl:294
    [9] run_work_thunk
      @ /buildworker/worker/package_linux32/build/usr/share/julia/stdlib/v1.6/Distributed/src/process_messages.jl:79
   [10] macro expansion
      @ /buildworker/worker/package_linux32/build/usr/share/julia/stdlib/v1.6/Distributed/src/process_messages.jl:294 [inlined]
   [11] #105
      @ ./task.jl:392

``

[StefanKarpinski]

This happens a lot. Do we have any idea what caused this?

[vtjnash]

I don't know exactly what causes it, but can see it's caused by an inability to use the debug logging level, and I know that Artifacts is the culprit of it:

$ JULIA_CPU_THREADS=1 ../julia --depwarn=error runtests.jl Artifacts Test
Test  (Worker) | Time (s) | GC (s) | GC % | Alloc (MB) | RSS (MB)
Artifacts  (1) |        started at 2020-10-01T00:35:55.976
Downloading artifact: c_simple
Downloading artifact: c_simple
Downloading artifact: c_simple
Artifacts  (1) |     8.38 |   0.29 |  3.4 |    1029.71 |   273.76
Test       (1) |        started at 2020-10-01T00:36:04.939
Test       (1) |         failed at 2020-10-01T00:36:40.258
Test Failed at /Users/jameson/julia/usr/share/julia/stdlib/v1.6/Test/test/runtests.jl:772
  Expression: #= /Users/jameson/julia/usr/share/julia/stdlib/v1.6/Test/test/runtests.jl:772 =# @debug "foo"
   Evaluated: Test.LogRecord[]
Test Failed at /Users/jameson/julia/usr/share/julia/stdlib/v1.6/Test/test/runtests.jl:781
  Expression: foo(2)
   Evaluated: Test.LogRecord[Test.LogRecord(Info, "Doing foo with n=2", Main.Test95Main_Test, :runtests, :Main_Test95Main_Test_afc4c2e2, "/Users/jameson/julia/usr/share/julia/stdlib/v1.6/Test/test/runtests.jl", 759, Base.Iterators.Pairs{Union{}, Union{}, Tuple{}, NamedTuple{(), Tuple{}}}())]
Test Failed at /Users/jameson/julia/usr/share/julia/stdlib/v1.6/Test/test/runtests.jl:783
  Expression: foo(10)
   Evaluated: Test.LogRecord[Test.LogRecord(Info, "Doing foo with n=10", Main.Test95Main_Test, :runtests, :Main_Test95Main_Test_afc4c2e2, "/Users/jameson/julia/usr/share/julia/stdlib/v1.6/Test/test/runtests.jl", 759, Base.Iterators.Pairs{Union{}, Union{}, Tuple{}, NamedTuple{(), Tuple{}}}())]

[vtjnash]

Indeed, Artifacts similarly also breaks the logging tests themselves:

$ JULIA_CPU_THREADS=1 ../julia --depwarn=error runtests.jl 
Test    (Worker) | Time (s) | GC (s) | GC % | Alloc (MB) | RSS (MB)
Artifacts    (1) |        started at 2020-10-01T00:41:54.304
Downloading artifact: c_simple
Downloading artifact: c_simple
Downloading artifact: c_simple
Artifacts    (1) |     7.99 |   0.31 |  3.9 |    1029.63 |   288.25
corelogging  (1) |        started at 2020-10-01T00:42:02.805
corelogging  (1) |         failed at 2020-10-01T00:42:05.730
Test Failed at /Users/jameson/julia/test/corelogging.jl:17
  Expression: #= /Users/jameson/julia/test/corelogging.jl:17 =# @debug "a"
   Evaluated: Test.LogRecord[]


Test Summary: | Pass  Fail  Total
  Overall     | 1658     1   1659
    Artifacts | 1429         1429
    corelogging |  229     1    230
    FAILURE

The global RNG seed was 0xff29af588cf393c2b076047d247cef26.

Error in testset corelogging:
Test Failed at /Users/jameson/julia/test/corelogging.jl:17
  Expression: #= /Users/jameson/julia/test/corelogging.jl:17 =# @debug "a"
   Evaluated: Test.LogRecord[]
ERROR: LoadError: Test run finished with errors
in expression starting at /Users/jameson/julia/test/runtests.jl:81

$ git diff
diff --git a/test/choosetests.jl b/test/choosetests.jl
index 887814c6ba..95c50cb034 100644
--- a/test/choosetests.jl
+++ b/test/choosetests.jl
@@ -154,5 +154,6 @@ function choosetests(choices = [])
     # Filter out tests from the test groups in the stdlibs
     filter!(!in(skip_tests), tests)
 
+    tests = ["Artifacts", "corelogging"]
     tests, net_on, exit_on_error, use_revise, seed
 end

[vtjnash]

Slightly simpler:

$ ./julia -q --depwarn=error
julia> using Pkg

julia> Pkg.PlatformEngines.probe_platform_engines!()
true

julia> module TestTest; using Test; @testset "Test" begin; include("stdlib/Test/test/runtests.jl"); end; end