Heisenbug in "test guarded Random.seed!"

[tkf]

Just as a record, I saw:

Error in testset Test:
Test Failed at /buildworker/worker/tester_linuxaarch64/build/share/julia/stdlib/v1.8/Test/test/runtests.jl:777
  Expression: orig == Random.default_rng()
   Evaluated: Xoshiro(0x947b9af2ba269897, 0x95ae8d9a31382b32, 0x8a532dc2baa61f2e, 0x7213512241a4dfbd) == TaskLocalRNG()
Error in testset Test:
Test Failed at /buildworker/worker/tester_linuxaarch64/build/share/julia/stdlib/v1.8/Test/test/runtests.jl:778
  Expression: rand(orig) == rand()
   Evaluated: 0.6209946085911393 == 0.7846500004305739

https://build.julialang.org/#/builders/7/builds/4863/steps/5/logs/stdio

in #42725. It vanished after re-running the test by merging master even though there doesn't seem a change that could fix the result a4903fd...76c2431.

[vtjnash]

I thought I was seeing this quite a bit on builds at random this week

[tkf]

Is it architecture-specific?

[Seelengrab]

When I run the test in question with the global seed given from the build log, I get the same result as the orig Xoshiro on the left:

julia> function testfun()
           Random.seed!(0x2f5d1b5dc893fdf5ee2a1080933cd16d)
           @testset "test guarded Random.seed!" begin
           seed = rand(UInt)
           orig = copy(Random.default_rng())
           @test guardseed(()->rand(), seed) == guardseed(()->rand(),
           seed)
           @test guardseed(()->rand(Int), seed) ==
           guardseed(()->rand(Int), seed)
           r1, r2 = MersenneTwister(0), MersenneTwister(0)
           a, b = guardseed(r1) do
               Random.seed!(r1, 0)
               rand(r1), rand(r1, Int)
           end::Tuple{Float64,Int}
           c, d = guardseed(r2) do
               Random.seed!(r2, 0)
               rand(r2), rand(r2, Int)
           end::Tuple{Float64,Int}
           @test a == c == rand(r1) == rand(r2)
           @test b == d == rand(r1, Int) == rand(r2, Int)
           @show orig
           @show Random.default_rng()
           @test orig == Random.default_rng()
           @test rand(orig) == rand()
       end
       end
testfun (generic function with 1 method)

julia> testfun()
orig = Xoshiro(0x947b9af2ba269897, 0x95ae8d9a31382b32, 0x8a532dc2baa61f2e, 0x7213512241a4dfbd)
Random.default_rng() = TaskLocalRNG()
Test Summary:             | Pass  Total
test guarded Random.seed! |    6      6
Test.DefaultTestSet("test guarded Random.seed!", Any[], 6, false, false)

Sadly we don't have the other internal state in the log :/ I checked all combinations of 2 flipped bits, so 65536 RNGs, but none showed a match. We do have the result of the next rand call though, so we could try to reconstruct the internal state of the task local RNG that way. Unfortunately, Symbolics.jl doesn't support << on Num and I'm not well versed in Z3 🤷

We'd basically have to solve this:

s0::UInt, s3::UInt
tmp = s0 + s3
res = (((tmp << 23) | (tmp >> 41)) + s0) >> 11
res == 0x00191bda5154fb80

which I got by seeing that the random values are generated via x = rand(rng, UInt); Float64(x >> 11) * 0x1.0p-53. Since we have a floating point result, we can easily invert everything up to x = by doing UInt(0.7846500004305739 / 0x1.0p-53) (I checked that this works by making sure that it works for the other floating point value generated by orig), giving us the above hex number 0x00191bda5154fb80. Still, I can tell you that in s0 and s3 only the following bits matter, from MSB to LSB:

• 13 - matter
• 10 - don't matter
• 41 - matter

This is due to the >> 11 at the end and propagating that requirement through everything, as long as bit 51 is set so that it "works" in s0 and s3.

[nalimilan]

FWIW I also saw it with 1.7.0-rc2 on x86_64, but with different values:

Test Failed at /builddir/build/BUILD/julia-1.7.0-rc2/build/usr/share/julia/stdlib/v1.7/Test/test/runtests.jl:741
  Expression: orig == Random.default_rng()
   Evaluated: Xoshiro(0x98eb785bda6da52d, 0xa71f2324bc045d76, 0x9739d712cfb7c053, 0xa001e265c6af9015) == TaskLocalRNG()
Error in testset Test:
Test Failed at /builddir/build/BUILD/julia-1.7.0-rc2/build/usr/share/julia/stdlib/v1.7/Test/test/runtests.jl:742
  Expression: rand(orig) == rand()
   Evaluated: 0.9755253173603154 == 0.45116343295850014

https://kojipkgs.fedoraproject.org//work/tasks/9369/77709369/build.log

(This was the first time I built 1.7.0-rc2 so it may not be so rare.)

[KristofferC]

Maybe something to do with #42201? Although that was a while ago.

[Seelengrab]

If we modify the test here to show the true state of Random.default_rng(), it will be much easier to debug because we can more easily distinguish bitflips from whole bytes missing etc. I doubt that it's a problem with our Xoshiro, since then I wouldn't be able to make the tests run through when running them with the same seed locally.

I tried to debug this by letting Z3 spit out a bunch of number pairs that would create those values, but there wasn't really a pattern in them. Please excuse the bad quality - I hadn't yet setup my screenshotting tool.

Picture of histogram

