math/big: zero divide in ProbablyPrime (garbage collection bug?)

[gopherbot]

by huseby@lindenlab.com:

What steps will reproduce the problem?
If possible, include a link to a program on play.golang.org.
1. Run this on linux_i386: http://play.golang.org/p/05udxnXbLH
2. Wait for it to have a divide by zero error (only happens very rarely)

What is the expected output?
The rsa.GenerateKey() shouldn't cause a panic.


What do you see instead?
panic: runtime error: integer divide by zero
[signal 0x8 code=0x1 addr=0x80a6898 pc=0x80a6898]

goroutine 10 [running]:
math/big.divWW(0xe49cf0e9, 0x7b5ae8c8, 0x0, 0x188fcac8, 0x17, ...)
    /home/huseby/Projects/go/src/pkg/math/big/arith_386.s:21 +0x8
math/big.nat.divLarge(0x18821870, 0x10, 0x24, 0x188fcaa0, unexpected fault address 0x21,
...0xeef97277
)
    /home/huseby/Projects/go/src/pkg/math/big/nat.go:564 +0x811
math/big.nat.div(0x18821870, 0x10, 0x24, 0x188fcaa0, 0x20, ...)
    /home/huseby/Projects/go/src/pkg/math/big/nat.go:519 +0x26f
math/big.nat.expNNWindowed(0x18821900, 0x20, 0x24, 0x1885f500, 0x10, ...)
    /home/huseby/Projects/go/src/pkg/math/big/nat.go:1358 +0x923
math/big.nat.expNN(0x1885f550, 0x10, 0x14, 0x1885f500, 0x10, ...)
    /home/huseby/Projects/go/src/pkg/math/big/nat.go:1257 +0x3f7
math/big.nat.probablyPrime(0x188ad4b0, 0x10, 0x14, 0x14, 0x6, ...)
    /home/huseby/Projects/go/src/pkg/math/big/nat.go:1442 +0x573
math/big.(*Int).ProbablyPrime(0x1892e0a0, 0x14, 0x35, 0x0)
    /home/huseby/Projects/go/src/pkg/math/big/int.go:726 +0x42
crypto/rand.Prime(0x1873d120, 0x1873d140, 0x200, 0x1892e0a0, 0x0, ...)
    /home/huseby/Projects/go/src/pkg/crypto/rand/util.go:97 +0x337
crypto/rsa.GenerateMultiPrimeKey(0x1873d120, 0x1873d140, 0x2, 0x400, 0x18863480, ...)
    /home/huseby/Projects/go/src/pkg/crypto/rsa/rsa.go:154 +0x192
crypto/rsa.GenerateKey(0x1873d120, 0x1873d140, 0x400, 0x0, 0x0, ...)
    /home/huseby/Projects/go/src/pkg/crypto/rsa/rsa.go:127 +0x51
main.CreateCert(0x1872c540, 0x0)
    /home/huseby/Projects/onion_finder/of.go:35 +0x4f
created by main.main
    /home/huseby/Projects/onion_finder/of.go:121 +0x155


Which compiler are you using (5g, 6g, 8g, gccgo)?

8g

Which operating system are you using?

Ubuntu 12.04 32-bit

Which version are you using?  (run 'go version')

$ go version
go version devel +8d71734a0cb0 Tue Feb 05 09:54:01 2013 -0800 linux/386

Please provide any additional information below.

This is a dual, quad-core Intel(R) Xeon(R) CPU X5492  @ 3.40GHz machine.  I was running
with GOMAXPROCS=10 and --ncpu 9.  It takes many, many iterations to get the panic.

Attachments:

1. of (2192416 bytes)

[gopherbot]

Comment 1 by huseby@lindenlab.com:

I attached the executable.

[rsc]

Comment 2:

