Crash with trace with 2 OTR sessions

alan-mushi commented 8 years ago

Hi, I met a rather disturbing error (trace & crash):

user_name_here> panic: otr: failed to generate sending keys: otr: internal error: no key slots

goroutine 1 [running]:
golang.org/x/crypto/otr.(*Conversation).generateData(0xc8200c8480, 0xc8201debd0, 0x2, 0x8, 0x0, 0x0, 0x0, 0x0)
    /home/user/.go/src/golang.org/x/crypto/otr/otr.go:960 +0x13b
golang.org/x/crypto/otr.(*Conversation).Send(0xc8200c8480, 0xc8201debd0, 0x2, 0x8, 0x0, 0x0, 0x0, 0x0, 0x0)
    /home/user/.go/src/golang.org/x/crypto/otr/otr.go:450 +0x170
main.main()
    /home/user/.go/src/github.com/agl/xmpp-client/ui.go:577 +0x5f16

goroutine 17 [syscall, 11 minutes, locked to thread]:
runtime.goexit()
    /usr/lib/go/src/runtime/asm_amd64.s:1696 +0x1

goroutine 5 [syscall, 11 minutes]:
os/signal.loop()
    /usr/lib/go/src/os/signal/signal_unix.go:22 +0x18
created by os/signal.init.1
    /usr/lib/go/src/os/signal/signal_unix.go:28 +0x37

goroutine 6 [chan receive, 11 minutes]:
main.main.func1(0xc82001a180, 0xc820084900)
    /home/user/.go/src/github.com/agl/xmpp-client/ui.go:204 +0x4d
created by main.main
    /home/user/.go/src/github.com/agl/xmpp-client/ui.go:207 +0x36e

goroutine 7 [select, 11 minutes, locked to thread]:
runtime.gopark(0x7fc000, 0xc82002af28, 0x769270, 0x6, 0x44ea18, 0x2)
    /usr/lib/go/src/runtime/proc.go:185 +0x163
runtime.selectgoImpl(0xc82002af28, 0x0, 0x18)
    /usr/lib/go/src/runtime/select.go:392 +0xa64
runtime.selectgo(0xc82002af28)
    /usr/lib/go/src/runtime/select.go:212 +0x12
runtime.ensureSigM.func1()
    /usr/lib/go/src/runtime/signal1_unix.go:227 +0x353
runtime.goexit()
    /usr/lib/go/src/runtime/asm_amd64.s:1696 +0x1

goroutine 19 [syscall]:
syscall.Syscall(0x0, 0x0, 0xc8200849c0, 0x100, 0x58dfe8, 0x71da00, 0x0)
    /usr/lib/go/src/syscall/asm_linux_amd64.s:18 +0x5
syscall.read(0x0, 0xc8200849c0, 0x100, 0x100, 0x42f3d5, 0x0, 0x0)
    /usr/lib/go/src/syscall/zsyscall_linux_amd64.go:783 +0x5f
syscall.Read(0x0, 0xc8200849c0, 0x100, 0x100, 0xc82005db58, 0x0, 0x0)
    /usr/lib/go/src/syscall/syscall_unix.go:160 +0x4d
os.(*File).read(0xc82002c008, 0xc8200849c0, 0x100, 0x100, 0xffffffff, 0x0, 0x0)
    /usr/lib/go/src/os/file_unix.go:211 +0x53
os.(*File).Read(0xc82002c008, 0xc8200849c0, 0x100, 0x100, 0x0, 0x0, 0x0)
    /usr/lib/go/src/os/file.go:95 +0x8a
golang.org/x/crypto/ssh/terminal.(*Terminal).readLine(0xc820084900, 0x0, 0x0, 0x0, 0x0)
    /home/user/.go/src/golang.org/x/crypto/ssh/terminal/terminal.go:734 +0x4a2
golang.org/x/crypto/ssh/terminal.(*Terminal).ReadLine(0xc820084900, 0x0, 0x0, 0x0, 0x0)
    /home/user/.go/src/golang.org/x/crypto/ssh/terminal/terminal.go:664 +0xac
main.(*Input).ProcessCommands(0xc82050c038, 0xc82001b500)
    /home/user/.go/src/github.com/agl/xmpp-client/input.go:370 +0x2a2
created by main.main
    /home/user/.go/src/github.com/agl/xmpp-client/ui.go:408 +0x2382

goroutine 20 [IO wait]:
net.runtime_pollWait(0x7f1b5c378078, 0x72, 0xc82000a1d0)
    /usr/lib/go/src/runtime/netpoll.go:157 +0x60
net.(*pollDesc).Wait(0xc8201961b0, 0x72, 0x0, 0x0)
    /usr/lib/go/src/net/fd_poll_runtime.go:73 +0x3a