This screenshot shows the number of times a bit flip had to have occured in the generated numbers in each nibble (4-bit group) of each UInt. Z3 spit out 15 values with exactly 9 bitflips (non-consecutive) and didn't find any possible values with fewer. The largest number of bitflips possible to still find solutions is 18 (but again no pattern in those).

[Seelengrab]

Is this expected/related behavior?

[sukera@tempman ~]$ julia -q -t1
julia> t = current_task()
Task (runnable) @0x00007f6723fdc010

julia> state = (t.rngState0, t.rngState1, t.rngState2, t.rngState3)
(0xf6e7025b1a108853, 0x1949f9d36755c8cf, 0xdc13b6c30461a2b5, 0xb199766836484420)

julia> using Random

julia> copy(Random.default_rng()) # yep, same state as the rng in our task
Xoshiro(0xf6e7025b1a108853, 0x1949f9d36755c8cf, 0xdc13b6c30461a2b5, 0xb199766836484420)

julia> Random.default_rng()
TaskLocalRNG()

julia> function Base.show(io::IO, ::MIME"text/plain", x::Random.TaskLocalRNG)
           t = current_task()
           write(io, "TaskLocalRNG(")
           show(io, MIME"text/plain"(), t.rngState0)
           write(io, ',')
           show(io, MIME"text/plain"(), t.rngState1)
           write(io, ',')
           show(io, MIME"text/plain"(), t.rngState2)
           write(io, ',')
           show(io, MIME"text/plain"(), t.rngState3)
           print(io, ')')
       end

julia> state1 = (t.rngState0, t.rngState1, t.rngState2, t.rngState3) # ok, our state didn't change..
(0xf6e7025b1a108853, 0x1949f9d36755c8cf, 0xdc13b6c30461a2b5, 0xb199766836484420)

julia> t = current_task()  # still the same task
Task (runnable) @0x00007f6723fdc010

julia> state1 = (t.rngState0, t.rngState1, t.rngState2, t.rngState3)  # still the same state
(0xf6e7025b1a108853, 0x1949f9d36755c8cf, 0xdc13b6c30461a2b5, 0xb199766836484420)

julia> copy(Random.default_rng()) # should just copy rng of current task, so far so good
Xoshiro(0xf6e7025b1a108853, 0x1949f9d36755c8cf, 0xdc13b6c30461a2b5, 0xb199766836484420)

julia> Random.default_rng()   # ?! shouldn't this be the same state we just copied from?
TaskLocalRNG(0x6c4866be67e41b35,0x190098b53e17879a,0xe342dc7b9c59fdeb,0xb156895802bc4cb0)

julia> using Base.Threads

julia> Threads.nthreads()
1

julia> versioninfo()
Julia Version 1.8.0-DEV.798
Commit 3ae25059fb (2021-10-22 06:13 UTC)
Platform Info:
  OS: Linux (x86_64-pc-linux-gnu)
  CPU: Intel(R) Core(TM) i7-6600U CPU @ 2.60GHz
  WORD_SIZE: 64
  LIBM: libopenlibm
  LLVM: libLLVM-12.0.1 (ORCJIT, skylake)

I have no idea why the copy differs from the original - as far as I can tell, even the current task is the same, so no new RNG was split off! Am I doing something wrong with printing here? It's basically the same as for regular Xoshiro, and printing itself doesn't seem to change RNG either:

julia> Random.default_rng()
TaskLocalRNG(0x6c4866be67e41b35,0x190098b53e17879a,0xe342dc7b9c59fdeb,0xb156895802bc4cb0)

julia> Random.default_rng()
TaskLocalRNG(0x6c4866be67e41b35,0x190098b53e17879a,0xe342dc7b9c59fdeb,0xb156895802bc4cb0)

julia> Random.default_rng()
TaskLocalRNG(0x6c4866be67e41b35,0x190098b53e17879a,0xe342dc7b9c59fdeb,0xb156895802bc4cb0)

[Seelengrab]

Ok, when I just dump(t) instead of printing the state manually, I get a very different picture. Seems like there's a task for printing/background stuff that's different from the REPL, which has a different RNG state. The REPL with our task/rng state is waiting diligently though - maybe something similar is going on here? Is there a somewhat easy way/tool to inspect task state of a running julia session, without messing with the julia session?

[vtjnash]

These numbers don't appear to be random, but is advanced exactly 8 numbers from where it was supposed to be generating:
0.6209946085911393 == 0.7846500004305739

julia> rng = Xoshiro(0x947b9af2ba269897, 0x95ae8d9a31382b32, 0x8a532dc2baa61f2e, 0x7213512241a4dfbd)
Xoshiro(0x947b9af2ba269897, 0x95ae8d9a31382b32, 0x8a532dc2baa61f2e, 0x7213512241a4dfbd)

julia> rand(rng)
0.6209946085911393

julia> rand(rng)
0.08217519705091403

julia> rand(rng)
0.7653532529104843

julia> rand(rng)
0.5444902979941714

julia> rand(rng)
0.696656487590396

julia> rand(rng)
0.40339486705752836

julia> rand(rng)
0.3460152995484739

julia> rand(rng)
0.3412018309199384

julia> rand(rng)
0.7846500004305739

[vtjnash]

which means the 2 states were probably:

orig = Xoshiro(0x7395c1c4acfb627a, 0x4c26b3294081a4a8, 0x4b551ddeca4f6ea5, 0x4da71ae5e526297b)
rng  = Xoshiro(0x947b9af2ba269897, 0x95ae8d9a31382b32, 0x8a532dc2baa61f2e, 0x7213512241a4dfbd)