There really is a zero on the stack as the argument to divWW (it's not a divide by -1,
for example), but that word is the most significant word of the divisor, which is never
zero. If the divisor itself were zero it would have len(v) == 0, so that v[len(v)-1]
would have panicked. Worse, in the context of the called code the divisor is the modulus
passed to expNN, which remains constant throughout the execution of expNNWindowed. And
yet the code died in the div at line 1358:
  1339      for i := len(y) - 1; i >= 0; i-- {
  1340          yi := y[i]
  1341          for j := 0; j < _W; j += n {
  1342              if i != len(y)-1 || j != 0 {
  1343                  // Unrolled loop for significant performance
  1344                  // gain.  Use go test -bench=".*" in crypto/rsa
  1345                  // to check performance before making changes.
  1346                  zz = zz.mul(z, z)
  1347                  zz, z = z, zz
  1348                  zz, r = zz.div(r, z, m)
  1349                  z, r = r, z
  1350  
  1351                  zz = zz.mul(z, z)
  1352                  zz, z = z, zz
  1353                  zz, r = zz.div(r, z, m)
  1354                  z, r = r, z
  1355  
  1356                  zz = zz.mul(z, z)
  1357                  zz, z = z, zz
  1358                  zz, r = zz.div(r, z, m)
  1359                  z, r = r, z
  1360  
  1361                  zz = zz.mul(z, z)
  1362                  zz, z = z, zz
  1363                  zz, r = zz.div(r, z, m)
  1364                  z, r = r, z
  1365              }
  1366  
  1367              zz = zz.mul(z, powers[yi>>(_W-n)])
  1368              zz, z = z, zz
  1369              zz, r = zz.div(r, z, m)
  1370              z, r = r, z
  1371  
  1372              yi <<= n
  1373          }
  1374      }
If m is a denormalized zero at 1358, why is not a denormalized zero at 1353 or 1348?
My hypothesis is that this is a garbage collection bug, that the underlying array
backing m has been collected and zeroed prematurely. That would resolve all the
mysteries.
It's easy to believe there are garbage collection bugs at tip, sadly. The garbage
collector has been having some work done recently and I've seen a couple strange crashes
I haven't tracked down yet. If you need stability my suggestion would be to stay at the
release version.
How many times have you seen this crash? How long does it typically take to happen?

Labels changed: added priority-later, go1.1, removed priority-triage, go1.1maybe.

Status changed to Accepted.

[gopherbot]

Comment 3 by huseby@lindenlab.com:

This crash usually takes anywhere between 5 minutes and an hour to happen.  I've never
seen this exe run longer than an hour before failing with this exact crash.

[rsc]

Comment 4:

The repository tip now has at least one important garbage collection fix,
as well as some other structural garbage collection changes. I'd be very
interested to hear whether you find that the crash still happens if you
rebuild at tip.
Thanks.
Russ

[gopherbot]

Comment 5 by huseby@lindenlab.com:

I updated to version:
go version devel +e0b23d56fd6a Wed Feb 27 21:17:53 2013 +0200 linux/386
And now it's failing with:
panic: runtime error: invalid memory address or nil pointer dereference
[signal 0xb code=0x1 addr=0x1 pc=0x80a7bbf]
I'm not sure which callstack it was so here's all of them:
goroutine 3 [running]:
math/big.nat.setBytes(0x1, 0x10, 0x14, 0x18411880, 0x40, ...)
    /home/huseby/Projects/go/src/pkg/math/big/nat.go:1494 +0xbf
math/big.(*Int).SetBytes(0x184f4b60, 0x18411880, 0x40, 0x40, 0x40, ...)
    /home/huseby/Projects/go/src/pkg/math/big/int.go:567 +0x48
crypto/rand.Prime(0x1834b400, 0x1834b020, 0x200, 0x184f4b60, 0x0, ...)
    /home/huseby/Projects/go/src/pkg/crypto/rand/util.go:69 +0x22c
crypto/rsa.GenerateMultiPrimeKey(0x1834b400, 0x1834b020, 0x2, 0x400, 0x1840fde0, ...)
    /home/huseby/Projects/go/src/pkg/crypto/rsa/rsa.go:168 +0x1af
crypto/rsa.GenerateKey(0x1834b400, 0x1834b020, 0x400, 0x0, 0x0, ...)
    /home/huseby/Projects/go/src/pkg/crypto/rsa/rsa.go:127 +0x51
main.CreateCert(0x18335510)
    /home/huseby/Projects/onion_finder/of.go:35 +0x4f
created by main.main
    /home/huseby/Projects/onion_finder/of.go:121 +0x155