net.(*pollDesc).WaitRead(0xc8201961b0, 0x0, 0x0)
    /usr/lib/go/src/net/fd_poll_runtime.go:78 +0x36
net.(*netFD).Read(0xc820196150, 0xc820198000, 0x4000, 0x4000, 0x0, 0x7f1b5cbb8050, 0xc82000a1d0)
    /usr/lib/go/src/net/fd_unix.go:232 +0x23a
net.(*conn).Read(0xc820168020, 0xc820198000, 0x4000, 0x4000, 0x0, 0x0, 0x0)
    /usr/lib/go/src/net/net.go:172 +0xe4
crypto/tls.(*block).readFromUntil(0xc820164db0, 0x7f1b5c3373a0, 0xc820168020, 0x5, 0x0, 0x0)
    /usr/lib/go/src/crypto/tls/conn.go:455 +0xcc
crypto/tls.(*Conn).readRecord(0xc8201b0000, 0x7fc017, 0x0, 0x0)
    /usr/lib/go/src/crypto/tls/conn.go:540 +0x2d1
crypto/tls.(*Conn).Read(0xc8201b0000, 0xc820178000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
    /usr/lib/go/src/crypto/tls/conn.go:901 +0x167
bufio.(*Reader).fill(0xc82001ac00)
    /usr/lib/go/src/bufio/bufio.go:97 +0x1e9
bufio.(*Reader).ReadByte(0xc82001ac00, 0x0, 0x0, 0x0)
    /usr/lib/go/src/bufio/bufio.go:229 +0x7a
encoding/xml.(*Decoder).getc(0xc82017ab00, 0x0)
    /usr/lib/go/src/encoding/xml/xml.go:861 +0xad
encoding/xml.(*Decoder).rawToken(0xc82017ab00, 0x0, 0x0, 0x0, 0x0)
    /usr/lib/go/src/encoding/xml/xml.go:512 +0x148
encoding/xml.(*Decoder).Token(0xc82017ab00, 0x0, 0x0, 0x0, 0x0)
    /usr/lib/go/src/encoding/xml/xml.go:247 +0xe83
github.com/agl/xmpp-client/xmpp.nextStart(0xc82017ab00, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
    /home/user/.go/src/github.com/agl/xmpp-client/xmpp/xmpp.go:701 +0x93
github.com/agl/xmpp-client/xmpp.next(0xc82016e000, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
    /home/user/.go/src/github.com/agl/xmpp-client/xmpp/xmpp.go:890 +0x7d
github.com/agl/xmpp-client/xmpp.(*Conn).Next(0xc82016e000, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
    /home/user/.go/src/github.com/agl/xmpp-client/xmpp/xmpp.go:103 +0xab
main.(*Session).readMessages(0xc82050c000, 0xc82001b560)
    /home/user/.go/src/github.com/agl/xmpp-client/ui.go:172 +0x62
created by main.main
    /home/user/.go/src/github.com/agl/xmpp-client/ui.go:411 +0x23da

I encountered this while having 2 OTR sessions running. Installed on Archlinux with go get github.com/agl/xmpp-client. I'm sorry but I have no idea on how to reproduce this (or if I did something wrong for that matter).

ghost commented 8 years ago

Got a similar one here on go1.5.1 darwin/amd64, OS X 10.10.5:

In contrast to the other report I only had one OTR conversation open.

While processing message from [redacted]: otr: bad MAC on data message

panic: otr: failed to generate sending keys: otr: internal error: no key slots

goroutine 1 [running]:
golang.org/x/crypto/otr.(*Conversation).generateData(0xc8205ff680, 0xc8203f6b20, 0x1b, 0x20, 0x0, 0x0, 0x0, 0x0)
    /Users/user/go/src/golang.org/x/crypto/otr/otr.go:960 +0x13b
golang.org/x/crypto/otr.(*Conversation).Send(0xc8205ff680, 0xc8203f6b20, 0x1b, 0x20, 0x0, 0x0, 0x0, 0x0, 0x0)
    /Users/user/go/src/golang.org/x/crypto/otr/otr.go:450 +0x170
main.main()
    /Users/user/go/src/github.com/agl/xmpp-client/ui.go:577 +0x5f16

goroutine 17 [syscall, 249 minutes, locked to thread]:
runtime.goexit()
    /usr/local/Cellar/go/1.5.1/libexec/src/runtime/asm_amd64.s:1696 +0x1

goroutine 5 [syscall, 249 minutes]:
os/signal.loop()
    /usr/local/Cellar/go/1.5.1/libexec/src/os/signal/signal_unix.go:22 +0x18
created by os/signal.init.1
    /usr/local/Cellar/go/1.5.1/libexec/src/os/signal/signal_unix.go:28 +0x37

goroutine 6 [chan receive, 249 minutes]:
main.main.func1(0xc820016180, 0xc820080900)
    /Users/user/go/src/github.com/agl/xmpp-client/ui.go:204 +0x4d
created by main.main
    /Users/user/go/src/github.com/agl/xmpp-client/ui.go:207 +0x36e

goroutine 7 [select, 249 minutes, locked to thread]:
runtime.gopark(0x3f6170, 0xc820026f28, 0x364200, 0x6, 0x4f918, 0x2)
    /usr/local/Cellar/go/1.5.1/libexec/src/runtime/proc.go:185 +0x163
runtime.selectgoImpl(0xc820026f28, 0x0, 0x18)
    /usr/local/Cellar/go/1.5.1/libexec/src/runtime/select.go:392 +0xa64
runtime.selectgo(0xc820026f28)
    /usr/local/Cellar/go/1.5.1/libexec/src/runtime/select.go:212 +0x12
runtime.ensureSigM.func1()
    /usr/local/Cellar/go/1.5.1/libexec/src/runtime/signal1_unix.go:227 +0x323
runtime.goexit()
    /usr/local/Cellar/go/1.5.1/libexec/src/runtime/asm_amd64.s:1696 +0x1

goroutine 34 [runnable]:
syscall.Syscall(0x4, 0x0, 0x52dee0, 0x0, 0x0, 0x0, 0x0)
    /usr/local/Cellar/go/1.5.1/libexec/src/syscall/asm_darwin_amd64.s:16 +0x5
syscall.write(0x0, 0xc820112100, 0x0, 0x100, 0xc820097b10, 0x0, 0x0)
    /usr/local/Cellar/go/1.5.1/libexec/src/syscall/zsyscall_darwin_amd64.go:1360 +0x5f
syscall.Write(0x0, 0xc820112100, 0x0, 0x100, 0x0, 0x0, 0x0)
    /usr/local/Cellar/go/1.5.1/libexec/src/syscall/syscall_unix.go:176 +0x4d
os.(*File).write(0xc820028008, 0xc820112100, 0x0, 0x100, 0x0, 0x0, 0x0)
    /usr/local/Cellar/go/1.5.1/libexec/src/os/file_unix.go:232 +0xd0
os.(*File).Write(0xc820028008, 0xc820112100, 0x0, 0x100, 0xfffd, 0x0, 0x0)
    /usr/local/Cellar/go/1.5.1/libexec/src/os/file.go:139 +0x8a
golang.org/x/crypto/ssh/terminal.(*Terminal).readLine(0xc820080900, 0x0, 0x0, 0x0, 0x0)
    /Users/user/go/src/golang.org/x/crypto/ssh/terminal/terminal.go:715 +0x2ff
golang.org/x/crypto/ssh/terminal.(*Terminal).ReadLine(0xc820080900, 0x0, 0x0, 0x0, 0x0)
    /Users/user/go/src/golang.org/x/crypto/ssh/terminal/terminal.go:664 +0xac
main.(*Input).ProcessCommands(0xc8203d2218, 0xc82031a4e0)
    /Users/user/go/src/github.com/agl/xmpp-client/input.go:370 +0x2a2
created by main.main
    /Users/user/go/src/github.com/agl/xmpp-client/ui.go:408 +0x2382

goroutine 35 [IO wait]:
net.runtime_pollWait(0x715708, 0x72, 0xc82000a1b0)
    /usr/local/Cellar/go/1.5.1/libexec/src/runtime/netpoll.go:157 +0x60
net.(*pollDesc).Wait(0xc82005c290, 0x72, 0x0, 0x0)
    /usr/local/Cellar/go/1.5.1/libexec/src/net/fd_poll_runtime.go:73 +0x3a
net.(*pollDesc).WaitRead(0xc82005c290, 0x0, 0x0)
    /usr/local/Cellar/go/1.5.1/libexec/src/net/fd_poll_runtime.go:78 +0x36
net.(*netFD).Read(0xc82005c230, 0xc82012f000, 0x1000, 0x1000, 0x0, 0x710050, 0xc82000a1b0)
    /usr/local/Cellar/go/1.5.1/libexec/src/net/fd_unix.go:232 +0x23a
net.(*conn).Read(0xc820028038, 0xc82012f000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
    /usr/local/Cellar/go/1.5.1/libexec/src/net/net.go:172 +0xe4
crypto/tls.(*block).readFromUntil(0xc820012f90, 0x7157c8, 0xc820028038, 0x5, 0x0, 0x0)
    /usr/local/Cellar/go/1.5.1/libexec/src/crypto/tls/conn.go:455 +0xcc
crypto/tls.(*Conn).readRecord(0xc8200b6580, 0x3f6217, 0x0, 0x0)
    /usr/local/Cellar/go/1.5.1/libexec/src/crypto/tls/conn.go:540 +0x2d1
crypto/tls.(*Conn).Read(0xc8200b6580, 0xc82005a000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
    /usr/local/Cellar/go/1.5.1/libexec/src/crypto/tls/conn.go:901 +0x167
bufio.(*Reader).fill(0xc8203dd800)
    /usr/local/Cellar/go/1.5.1/libexec/src/bufio/bufio.go:97 +0x1e9
bufio.(*Reader).ReadByte(0xc8203dd800, 0x0, 0x0, 0x0)
    /usr/local/Cellar/go/1.5.1/libexec/src/bufio/bufio.go:229 +0x7a
encoding/xml.(*Decoder).getc(0xc82057e6e0, 0x0)
    /usr/local/Cellar/go/1.5.1/libexec/src/encoding/xml/xml.go:861 +0xad
encoding/xml.(*Decoder).rawToken(0xc82057e6e0, 0x0, 0x0, 0x0, 0x0)
    /usr/local/Cellar/go/1.5.1/libexec/src/encoding/xml/xml.go:512 +0x148
encoding/xml.(*Decoder).Token(0xc82057e6e0, 0x0, 0x0, 0x0, 0x0)
    /usr/local/Cellar/go/1.5.1/libexec/src/encoding/xml/xml.go:247 +0xe83
github.com/agl/xmpp-client/xmpp.nextStart(0xc82057e6e0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
    /Users/user/go/src/github.com/agl/xmpp-client/xmpp/xmpp.go:701 +0x93
github.com/agl/xmpp-client/xmpp.next(0xc820016360, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
    /Users/user/go/src/github.com/agl/xmpp-client/xmpp/xmpp.go:890 +0x7d
github.com/agl/xmpp-client/xmpp.(*Conn).Next(0xc820016360, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
    /Users/user/go/src/github.com/agl/xmpp-client/xmpp/xmpp.go:103 +0xab
main.(*Session).readMessages(0xc8203d21e0, 0xc82031a540)
    /Users/user/go/src/github.com/agl/xmpp-client/ui.go:172 +0x62
created by main.main
    /Users/user/go/src/github.com/agl/xmpp-client/ui.go:411 +0x23da

ghost commented 8 years ago

Is this a golang/crypto/otr bug? Seem like this only started happening since 1.5+

christophershirk commented 8 years ago

@hotpatch perhaps, given the change to GOMAXPROCS default in Go 1.5, there's a data race in the otr package. I don't know whether this would be useful, but can you reproduce the crash if you make a one-line change to xmpp-client in main() and call runtime.GOMAXPROCS(1) .. ? or try building xmpp-client with go build -race

ghost commented 8 years ago

@zeroshirts The build plus race detector produced no output and completed successfully so I went ahead and added the call to runtime.GOMAXPROCS (plus the required import) to main() in ui.go.

As far as reproducibility is concerned it seems to "just happen" during conversations, so now with a license to chat^H^H^H^Htest I'll see if it crashes again!

christophershirk commented 8 years ago

@hotpatch just to be clear, the race detector works at runtime, so you'd have to run the resulting executable and then test test test to see if you get anything on stderr from the race detector. I could easily be off base here and the true culprit might just be a logic bug in the otr lib or client app. I should mention that I have no idea what happens in terms of side channels when the race detector instruments the Go crypto code. just FYI. an alternative to testing with the race detector .. could be to add that runtime.GOMAXPROCS(1) line I mentioned, and see if you can get a crash that way.

agl commented 8 years ago

Could you patch in https://gist.github.com/agl/07cb9f83f40e0764c7af and run with that? The resulting error message (if you can reproduce) will be much more helpful. I suspect that the peer's client is getting out of sync with our key-ids. That should never happen, but we still shouldn't crash if it does.

mutantmonkey commented 8 years ago

I had this happen on Linux immediately after receiving otr: bad MAC on data message and renegotiating an OTR session with my peer, so that sounds like that's the issue. I'll patch that in and see if I can reproduce.

mutantmonkey commented 8 years ago

I was able to reproduce this with a different peer who also uses libotr. With that patch, I got this error message: otr: failed to generate sending keys: otr: internal error: no key slots (myKeyId: 1, theirKeyId: 1, slot[2] = {myKeyId: 2, theirKeyId: %!d(MISSING)}, slot[10] = {myKeyId: 9, theirKeyId: %!d(MISSING)}, slot[10] = {myKeyId: 10, theirKeyId: %!d(MISSING)}, slot[2] = {myKeyId: 1, theirKeyId: %!d(MISSING)}

ghost commented 8 years ago

Reproduced this again.

Gist

Details:

Happened after ~8 hours.
Other party uses Pidgin 2.10.11 / libotr 4.1.0 on Windows.
xmpp-client was go install -race'd with the otr patch from suggestions above.

agl commented 8 years ago

https://go-review.googlesource.com/#/c/16934/1 is now out for review to fix this.

agl / xmpp-client

Crash with trace with 2 OTR sessions #96