strconv: panic during init()

[davecheney]

What steps will reproduce the problem?
1. sudo apt-get install mongodb-server
2. go get -u launchpad.net/juju-core/...
3. go test launchpad.net/juju-core/cmd/jujud

What is the expected output? What do you see instead?

% go test launchpad.net/juju-core/cmd/jujud                                             
               
panic: runtime error: call of nil func value
[signal 0xb code=0x1 addr=0x0 pc=0x0]

goroutine 16 [running]:
runtime.panic(0x9182e0, 0xdb281c)
        /home/dfc/go/src/pkg/runtime/panic.c:279 +0xf5
strconv.init()
        /home/dfc/go/src/pkg/strconv/atoi.go:10 +0x43
testing.init()
        /home/dfc/go/src/pkg/testing/testing.go:656 +0x43
launchpad.net/juju-core/cmd/jujud.init()
        /home/dfc/src/launchpad.net/juju-core/cmd/jujud/upgrade_test.go:138 +0x51
main.init()
        /tmp/go-build380384730/launchpad.net/juju-core/cmd/jujud/_test/_testmain.go:50 +0x3b

goroutine 17 [runnable]:
runtime.MHeap_Scavenger()
        /home/dfc/go/src/pkg/runtime/mheap.c:507
runtime.goexit()
        /home/dfc/go/src/pkg/runtime/proc.c:1430
FAIL    launchpad.net/juju-core/cmd/jujud       0.004s

Please use labels and text to provide additional information.

% uname -a
Linux lucky 3.11.0-19-generic #33-Ubuntu SMP Tue Mar 11 18:48:34 UTC 2014 x86_64 x86_64
x86_64 GNU/Linux
% go version
go version devel +94d84d24086b Wed Apr 09 18:23:53 2014 -0700 + linux/amd64

[bradfitz]

Comment 1:

The subject of this bug hints at information that is not in the bug itself.
What is the corrupt init function? Did you corrupt it on purpose? Did you find it to be
corrupt? How?

[davecheney]

Comment 2:

Sorry, this was not a good bug report, I should do better.
While trying to run tests of a juju package the runtime paniced saying that there was a
"call of nil func value" on atoi.go line 10. 
This sounds impossible as there isn't a function declaration on that line and the
strconv package has not reported failures for a long time.

[dvyukov]

Comment 4:

Currently the build fails with:
$ go test launchpad.net/juju-core/cmd/jujud
# launchpad.net/juju-core/utils/ssh
/ssd/src/gopath/src/launchpad.net/juju-core/utils/ssh/ssh_gocrypto.go:84: undefined:
ssh.ClientConn
FAIL    launchpad.net/juju-core/cmd/jujud [build failed]
I've updated go.crypto to r191, which roughly relates to the report date.
Then it started failing with:
$ go test launchpad.net/juju-core/cmd/jujud
# launchpad.net/juju-core/worker/instancepoller
/ssd/src/gopath/src/launchpad.net/juju-core/worker/instancepoller/aggregate.go:67:
undefined: ratelimit.New
FAIL    launchpad.net/juju-core/cmd/jujud [build failed]
I've reverted launchpad.net/juju-core to r2597, which roughly relates to the report date.
But it still fails to build.
Please provide exact revisions that build.

[davecheney]

Comment 5:

I'm sorry. I neglected to mention that we use a tool we developed to pin dependency
versions. 
Please try
$ go get launchpad.net/godeps
$ cd $GOPATH/src/launchpad.net/juju-core
$ godeps -u dependencies.tsv 
There will be a bunch of output as godeps updates each dependency to the correct revision

[dvyukov]

Comment 6:

Do I need to start mongodb somehow?
Current the tests print:
... Panic: no reachable servers (PC=0x40EDCD)
src/pkg/runtime/panic.c:248
  in panic
gopath/src/launchpad.net/juju-core/testing/mgo.go:267
  in MgoInstance.MustDial
gopath/src/launchpad.net/juju-core/testing/mgo.go:331
  in MgoSuite.SetUpTest
bootstrap_test.go:94
  in BootstrapSuite.SetUpTest
src/pkg/runtime/asm_amd64.s:345
  in call16

[davecheney]

Comment 7:

The test should start mongodb itself. 
Unfortunately you can't Ubuntu Precise, the version of mongodb that ships with that is
too old. 
We have a replacement mongodb available
sudo add-apt-repository cloud-archive:tools
sudo apt-get update
sudo apt-get install mongodb-server
should do the trick