goroutine 1 [chan receive]:
main.main()
    /home/huseby/Projects/onion_finder/of.go:128 +0x19f
goroutine 0 [syscall]:
goroutine 4 [running]:
created by main.main
    /home/huseby/Projects/onion_finder/of.go:121 +0x155
goroutine 5 [running]:
math/big.nat.divLarge(0x184bb750, 0x10, 0x24, 0x184bb7e0, 0x21, ...)
    /home/huseby/Projects/go/src/pkg/math/big/nat.go:584 +0xbf4
math/big.nat.div(0x18461b40, 0x10, 0x24, 0x18501630, 0x20, ...)
    /home/huseby/Projects/go/src/pkg/math/big/nat.go:519 +0x26f
created by main.main
    /home/huseby/Projects/onion_finder/of.go:121 +0x155
goroutine 6 [running]:
created by main.main
    /home/huseby/Projects/onion_finder/of.go:121 +0x155
goroutine 7 [running]:
math/big.nat.divLarge(0x1839bab0, 0x10, 0x24, 0x1839bab0, 0x21, ...)
    /home/huseby/Projects/go/src/pkg/math/big/nat.go:582 +0xa36
math/big.nat.div(0x1839bab0, 0x10, 0x24, 0x1839bab0, 0x20, ...)
    /home/huseby/Projects/go/src/pkg/math/big/nat.go:519 +0x26f
math/big.nat.expNNWindowed(0x1839bab0, 0x20, 0x24, 0x1840e780, 0x10, ...)
    /home/huseby/Projects/go/src/pkg/math/big/nat.go:1363 +0xa4e
math/big.nat.expNN(0x1840e7d0, 0x10, 0x14, 0x1840e780, 0x10, ...)
    /home/huseby/Projects/go/src/pkg/math/big/nat.go:1257 +0x3f7
math/big.nat.probablyPrime(0x184f1be0, 0x10, 0x14, 0x14, 0x0, ...)
    /home/huseby/Projects/go/src/pkg/math/big/nat.go:1442 +0x573
math/big.(*Int).ProbablyPrime(0x184d9270, 0x14, 0x35)
    /home/huseby/Projects/go/src/pkg/math/big/int.go:726 +0x42
crypto/rand.Prime(0x1834b400, 0x1834b020, 0x200, 0x184d9270, 0x0, ...)
    /home/huseby/Projects/go/src/pkg/crypto/rand/util.go:97 +0x337
crypto/rsa.GenerateMultiPrimeKey(0x1834b400, 0x1834b020, 0x2, 0x400, 0x1840f4e0, ...)
    /home/huseby/Projects/go/src/pkg/crypto/rsa/rsa.go:168 +0x1af
crypto/rsa.GenerateKey(0x1834b400, 0x1834b020, 0x400, 0x0, 0x0, ...)
    /home/huseby/Projects/go/src/pkg/crypto/rsa/rsa.go:127 +0x51
main.CreateCert(0x18335510)
    /home/huseby/Projects/onion_finder/of.go:35 +0x4f
created by main.main
    /home/huseby/Projects/onion_finder/of.go:121 +0x155
goroutine 8 [running]:
math/big.nat.divLarge(0x183c2e40, 0x10, 0x15, 0x183c2e40, 0x21, ...)
    /home/huseby/Projects/go/src/pkg/math/big/nat.go:541 +0x2bc
math/big.nat.div(0x184f23f0, 0x10, 0x24, 0x184f2360, 0x10, ...)
    /home/huseby/Projects/go/src/pkg/math/big/nat.go:519 +0x26f
math/big.nat.expNNWindowed(0x18493140, 0x20, 0x25, 0x1841deb0, 0x10, ...)
    /home/huseby/Projects/go/src/pkg/math/big/nat.go:1353 +0x7f8
math/big.nat.expNN(0x1841df00, 0x10, 0x14, 0x1841deb0, 0x10, ...)
    /home/huseby/Projects/go/src/pkg/math/big/nat.go:1257 +0x3f7
math/big.nat.probablyPrime(0x18402370, 0x10, 0x14, 0x14, 0x0, ...)
    /home/huseby/Projects/go/src/pkg/math/big/nat.go:1442 +0x573