[dvyukov]

Comment 8:

I've downloaded mongodb 2.6.0 from
https://www.mongodb.org/dr//fastdl.mongodb.org/linux/mongodb-linux-x86_64-2.6.0.tgz/download
but it still fails:
$ mongod -v
2014-04-15T15:06:21.509+0400 [initandlisten] db version v2.6.0
$ go test -v launchpad.net/juju-core/cmd/jujud
=== RUN TestPackage
----------------------------------------------------------------------
PANIC: bootstrap_test.go:92: BootstrapSuite.SetUpTest
[LOG] 36.85478 DEBUG juju.testing tls.Dial(127.0.0.1:58107) failed with dial tcp
127.0.0.1:58107: connection refused
[LOG] 36.85478 DEBUG juju.testing tls.Dial(127.0.0.1:58107) failed with dial tcp
127.0.0.1:58107: connection refused
[LOG] 36.85478 ERROR juju mongodb has exited without being killed
[LOG] 36.85478 ERROR juju mongod: Error parsing command line: unknown option
sslOnNormalPorts
[LOG] 36.85478 ERROR juju mongod: try 'mongod --help' for more information
[LOG] 36.85478 DEBUG juju.testing tls.Dial(127.0.0.1:58107) failed with dial tcp
127.0.0.1:58107: connection refused
... Panic: no reachable servers (PC=0x40EDCD)
/ssd/src/go2/src/pkg/runtime/panic.c:248
  in panic
/ssd/src/gopath/src/launchpad.net/juju-core/testing/mgo.go:267
  in MgoInstance.MustDial
/ssd/src/gopath/src/launchpad.net/juju-core/testing/mgo.go:331
  in MgoSuite.SetUpTest
bootstrap_test.go:94
  in BootstrapSuite.SetUpTest
/ssd/src/go2/src/pkg/runtime/asm_amd64.s:345
  in call16
----------------------------------------------------------------------
PANIC: bootstrap_test.go:100: BootstrapSuite.TearDownTest
... Panic: no reachable servers (PC=0x40EDCD)
/ssd/src/go2/src/pkg/runtime/panic.c:248
  in panic
/ssd/src/gopath/src/launchpad.net/juju-core/testing/mgo.go:267
  in MgoInstance.MustDial
/ssd/src/gopath/src/launchpad.net/juju-core/testing/mgo.go:345
  in MgoInstance.Reset
/ssd/src/gopath/src/launchpad.net/juju-core/testing/mgo.go:431
  in MgoSuite.TearDownTest
bootstrap_test.go:101
  in BootstrapSuite.TearDownTest
/ssd/src/go2/src/pkg/runtime/asm_amd64.s:345
  in call16

[davecheney]

Comment 9:

I'm really sorry, you can't use the regular mongodb as that does not ship with TLS
support. This is also why you cannot use the mongodb from precise. 
We ship a compatible version of mongodb in this ppa
sudo add-apt-repository cloud-archive:tools
sudo apt-get update
sudo apt-get install mongodb-server

[rsc]

Comment 10:

$ gdb -q jujud.test
Reading symbols from jujud.test...done.
(gdb) r
Starting program: /home/ubuntu/go/jujud.test 
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
[New Thread 0x7ffff77f5700 (LWP 15782)]
Program received signal SIGSEGV, Segmentation fault.
0x0000000000000000 in ?? ()
(gdb) up
#1  0x00000000004acd13 in strconv.init () at
/home/ubuntu/src/launchpad.net/juju-core/cmd/jujud/machine.go:542
542     st, err := state.Open(info, state.DialOpts{}, environs.NewStatePolicy())
(gdb) disas
Dump of assembler code for function strconv.init:
   0x00000000004accd0 <+0>:   mov    %fs:0xfffffffffffffff0,%rcx
   0x00000000004accd9 <+9>:   cmp    (%rcx),%rsp
   0x00000000004accdc <+12>:  ja     0x4acce5 <strconv.init+21>
   0x00000000004accde <+14>:  callq  0x42c950 <runtime.morestack00_noctxt>
   0x00000000004acce3 <+19>:  jmp    0x4accd0 <strconv.init>
   0x00000000004acce5 <+21>:  sub    $0x20,%rsp
   0x00000000004acce9 <+25>:  movzbq 0xe015c0,%rax
   0x00000000004accf2 <+34>:  cmp    $0x0,%al
   0x00000000004accf4 <+36>:  je     0x4acd06 <strconv.init+54>
   0x00000000004accf6 <+38>:  cmp    $0x2,%al
   0x00000000004accf8 <+40>:  jne    0x4accff <strconv.init+47>
   0x00000000004accfa <+42>:  add    $0x20,%rsp
   0x00000000004accfe <+46>:  retq   
   0x00000000004accff <+47>:  callq  0x40f5f0 <runtime.throwinit>
   0x00000000004acd04 <+52>:  ud2    
   0x00000000004acd06 <+54>:  movb   $0x1,0xe015c0
   0x00000000004acd0e <+62>:  callq  0x0
=> 0x00000000004acd13 <+67>:   lea    0xb10780,%rbx
   0x00000000004acd1b <+75>:  lea    (%rsp),%rbp
   0x00000000004acd1f <+79>:  mov    %rbp,%rdi
   0x00000000004acd22 <+82>:  mov    %rbx,%rsi
...
(gdb) x/5xb 0x00000000004acd0e
0x4acd0e <strconv.init+62>:   0xe8     0xed   0x32    0xb5    0xff
(gdb)
Emitting a call 0x0 is clearly wrong, and the linker tried really hard to get the zero.
It clearly is emitting a reference to a symbol with address 0, presumably because it's
not in the binary. There's another later in the function but let's focus on the first
one. On my Mac I get:
(gdb) disas 'strconv.init'
Dump of assembler code for function strconv.init:
0x00000000000eda80 <strconv.init+0>:  mov    %gs:0x8a0,%rcx
0x00000000000eda89 <strconv.init+9>:  cmp    (%rcx),%rsp
0x00000000000eda8c <strconv.init+12>: ja     0xeda95 <strconv.init+21>
0x00000000000eda8e <strconv.init+14>: callq  0x88610
<runtime.morestack00_noctxt>
0x00000000000eda93 <strconv.init+19>: jmp    0xeda80 <strconv.init>
0x00000000000eda95 <strconv.init+21>: sub    $0x20,%rsp
0x00000000000eda99 <strconv.init+25>: movzbq 0x68711c,%rax
0x00000000000edaa2 <strconv.init+34>: cmp    $0x0,%al
0x00000000000edaa4 <strconv.init+36>: je     0xedab6 <strconv.init+54>
0x00000000000edaa6 <strconv.init+38>: cmp    $0x2,%al
0x00000000000edaa8 <strconv.init+40>: jne    0xedaaf <strconv.init+47>
0x00000000000edaaa <strconv.init+42>: add    $0x20,%rsp
0x00000000000edaae <strconv.init+46>: retq   
0x00000000000edaaf <strconv.init+47>: callq  0x6d2e0 <runtime.throwinit>
0x00000000000edab4 <strconv.init+52>: ud2a   
0x00000000000edab6 <strconv.init+54>: movb   $0x1,0x68711c
0x00000000000edabe <strconv.init+62>: callq  0x1dcd80 <math.init>
0x00000000000edac3 <strconv.init+67>: lea    0x491460,%rbx
So it's strconv.init calling math.init, but somehow math.init is gone. Back to the jujud
binary:
$ gdb -q jujud.test
Reading symbols from jujud.test...done.
(gdb) disas 'strconv.init'
Dump of assembler code for function strconv.init:
   0x00000000004accd0 <+0>:   mov    %fs:0xfffffffffffffff0,%rcx
   0x00000000004accd9 <+9>:   cmp    (%rcx),%rsp
   0x00000000004accdc <+12>:  ja     0x4acce5 <strconv.init+21>
   0x00000000004accde <+14>:  callq  0x42c950 <runtime.morestack00_noctxt>
   0x00000000004acce3 <+19>:  jmp    0x4accd0 <strconv.init>
   0x00000000004acce5 <+21>:  sub    $0x20,%rsp
   0x00000000004acce9 <+25>:  movzbq 0xe015c0,%rax
   0x00000000004accf2 <+34>:  cmp    $0x0,%al
   0x00000000004accf4 <+36>:  je     0x4acd06 <strconv.init+54>
   0x00000000004accf6 <+38>:  cmp    $0x2,%al
   0x00000000004accf8 <+40>:  jne    0x4accff <strconv.init+47>
   0x00000000004accfa <+42>:  add    $0x20,%rsp
   0x00000000004accfe <+46>:  retq   
   0x00000000004accff <+47>:  callq  0x40f5f0 <runtime.throwinit>
   0x00000000004acd04 <+52>:  ud2    
   0x00000000004acd06 <+54>:  movb   $0x1,0xe015c0
   0x00000000004acd0e <+62>:  callq  0x0
   0x00000000004acd13 <+67>:  lea    0xb10780,%rbx
   0x00000000004acd1b <+75>:  lea    (%rsp),%rbp
   0x00000000004acd1f <+79>:  mov    %rbp,%rdi
   0x00000000004acd22 <+82>:  mov    %rbx,%rsi
   0x00000000004acd25 <+85>:  movsq  %ds:(%rsi),%es:(%rdi)
   0x00000000004acd27 <+87>:  movsq  %ds:(%rsi),%es:(%rdi)
   0x00000000004acd29 <+89>:  callq  0x0
   0x00000000004acd2e <+94>:  mov    0x10(%rsp),%rcx
   0x00000000004acd33 <+99>:  mov    0x18(%rsp),%rax
   0x00000000004acd38 <+104>: mov    %rcx,0xdf8960
   0x00000000004acd40 <+112>: mov    %rax,0xdf8968
   0x00000000004acd48 <+120>: lea    0xa8e820,%rbx
   0x00000000004acd50 <+128>: lea    (%rsp),%rbp
   0x00000000004acd54 <+132>: mov    %rbp,%rdi
   0x00000000004acd57 <+135>: mov    %rbx,%rsi
   0x00000000004acd5a <+138>: movsq  %ds:(%rsi),%es:(%rdi)
   0x00000000004acd5c <+140>: movsq  %ds:(%rsi),%es:(%rdi)
   0x00000000004acd5e <+142>: callq  0x0
   0x00000000004acd63 <+147>: mov    0x10(%rsp),%rcx
   0x00000000004acd68 <+152>: mov    0x18(%rsp),%rax
   0x00000000004acd6d <+157>: mov    %rcx,0xdf8970
   0x00000000004acd75 <+165>: mov    %rax,0xdf8978
   0x00000000004acd7d <+173>: movb   $0x2,0xe015c0
   0x00000000004acd85 <+181>: add    $0x20,%rsp
   0x00000000004acd89 <+185>: retq   
   0x00000000004acd8a <+186>: add    %al,(%rax)
   0x00000000004acd8c <+188>: add    %al,(%rax)
   0x00000000004acd8e <+190>: add    %al,(%rax)