math/big.(*Int).ProbablyPrime(0x184d9130, 0x14, 0x35)
    /home/huseby/Projects/go/src/pkg/math/big/int.go:726 +0x42
crypto/rand.Prime(0x1834b400, 0x1834b020, 0x200, 0x184d9130, 0x0, ...)
    /home/huseby/Projects/go/src/pkg/crypto/rand/util.go:97 +0x337
crypto/rsa.GenerateMultiPrimeKey(0x1834b400, 0x1834b020, 0x2, 0x400, 0x183adea0, ...)
    /home/huseby/Projects/go/src/pkg/crypto/rsa/rsa.go:168 +0x1af
crypto/rsa.GenerateKey(0x1834b400, 0x1834b020, 0x400, 0x0, 0x0, ...)
    /home/huseby/Projects/go/src/pkg/crypto/rsa/rsa.go:127 +0x51
main.CreateCert(0x18335510)
    /home/huseby/Projects/onion_finder/of.go:35 +0x4f
created by main.main
    /home/huseby/Projects/onion_finder/of.go:121 +0x155
goroutine 9 [running]:
math/big.nat.divLarge(0x183ae870, 0x10, 0x24, 0x183ae870, 0x21, ...)
    /home/huseby/Projects/go/src/pkg/math/big/nat.go:596 +0xf55
created by main.main
    /home/huseby/Projects/onion_finder/of.go:121 +0x155
goroutine 10 [running]:
created by main.main
    /home/huseby/Projects/onion_finder/of.go:121 +0x155
goroutine 11 [running]:
created by main.main
    /home/huseby/Projects/onion_finder/of.go:121 +0x155
goroutine 12 [chan receive]:
main.HashCert(0xbfd854ca, 0x6, 0x18335510, 0x183354e0)
    /home/huseby/Projects/onion_finder/of.go:54 +0xff
created by main.main
    /home/huseby/Projects/onion_finder/of.go:125 +0x189

[gopherbot]

Comment 6 by huseby@lindenlab.com:

I'll re-run it with a single producer and a single consumer goroutine and wait for it to
fail.

[gopherbot]

Comment 7:

I created a patch that turns off some code in the garbage collector:
https://golang.org/cl/7557044/
The idea is to gradually extend the patch until the cause of the issue is pinpointed.
I am unable to reproduce the failure on my notebook. Please apply
https://golang.org/cl/7557044/ to Go tip on a computer on which the issue is
reproducible and report the results.

[cznic]

Comment 8:

Why it isn't possible to (slowly but simply) bisect this heisenbug? (On a machine which
can reproduce it.)

[alberts]

Comment 9:

I'm going to see if I can reproduce this on the machine that has been doing the
linux/amd64 stress tests. I've also set up a linux/386 stress test to see if anything
falls out.

[alberts]

Comment 10:

Can you reproduce this with GOGCTRACE=1?
If so, how many collections before it typically blows up?

[alberts]

Comment 11:

I have managed to reproduce this with:
go build mal.go && file ./mal && GOGCTRACE=1 GOMAXPROCS=10 ./mal -ncpu=9
gc329284(8): 0+1+0 ms, 1 -> 0 MB 11545 -> 581 (3746016176-3746015595) objects, 14(497)
handoff, 47(697) steal, 327/166/9 yields
SIGSEGV: segmentation violation
PC=0x8065892
Segmentation fault
I've also seen something suspect while running the time unit tests (nil pointer
dereference). Investigating to see if they are related.

[alberts]

Comment 12:

issue #5007 describes some more linux/386 issues. this might be related to that.

[gopherbot]

Comment 13:

Would it be possible to publish the source code of mal.go?

[alberts]

Comment 14:

mal.go is http://play.golang.org/p/05udxnXbLH

[gopherbot]

Comment 15 by huseby@lindenlab.com:

I applied the patch (https://golang.org/cl/7557044/) and re-ran the code.  This
time it failed with:
unexpected fault address 0x4a983dc9
fatal error: fault
[signal 0xb code=0x1 addr=0x4a983dc9 pc=0x805178b]
several goroutines:
panic: runtime error: invalid memory address or nil pointer dereference
I'll try GOGCTRACE=1 next using the latest tip without the patch.