End of assembler dump.
(gdb) disas 'math.init'
No symbol "math.init" in current context.
(gdb) quit
$ nm jujud.test|grep math.init
0000000000e015a1 B math.initdone.
$ 
math.init is well and truly missing from the binary, despite being called. That's not
good. You'd think the linker's dead code walk was broken, but:
$ go test -ldflags '-v -v' -c launchpad.net/juju-core/cmd/jujud 2>log
$ grep strconv.init log
marktext strconv.init
$ grep math.init log
marktext math.init
marktext math.init·1
$ nm jujud.test|grep math.ini
0000000000e015a1 B math.initdone.
$ 
$ go test -ldflags '-a -v -v' -c launchpad.net/juju-core/cmd/jujud 2>log
$ grep strconv.init log
marktext strconv.init
4accd0  strconv.init        
$ grep math.init log
marktext math.init
marktext math.init·1
$
math.init is supposed to be there - it was marked - it's just not in the output.
Running 6l under valgrind did not turn anything up.
Okay, so it got marked but it is not in the ctxt->textp walk. The usual reason you
miss something in a linked list is that you inserted the same thing twice, which
short-circuited a whole swath of list. I put some checking in to make sure we aren't
inserting duplicates, and lo and behold! we are. And the symbol is named '.dup' which is
a nice touch.
CL on its way.

Status changed to Started.

[davecheney]

Comment 11:

Great detective work Russ. I wonder if https://golang.org/cl/83630044/ was the
culprit.

[gopherbot]

Comment 12:

CL https://golang.org/cl/87910047 mentions this issue.

[rsc]

Comment 13:

This issue was closed by revision 468cf82.

Status changed to Fixed.