Opened 4 months ago

Closed 4 months ago

Last modified 3 months ago

#30206 closed defect (fixed)

Segfault in proxy-go

Reported by: irl Owned by: cohosh
Priority: Medium Milestone:
Component: Circumvention/Snowflake Version:
Severity: Normal Keywords:
Cc: dcf, arlolra, cohosh Actual Points:
Parent ID: Points:
Reviewer: Sponsor:

Description

It happened quite quickly, so here's the full output.

2019/04/16 [scrubbed] starting
INFO: configuration.go:174: Created Configuration at  &{[{[stun:stun.l.google.com:19302]  }] All Balanced }
INFO: configuration.go:256: Converting Config:  &{[{[stun:stun.l.google.com:19302]  }] All Balanced }
INFO: peerconnection.go:168: Created PeerConnection:  &{<nil> <nil> false <nil> <nil> <nil> <nil> <nil> <nil> <nil> <nil> <nil> {[{[stun:stun.l.google.com:19302]  }] 3 0 } 0x7f65bc000c60 1} 0x7f65bc000c60
INFO: peerconnection.go:436: fired OnSignalingStateChange:  1 HaveRemoteOffer
2019/04/16 [scrubbed] sdp offer successfully received.
2019/04/16 [scrubbed] Generating answer...
INFO: peerconnection.go:436: fired OnSignalingStateChange:  1 Stable
INFO: peerconnection.go:504: fired OnIceConnectionStateChange:  1
INFO: peerconnection.go:495: fired OnConnectionStateChange:  1
INFO: peerconnection.go:513: fired OnIceGatheringStateChange: 1
INFO: peerconnection.go:459: fired OnIceCandidate:  1 candidate:1020330603 1 udp 2122262783 2001:470:1d58:1337:2066:3507:9c2e:9cc8 39908 typ host generation 0 ufrag gUW/ network-id 2 network-cost 50
INFO: peerconnection.go:459: fired OnIceCandidate:  1 candidate:498995695 1 udp 2122194687 172.22.152.130 59852 typ host generation 0 ufrag gUW/ network-id 1 network-cost 50
INFO: peerconnection.go:459: fired OnIceCandidate:  1 candidate:3509792380 1 udp 1685987071 84.92.41.201 59913 typ srflx raddr 172.22.152.130 rport 59852 generation 0 ufrag gUW/ network-id 1 network-cost 50
INFO: peerconnection.go:459: fired OnIceCandidate:  1 candidate:1918041755 1 tcp 1518283007 2001:470:1d58:1337:2066:3507:9c2e:9cc8 34045 typ host tcptype passive generation 0 ufrag gUW/ network-id 2 network-cost 50
INFO: peerconnection.go:459: fired OnIceCandidate:  1 candidate:1396567327 1 tcp 1518214911 172.22.152.130 54255 typ host tcptype passive generation 0 ufrag gUW/ network-id 1 network-cost 50
INFO: peerconnection.go:513: fired OnIceGatheringStateChange: 1
INFO: peerconnection.go:504: fired OnIceConnectionStateChange:  1
INFO: peerconnection.go:495: fired OnConnectionStateChange:  1
INFO: peerconnection.go:527: fired OnDataChannel:  1 0x7f6584008960
2019/04/16 [scrubbed] OnDataChannel
2019/04/16 [scrubbed] OnOpen channel
2019/04/16 [scrubbed] connected to relay
INFO: configuration.go:256: Converting Config:  &{[{[stun:stun.l.google.com:19302]  }] All Balanced }
INFO: peerconnection.go:168: Created PeerConnection:  &{<nil> <nil> false <nil> <nil> <nil> <nil> <nil> <nil> <nil> <nil> <nil> {[{[stun:stun.l.google.com:19302]  }] 3 0 } 0x7f6580000b20 2} 0x7f6580000b20
INFO: peerconnection.go:436: fired OnSignalingStateChange:  2 HaveRemoteOffer
2019/04/16 [scrubbed] sdp offer successfully received.
2019/04/16 [scrubbed] Generating answer...
INFO: peerconnection.go:436: fired OnSignalingStateChange:  2 Stable
INFO: peerconnection.go:504: fired OnIceConnectionStateChange:  2
INFO: peerconnection.go:495: fired OnConnectionStateChange:  2
INFO: peerconnection.go:513: fired OnIceGatheringStateChange: 2
INFO: peerconnection.go:459: fired OnIceCandidate:  2 candidate:1020330603 1 udp 2122262783 2001:470:1d58:1337:2066:3507:9c2e:9cc8 59602 typ host generation 0 ufrag ZK+V network-id 2 network-cost 50
INFO: peerconnection.go:459: fired OnIceCandidate:  2 candidate:498995695 1 udp 2122194687 172.22.152.130 58452 typ host generation 0 ufrag ZK+V network-id 1 network-cost 50
INFO: peerconnection.go:459: fired OnIceCandidate:  2 candidate:3509792380 1 udp 1685987071 84.92.41.201 59538 typ srflx raddr 172.22.152.130 rport 58452 generation 0 ufrag ZK+V network-id 1 network-cost 50
INFO: peerconnection.go:459: fired OnIceCandidate:  2 candidate:1918041755 1 tcp 1518283007 2001:470:1d58:1337:2066:3507:9c2e:9cc8 33335 typ host tcptype passive generation 0 ufrag ZK+V network-id 2 network-cost 50
INFO: peerconnection.go:459: fired OnIceCandidate:  2 candidate:1396567327 1 tcp 1518214911 172.22.152.130 55661 typ host tcptype passive generation 0 ufrag ZK+V network-id 1 network-cost 50
INFO: peerconnection.go:513: fired OnIceGatheringStateChange: 2
INFO: peerconnection.go:504: fired OnIceConnectionStateChange:  2
INFO: peerconnection.go:495: fired OnConnectionStateChange:  2
INFO: peerconnection.go:527: fired OnDataChannel:  2 0x7f656800a310
2019/04/16 [scrubbed] OnDataChannel
2019/04/16 [scrubbed] OnOpen channel
2019/04/16 [scrubbed] connected to relay
INFO: configuration.go:256: Converting Config:  &{[{[stun:stun.l.google.com:19302]  }] All Balanced }
INFO: peerconnection.go:168: Created PeerConnection:  &{<nil> <nil> false <nil> <nil> <nil> <nil> <nil> <nil> <nil> <nil> <nil> {[{[stun:stun.l.google.com:19302]  }] 3 0 } 0x7f658c000b20 3} 0x7f658c000b20
INFO: peerconnection.go:436: fired OnSignalingStateChange:  3 HaveRemoteOffer
2019/04/16 [scrubbed] sdp offer successfully received.
2019/04/16 [scrubbed] Generating answer...
INFO: peerconnection.go:436: fired OnSignalingStateChange:  3 Stable
INFO: peerconnection.go:504: fired OnIceConnectionStateChange:  3
INFO: peerconnection.go:495: fired OnConnectionStateChange:  3
INFO: peerconnection.go:513: fired OnIceGatheringStateChange: 3
INFO: peerconnection.go:459: fired OnIceCandidate:  3 candidate:1020330603 1 udp 2122262783 2001:470:1d58:1337:2066:3507:9c2e:9cc8 36827 typ host generation 0 ufrag Ixjw network-id 2 network-cost 50
INFO: peerconnection.go:459: fired OnIceCandidate:  3 candidate:498995695 1 udp 2122194687 172.22.152.130 47070 typ host generation 0 ufrag Ixjw network-id 1 network-cost 50
INFO: peerconnection.go:459: fired OnIceCandidate:  3 candidate:3509792380 1 udp 1685987071 84.92.41.201 62688 typ srflx raddr 172.22.152.130 rport 47070 generation 0 ufrag Ixjw network-id 1 network-cost 50
INFO: peerconnection.go:459: fired OnIceCandidate:  3 candidate:1918041755 1 tcp 1518283007 2001:470:1d58:1337:2066:3507:9c2e:9cc8 56747 typ host tcptype passive generation 0 ufrag Ixjw network-id 2 network-cost 50
INFO: peerconnection.go:459: fired OnIceCandidate:  3 candidate:1396567327 1 tcp 1518214911 172.22.152.130 42273 typ host tcptype passive generation 0 ufrag Ixjw network-id 1 network-cost 50
INFO: peerconnection.go:513: fired OnIceGatheringStateChange: 3
INFO: peerconnection.go:504: fired OnIceConnectionStateChange:  3
INFO: peerconnection.go:495: fired OnConnectionStateChange:  3
INFO: peerconnection.go:527: fired OnDataChannel:  3 0x7f6550001130
2019/04/16 [scrubbed] OnDataChannel
2019/04/16 [scrubbed] OnOpen channel
2019/04/16 [scrubbed] connected to relay
INFO: configuration.go:256: Converting Config:  &{[{[stun:stun.l.google.com:19302]  }] All Balanced }
INFO: peerconnection.go:168: Created PeerConnection:  &{<nil> <nil> false <nil> <nil> <nil> <nil> <nil> <nil> <nil> <nil> <nil> {[{[stun:stun.l.google.com:19302]  }] 3 0 } 0x7f658c064d20 4} 0x7f658c064d20
INFO: peerconnection.go:436: fired OnSignalingStateChange:  4 HaveRemoteOffer
2019/04/16 [scrubbed] sdp offer successfully received.
2019/04/16 [scrubbed] Generating answer...
INFO: peerconnection.go:436: fired OnSignalingStateChange:  4 Stable
INFO: peerconnection.go:504: fired OnIceConnectionStateChange:  4
INFO: peerconnection.go:495: fired OnConnectionStateChange:  4
INFO: peerconnection.go:513: fired OnIceGatheringStateChange: 4
INFO: peerconnection.go:459: fired OnIceCandidate:  4 candidate:1020330603 1 udp 2122262783 2001:470:1d58:1337:2066:3507:9c2e:9cc8 34485 typ host generation 0 ufrag TTEP network-id 2 network-cost 50
INFO: peerconnection.go:459: fired OnIceCandidate:  4 candidate:498995695 1 udp 2122194687 172.22.152.130 45068 typ host generation 0 ufrag TTEP network-id 1 network-cost 50
INFO: peerconnection.go:459: fired OnIceCandidate:  4 candidate:3509792380 1 udp 1685987071 84.92.41.201 51346 typ srflx raddr 172.22.152.130 rport 45068 generation 0 ufrag TTEP network-id 1 network-cost 50
INFO: peerconnection.go:459: fired OnIceCandidate:  4 candidate:1918041755 1 tcp 1518283007 2001:470:1d58:1337:2066:3507:9c2e:9cc8 47037 typ host tcptype passive generation 0 ufrag TTEP network-id 2 network-cost 50
INFO: peerconnection.go:459: fired OnIceCandidate:  4 candidate:1396567327 1 tcp 1518214911 172.22.152.130 41629 typ host tcptype passive generation 0 ufrag TTEP network-id 1 network-cost 50
INFO: peerconnection.go:513: fired OnIceGatheringStateChange: 4
INFO: peerconnection.go:504: fired OnIceConnectionStateChange:  4
INFO: peerconnection.go:495: fired OnConnectionStateChange:  4
INFO: peerconnection.go:527: fired OnDataChannel:  4 0x7f654000ad40
2019/04/16 [scrubbed] OnDataChannel
2019/04/16 [scrubbed] OnOpen channel
2019/04/16 [scrubbed] connected to relay
2019/04/16 [scrubbed] OnClose channel
INFO: peerconnection.go:504: fired OnIceConnectionStateChange:  1
INFO: peerconnection.go:436: fired OnSignalingStateChange:  1 Closed
2019/04/16 [scrubbed] datachannelHandler ends
INFO: configuration.go:256: Converting Config:  &{[{[stun:stun.l.google.com:19302]  }] All Balanced }
INFO: peerconnection.go:168: Created PeerConnection:  &{<nil> <nil> false <nil> <nil> <nil> <nil> <nil> <nil> <nil> <nil> <nil> {[{[stun:stun.l.google.com:19302]  }] 3 0 } 0x7f6580064f40 5} 0x7f6580064f40
INFO: peerconnection.go:436: fired OnSignalingStateChange:  5 HaveRemoteOffer
2019/04/16 [scrubbed] sdp offer successfully received.
2019/04/16 [scrubbed] Generating answer...
INFO: peerconnection.go:436: fired OnSignalingStateChange:  5 Stable
INFO: peerconnection.go:504: fired OnIceConnectionStateChange:  5
INFO: peerconnection.go:495: fired OnConnectionStateChange:  5
INFO: peerconnection.go:513: fired OnIceGatheringStateChange: 5
INFO: peerconnection.go:459: fired OnIceCandidate:  5 candidate:1020330603 1 udp 2122262783 2001:470:1d58:1337:2066:3507:9c2e:9cc8 35400 typ host generation 0 ufrag qYdh network-id 2 network-cost 50
INFO: peerconnection.go:459: fired OnIceCandidate:  5 candidate:498995695 1 udp 2122194687 172.22.152.130 39835 typ host generation 0 ufrag qYdh network-id 1 network-cost 50
INFO: peerconnection.go:459: fired OnIceCandidate:  5 candidate:3509792380 1 udp 1685987071 84.92.41.201 63045 typ srflx raddr 172.22.152.130 rport 39835 generation 0 ufrag qYdh network-id 1 network-cost 50
INFO: peerconnection.go:459: fired OnIceCandidate:  5 candidate:1918041755 1 tcp 1518283007 2001:470:1d58:1337:2066:3507:9c2e:9cc8 55769 typ host tcptype passive generation 0 ufrag qYdh network-id 2 network-cost 50
INFO: peerconnection.go:459: fired OnIceCandidate:  5 candidate:1396567327 1 tcp 1518214911 172.22.152.130 55571 typ host tcptype passive generation 0 ufrag qYdh network-id 1 network-cost 50
INFO: peerconnection.go:513: fired OnIceGatheringStateChange: 5
INFO: peerconnection.go:504: fired OnIceConnectionStateChange:  5
INFO: peerconnection.go:495: fired OnConnectionStateChange:  5
INFO: peerconnection.go:527: fired OnDataChannel:  5 0x7f658400af30
2019/04/16 [scrubbed] OnDataChannel
2019/04/16 [scrubbed] OnOpen channel
2019/04/16 [scrubbed] connected to relay
2019/04/16 [scrubbed] OnClose channel
INFO: peerconnection.go:504: fired OnIceConnectionStateChange:  2
INFO: peerconnection.go:436: fired OnSignalingStateChange:  2 Closed
2019/04/16 [scrubbed] datachannelHandler ends
2019/04/16 [scrubbed] OnClose channel
INFO: peerconnection.go:504: fired OnIceConnectionStateChange:  3
INFO: peerconnection.go:436: fired OnSignalingStateChange:  3 Closed
2019/04/16 [scrubbed] datachannelHandler ends
INFO: configuration.go:256: Converting Config:  &{[{[stun:stun.l.google.com:19302]  }] All Balanced }
INFO: peerconnection.go:168: Created PeerConnection:  &{<nil> <nil> false <nil> <nil> <nil> <nil> <nil> <nil> <nil> <nil> <nil> {[{[stun:stun.l.google.com:19302]  }] 3 0 } 0x7f6580061920 6} 0x7f6580061920
INFO: peerconnection.go:436: fired OnSignalingStateChange:  6 HaveRemoteOffer
2019/04/16 [scrubbed] sdp offer successfully received.
2019/04/16 [scrubbed] Generating answer...
INFO: peerconnection.go:436: fired OnSignalingStateChange:  6 Stable
INFO: peerconnection.go:504: fired OnIceConnectionStateChange:  6
INFO: peerconnection.go:495: fired OnConnectionStateChange:  6
INFO: peerconnection.go:513: fired OnIceGatheringStateChange: 6
INFO: peerconnection.go:459: fired OnIceCandidate:  6 candidate:1020330603 1 udp 2122262783 2001:470:1d58:1337:2066:3507:9c2e:9cc8 59583 typ host generation 0 ufrag eVKt network-id 2 network-cost 50
INFO: peerconnection.go:459: fired OnIceCandidate:  6 candidate:498995695 1 udp 2122194687 172.22.152.130 47513 typ host generation 0 ufrag eVKt network-id 1 network-cost 50
INFO: peerconnection.go:459: fired OnIceCandidate:  6 candidate:3509792380 1 udp 1685987071 84.92.41.201 50031 typ srflx raddr 172.22.152.130 rport 47513 generation 0 ufrag eVKt network-id 1 network-cost 50
INFO: peerconnection.go:459: fired OnIceCandidate:  6 candidate:1918041755 1 tcp 1518283007 2001:470:1d58:1337:2066:3507:9c2e:9cc8 59003 typ host tcptype passive generation 0 ufrag eVKt network-id 2 network-cost 50
INFO: peerconnection.go:459: fired OnIceCandidate:  6 candidate:1396567327 1 tcp 1518214911 172.22.152.130 49119 typ host tcptype passive generation 0 ufrag eVKt network-id 1 network-cost 50
INFO: peerconnection.go:513: fired OnIceGatheringStateChange: 6
INFO: peerconnection.go:504: fired OnIceConnectionStateChange:  6
INFO: peerconnection.go:495: fired OnConnectionStateChange:  6
INFO: peerconnection.go:527: fired OnDataChannel:  6 0x7f655000adf0
2019/04/16 [scrubbed] OnDataChannel
2019/04/16 [scrubbed] OnOpen channel
2019/04/16 [scrubbed] connected to relay
INFO: configuration.go:256: Converting Config:  &{[{[stun:stun.l.google.com:19302]  }] All Balanced }
INFO: peerconnection.go:168: Created PeerConnection:  &{<nil> <nil> false <nil> <nil> <nil> <nil> <nil> <nil> <nil> <nil> <nil> {[{[stun:stun.l.google.com:19302]  }] 3 0 } 0x7f6580000b20 7} 0x7f6580000b20
INFO: peerconnection.go:436: fired OnSignalingStateChange:  7 HaveRemoteOffer
2019/04/16 [scrubbed] sdp offer successfully received.
2019/04/16 [scrubbed] Generating answer...
INFO: peerconnection.go:436: fired OnSignalingStateChange:  7 Stable
INFO: peerconnection.go:504: fired OnIceConnectionStateChange:  7
INFO: peerconnection.go:495: fired OnConnectionStateChange:  7
INFO: peerconnection.go:513: fired OnIceGatheringStateChange: 7
INFO: peerconnection.go:459: fired OnIceCandidate:  7 candidate:1020330603 1 udp 2122262783 2001:470:1d58:1337:2066:3507:9c2e:9cc8 50955 typ host generation 0 ufrag cbJC network-id 2 network-cost 50
INFO: peerconnection.go:459: fired OnIceCandidate:  7 candidate:498995695 1 udp 2122194687 172.22.152.130 39725 typ host generation 0 ufrag cbJC network-id 1 network-cost 50
INFO: peerconnection.go:459: fired OnIceCandidate:  7 candidate:3509792380 1 udp 1685987071 84.92.41.201 60984 typ srflx raddr 172.22.152.130 rport 39725 generation 0 ufrag cbJC network-id 1 network-cost 50
INFO: peerconnection.go:459: fired OnIceCandidate:  7 candidate:1918041755 1 tcp 1518283007 2001:470:1d58:1337:2066:3507:9c2e:9cc8 49269 typ host tcptype passive generation 0 ufrag cbJC network-id 2 network-cost 50
INFO: peerconnection.go:459: fired OnIceCandidate:  7 candidate:1396567327 1 tcp 1518214911 172.22.152.130 35571 typ host tcptype passive generation 0 ufrag cbJC network-id 1 network-cost 50
INFO: peerconnection.go:513: fired OnIceGatheringStateChange: 7
INFO: peerconnection.go:504: fired OnIceConnectionStateChange:  7
INFO: peerconnection.go:495: fired OnConnectionStateChange:  7
INFO: peerconnection.go:527: fired OnDataChannel:  7 0x7f6544008100
2019/04/16 [scrubbed] OnDataChannel
2019/04/16 [scrubbed] OnOpen channel
2019/04/16 [scrubbed] OnMessage <--- 200 bytes
2019/04/16 [scrubbed] connected to relay
2019/04/16 [scrubbed] Write 754 bytes --> WebRTC
2019/04/16 [scrubbed] OnMessage <--- 126 bytes
2019/04/16 [scrubbed] Write 51 bytes --> WebRTC
2019/04/16 [scrubbed] OnMessage <--- 40 bytes
2019/04/16 [scrubbed] Write 1524 bytes --> WebRTC
2019/04/16 [scrubbed] OnMessage <--- 1057 bytes
2019/04/16 [scrubbed] Write 543 bytes --> WebRTC
2019/04/16 [scrubbed] OnClose channel
INFO: peerconnection.go:504: fired OnIceConnectionStateChange:  4
INFO: peerconnection.go:436: fired OnSignalingStateChange:  4 Closed
2019/04/16 [scrubbed] datachannelHandler ends
2019/04/16 [scrubbed] broker returns: 504
fatal error: unexpected signal during runtime execution
[signal SIGSEGV: segmentation violation code=0x1 addr=0x0 pc=0x66a11a]

runtime stack:
runtime.throw(0xeea8ff, 0x2a)
	/usr/lib/go-1.11/src/runtime/panic.go:608 +0x72
runtime.sigpanic()
	/usr/lib/go-1.11/src/runtime/signal_unix.go:374 +0x2f2

goroutine 43 [syscall]:
runtime.cgocall(0x668210, 0xc000249748, 0xc0004c8300)
	/usr/lib/go-1.11/src/runtime/cgocall.go:128 +0x5e fp=0xc000249718 sp=0xc0002496e0 pc=0x41c51e
github.com/keroserene/go-webrtc._Cfunc_CGO_IceConnectionState(0x7f65bc000c60, 0x7f6500000000)
	_cgo_gotypes.go:555 +0x49 fp=0xc000249748 sp=0xc000249718 pc=0x6578f9
github.com/keroserene/go-webrtc.(*PeerConnection).ConnectionState.func1(0x7f65bc000c60, 0xc000270101)
	/home/irl/go/src/github.com/keroserene/go-webrtc/peerconnection.go:286 +0x56 fp=0xc000249780 sp=0xc000249748 pc=0x65cd26
github.com/keroserene/go-webrtc.(*PeerConnection).ConnectionState(0xc0000d62c0, 0x0)
	/home/irl/go/src/github.com/keroserene/go-webrtc/peerconnection.go:286 +0x32 fp=0xc0002497a0 sp=0xc000249780 pc=0x65aba2
main.makePeerConnectionFromOffer.func3(0xc0000d62c0)
	/tmp/snowflake/proxy-go/snowflake.go:339 +0x59 fp=0xc0002497d8 sp=0xc0002497a0 pc=0x667179
runtime.goexit()
	/usr/lib/go-1.11/src/runtime/asm_amd64.s:1333 +0x1 fp=0xc0002497e0 sp=0xc0002497d8 pc=0x46ff51
created by main.makePeerConnectionFromOffer
	/tmp/snowflake/proxy-go/snowflake.go:337 +0x35d

goroutine 1 [select]:
net/http.(*http2ClientConn).roundTrip(0xc000346c40, 0xc0004c0000, 0x0, 0x0, 0x0, 0x0)
	/usr/lib/go-1.11/src/net/http/h2_bundle.go:7665 +0x7cc
net/http.(*http2Transport).RoundTripOpt(0xc0000aa410, 0xc0004c0000, 0x0, 0x30000c0002c212b, 0x42ac1c, 0xedebef)
	/usr/lib/go-1.11/src/net/http/h2_bundle.go:7037 +0x153
net/http.(*http2Transport).RoundTrip(0xc0000aa410, 0xc0004c0000, 0xc0004d6240, 0x128e310, 0x0)
	/usr/lib/go-1.11/src/net/http/h2_bundle.go:6999 +0x3a
net/http.http2noDialH2RoundTripper.RoundTrip(0xc0000aa410, 0xc0004c0000, 0xc0004ce540, 0x5, 0xc0000c1168)
	/usr/lib/go-1.11/src/net/http/h2_bundle.go:1019 +0x39
net/http.(*Transport).roundTrip(0x128e380, 0xc0004c0000, 0x203000, 0xc000129a30, 0x5fd22d)
	/usr/lib/go-1.11/src/net/http/transport.go:415 +0xd4c
net/http.(*Transport).RoundTrip(0x128e380, 0xc0004c0000, 0x128e380, 0x0, 0x0)
	/usr/lib/go-1.11/src/net/http/roundtrip.go:17 +0x35
net/http.send(0xc0004c0000, 0xf27f60, 0x128e380, 0x0, 0x0, 0x0, 0xc00000e040, 0x7f65e649b440, 0xc000129ac0, 0x1)
	/usr/lib/go-1.11/src/net/http/client.go:250 +0x14b
net/http.(*Client).send(0x12c01a0, 0xc0004c0000, 0x0, 0x0, 0x0, 0xc00000e040, 0x0, 0x1, 0xc0001eb500)
	/usr/lib/go-1.11/src/net/http/client.go:174 +0xfa
net/http.(*Client).do(0x12c01a0, 0xc0004c0000, 0x0, 0x0, 0x0)
	/usr/lib/go-1.11/src/net/http/client.go:641 +0x2a8
net/http.(*Client).Do(0x12c01a0, 0xc0004c0000, 0xc, 0xc000374280, 0x16)
	/usr/lib/go-1.11/src/net/http/client.go:509 +0x35
main.pollOffer(0xc000374280, 0x16, 0x0)
	/tmp/snowflake/proxy-go/snowflake.go:157 +0x37f
main.runSession(0xc000374280, 0x16)
	/tmp/snowflake/proxy-go/snowflake.go:351 +0x39
main.main()
	/tmp/snowflake/proxy-go/snowflake.go:423 +0x5ba

goroutine 80 [semacquire]:
sync.runtime_Semacquire(0xc0002dd768)
	/usr/lib/go-1.11/src/runtime/sema.go:56 +0x39
sync.(*WaitGroup).Wait(0xc0002dd760)
	/usr/lib/go-1.11/src/sync/waitgroup.go:130 +0x64
main.CopyLoopTimeout(0xf2b6e0, 0xc0001ad2f0, 0xf2b680, 0xc0001743f0, 0xdf8475800)
	/tmp/snowflake/proxy-go/snowflake.go:223 +0x253
main.datachannelHandler(0xc0001ad2f0, 0xf29660, 0xc0001ad380)
	/tmp/snowflake/proxy-go/snowflake.go:258 +0x383
created by main.makePeerConnectionFromOffer.func2
	/tmp/snowflake/proxy-go/snowflake.go:303 +0x2ac

goroutine 12 [IO wait]:
internal/poll.runtime_pollWait(0x7f65e1a49f00, 0x72, 0xc000231870)
	/usr/lib/go-1.11/src/runtime/netpoll.go:173 +0x66
internal/poll.(*pollDesc).wait(0xc0001d6098, 0x72, 0xffffffffffffff00, 0xf28a00, 0x12940d0)
	/usr/lib/go-1.11/src/internal/poll/fd_poll_runtime.go:85 +0x9a
internal/poll.(*pollDesc).waitRead(0xc0001d6098, 0xc0001f6000, 0x1000, 0x1000)
	/usr/lib/go-1.11/src/internal/poll/fd_poll_runtime.go:90 +0x3d
internal/poll.(*FD).Read(0xc0001d6080, 0xc0001f6000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
	/usr/lib/go-1.11/src/internal/poll/fd_unix.go:169 +0x179
net.(*netFD).Read(0xc0001d6080, 0xc0001f6000, 0x1000, 0x1000, 0x421cdb, 0x1290d00, 0xe943e0)
	/usr/lib/go-1.11/src/net/fd_unix.go:202 +0x4f
net.(*conn).Read(0xc0001bc010, 0xc0001f6000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
	/usr/lib/go-1.11/src/net/net.go:177 +0x68
crypto/tls.(*block).readFromUntil(0xc0001ac1e0, 0xf27f00, 0xc0001bc010, 0x5, 0xc0001bc010, 0x0)
	/usr/lib/go-1.11/src/crypto/tls/conn.go:492 +0x89
crypto/tls.(*Conn).readRecord(0xc0001ea000, 0xef3617, 0xc0001ea120, 0x0)
	/usr/lib/go-1.11/src/crypto/tls/conn.go:593 +0xdd
crypto/tls.(*Conn).Read(0xc0001ea000, 0xc00016b000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
	/usr/lib/go-1.11/src/crypto/tls/conn.go:1145 +0xf1
bufio.(*Reader).Read(0xc0001b4ba0, 0xc0005443b8, 0x9, 0x9, 0x100000000000009, 0x0, 0x10)
	/usr/lib/go-1.11/src/bufio/bufio.go:216 +0x22f
io.ReadAtLeast(0xf27ba0, 0xc0001b4ba0, 0xc0005443b8, 0x9, 0x9, 0x9, 0xc0004d6180, 0x10, 0xeb7a40)
	/usr/lib/go-1.11/src/io/io.go:310 +0x88
io.ReadFull(0xf27ba0, 0xc0001b4ba0, 0xc0005443b8, 0x9, 0x9, 0xf4b1a374b92e2501, 0x3, 0xc000024570)
	/usr/lib/go-1.11/src/io/io.go:329 +0x58
net/http.http2readFrameHeader(0xc0005443b8, 0x9, 0x9, 0xf27ba0, 0xc0001b4ba0, 0x0, 0x0, 0xc00026f3a0, 0xc000231db8)
	/usr/lib/go-1.11/src/net/http/h2_bundle.go:1545 +0x7b
net/http.(*http2Framer).ReadFrame(0xc000544380, 0xc00026f3a0, 0x0, 0x0, 0x0)
	/usr/lib/go-1.11/src/net/http/h2_bundle.go:1803 +0xa3
net/http.(*http2clientConnReadLoop).run(0xc000231fb8, 0xef3098, 0xc00048b7b8)
	/usr/lib/go-1.11/src/net/http/h2_bundle.go:8263 +0x9e
net/http.(*http2ClientConn).readLoop(0xc000346c40)
	/usr/lib/go-1.11/src/net/http/h2_bundle.go:8191 +0x76
created by net/http.(*http2Transport).newClientConn
	/usr/lib/go-1.11/src/net/http/h2_bundle.go:7264 +0x636

goroutine 81 [IO wait]:
internal/poll.runtime_pollWait(0x7f65e1a49e30, 0x72, 0xc00022c8d0)
	/usr/lib/go-1.11/src/runtime/netpoll.go:173 +0x66
internal/poll.(*pollDesc).wait(0xc000020d98, 0x72, 0xffffffffffffff00, 0xf28a00, 0x12940d0)
	/usr/lib/go-1.11/src/internal/poll/fd_poll_runtime.go:85 +0x9a
internal/poll.(*pollDesc).waitRead(0xc000020d98, 0xc000525400, 0x400, 0x400)
	/usr/lib/go-1.11/src/internal/poll/fd_poll_runtime.go:90 +0x3d
internal/poll.(*FD).Read(0xc000020d80, 0xc000525400, 0x400, 0x400, 0x0, 0x0, 0x0)
	/usr/lib/go-1.11/src/internal/poll/fd_unix.go:169 +0x179
net.(*netFD).Read(0xc000020d80, 0xc000525400, 0x400, 0x400, 0x421cdb, 0x1290d00, 0xe943e0)
	/usr/lib/go-1.11/src/net/fd_unix.go:202 +0x4f
net.(*conn).Read(0xc00000e188, 0xc000525400, 0x400, 0x400, 0x0, 0x0, 0x0)
	/usr/lib/go-1.11/src/net/net.go:177 +0x68
crypto/tls.(*block).readFromUntil(0xc0001ad440, 0xf27f00, 0xc00000e188, 0x5, 0xc00000e188, 0x3)
	/usr/lib/go-1.11/src/crypto/tls/conn.go:492 +0x89
crypto/tls.(*Conn).readRecord(0xc0004ae380, 0xef3617, 0xc0004ae4a0, 0x40)
	/usr/lib/go-1.11/src/crypto/tls/conn.go:593 +0xdd
crypto/tls.(*Conn).Read(0xc0004ae380, 0xc000415000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
	/usr/lib/go-1.11/src/crypto/tls/conn.go:1145 +0xf1
bufio.(*Reader).fill(0xc000076ea0)
	/usr/lib/go-1.11/src/bufio/bufio.go:100 +0x10f
bufio.(*Reader).ReadByte(0xc000076ea0, 0xc0000ab3b0, 0x49c332, 0xc000020d80)
	/usr/lib/go-1.11/src/bufio/bufio.go:242 +0x39
golang.org/x/net/websocket.hybiFrameReaderFactory.NewFrameReader(0xc000076ea0, 0xef3600, 0xc000174418, 0xbf25b0e43acddb06, 0x170eb2420c)
	/home/irl/go/src/golang.org/x/net/websocket/hybi.go:123 +0x60
golang.org/x/net/websocket.(*Conn).Read(0xc0001743f0, 0xc00060e000, 0x8000, 0x8000, 0x0, 0x0, 0x0)
	/home/irl/go/src/golang.org/x/net/websocket/websocket.go:197 +0x1b1
main.timeoutConn.Read(0xf2b680, 0xc0001743f0, 0xdf8475800, 0xc00060e000, 0x8000, 0x8000, 0xe78f60, 0x1, 0xc00060e000)
	/tmp/snowflake/proxy-go/snowflake.go:198 +0x99
io.copyBuffer(0x7f65e1a4a518, 0xc0002c46a0, 0x7f65e1a4a538, 0xc0002c46c0, 0xc00060e000, 0x8000, 0x8000, 0xeb7080, 0x0, 0x7f65e1a4a538)
	/usr/lib/go-1.11/src/io/io.go:402 +0x125
io.Copy(0x7f65e1a4a518, 0xc0002c46a0, 0x7f65e1a4a538, 0xc0002c46c0, 0xc0002c46c0, 0xc000118300, 0x5348fe)
	/usr/lib/go-1.11/src/io/io.go:364 +0x5a
main.CopyLoopTimeout.func1(0xf2a660, 0xc0002c46a0, 0xf2a660, 0xc0002c46c0)
	/tmp/snowflake/proxy-go/snowflake.go:216 +0xd2
created by main.CopyLoopTimeout
	/tmp/snowflake/proxy-go/snowflake.go:221 +0x16d

goroutine 71 [chan receive]:
main.makePeerConnectionFromOffer.func3(0xc0000d6580)
	/tmp/snowflake/proxy-go/snowflake.go:338 +0x4b
created by main.makePeerConnectionFromOffer
	/tmp/snowflake/proxy-go/snowflake.go:337 +0x35d

goroutine 78 [chan receive]:
main.makePeerConnectionFromOffer.func3(0xc0000d66e0)
	/tmp/snowflake/proxy-go/snowflake.go:338 +0x4b
created by main.makePeerConnectionFromOffer
	/tmp/snowflake/proxy-go/snowflake.go:337 +0x35d

goroutine 69 [chan receive]:
main.makePeerConnectionFromOffer.func3(0xc0000d6370)
	/tmp/snowflake/proxy-go/snowflake.go:338 +0x4b
created by main.makePeerConnectionFromOffer
	/tmp/snowflake/proxy-go/snowflake.go:337 +0x35d

goroutine 105 [select]:
io.(*pipe).Read(0xc0000aa140, 0xc0000b0000, 0x8000, 0x8000, 0x1b, 0x1b, 0xc000374660)
	/usr/lib/go-1.11/src/io/pipe.go:50 +0xea
io.(*PipeReader).Read(0xc000206000, 0xc0000b0000, 0x8000, 0x8000, 0x0, 0xf27d80, 0xc0002ec240)
	/usr/lib/go-1.11/src/io/pipe.go:127 +0x4c
main.(*webRTCConn).Read(0xc0001ac000, 0xc0000b0000, 0x8000, 0x8000, 0xf27d80, 0xc0002ec240, 0x12c0400)
	/tmp/snowflake/proxy-go/snowflake.go:77 +0x4d
main.timeoutConn.Read(0xf2b6e0, 0xc0001ac000, 0xdf8475800, 0xc0000b0000, 0x8000, 0x8000, 0x421, 0x0, 0x0)
	/tmp/snowflake/proxy-go/snowflake.go:198 +0x99
io.copyBuffer(0x7f65e1a4a518, 0xc0002d2060, 0x7f65e1a4a538, 0xc0002d2080, 0xc0000b0000, 0x8000, 0x8000, 0xeb7080, 0xc000576200, 0x7f65e1a4a538)
	/usr/lib/go-1.11/src/io/io.go:402 +0x125
io.Copy(0x7f65e1a4a518, 0xc0002d2060, 0x7f65e1a4a538, 0xc0002d2080, 0xc0002d2080, 0x0, 0x0)
	/usr/lib/go-1.11/src/io/io.go:364 +0x5a
main.CopyLoopTimeout.func1(0xf2a660, 0xc0002d2060, 0xf2a660, 0xc0002d2080)
	/tmp/snowflake/proxy-go/snowflake.go:216 +0xd2
created by main.CopyLoopTimeout
	/tmp/snowflake/proxy-go/snowflake.go:222 +0x245

goroutine 102 [chan receive]:
main.makePeerConnectionFromOffer.func3(0xc00040e0b0)
	/tmp/snowflake/proxy-go/snowflake.go:338 +0x4b
created by main.makePeerConnectionFromOffer
	/tmp/snowflake/proxy-go/snowflake.go:337 +0x35d

goroutine 117 [semacquire]:
sync.runtime_Semacquire(0xc00026e678)
	/usr/lib/go-1.11/src/runtime/sema.go:56 +0x39
sync.(*WaitGroup).Wait(0xc00026e670)
	/usr/lib/go-1.11/src/sync/waitgroup.go:130 +0x64
main.CopyLoopTimeout(0xf2b6e0, 0xc0003ff8f0, 0xf2b680, 0xc0002a8630, 0xdf8475800)
	/tmp/snowflake/proxy-go/snowflake.go:223 +0x253
main.datachannelHandler(0xc0003ff8f0, 0xf29660, 0xc0003ff980)
	/tmp/snowflake/proxy-go/snowflake.go:258 +0x383
created by main.makePeerConnectionFromOffer.func2
	/tmp/snowflake/proxy-go/snowflake.go:303 +0x2ac

goroutine 82 [select]:
io.(*pipe).Read(0xc0000aaa00, 0xc000606000, 0x8000, 0x8000, 0x1b, 0x1b, 0xc000357480)
	/usr/lib/go-1.11/src/io/pipe.go:50 +0xea
io.(*PipeReader).Read(0xc00000e178, 0xc000606000, 0x8000, 0x8000, 0x0, 0xf27d80, 0xc0003175e0)
	/usr/lib/go-1.11/src/io/pipe.go:127 +0x4c
main.(*webRTCConn).Read(0xc0001ad2f0, 0xc000606000, 0x8000, 0x8000, 0xf27d80, 0xc0003175e0, 0x12c0400)
	/tmp/snowflake/proxy-go/snowflake.go:77 +0x4d
main.timeoutConn.Read(0xf2b6e0, 0xc0001ad2f0, 0xdf8475800, 0xc000606000, 0x8000, 0x8000, 0xe78f60, 0x1, 0xc000606000)
	/tmp/snowflake/proxy-go/snowflake.go:198 +0x99
io.copyBuffer(0x7f65e1a4a518, 0xc0002c46e0, 0x7f65e1a4a538, 0xc0002c4700, 0xc000606000, 0x8000, 0x8000, 0xeb7080, 0x0, 0x7f65e1a4a538)
	/usr/lib/go-1.11/src/io/io.go:402 +0x125
io.Copy(0x7f65e1a4a518, 0xc0002c46e0, 0x7f65e1a4a538, 0xc0002c4700, 0xc0002c4700, 0x0, 0x0)
	/usr/lib/go-1.11/src/io/io.go:364 +0x5a
main.CopyLoopTimeout.func1(0xf2a660, 0xc0002c46e0, 0xf2a660, 0xc0002c4700)
	/tmp/snowflake/proxy-go/snowflake.go:216 +0xd2
created by main.CopyLoopTimeout
	/tmp/snowflake/proxy-go/snowflake.go:222 +0x245

goroutine 100 [chan receive]:
main.makePeerConnectionFromOffer.func3(0xc00040e210)
	/tmp/snowflake/proxy-go/snowflake.go:338 +0x4b
created by main.makePeerConnectionFromOffer
	/tmp/snowflake/proxy-go/snowflake.go:337 +0x35d

goroutine 104 [IO wait]:
internal/poll.runtime_pollWait(0x7f65e1a49d60, 0x72, 0xc00054b8d0)
	/usr/lib/go-1.11/src/runtime/netpoll.go:173 +0x66
internal/poll.(*pollDesc).wait(0xc000020498, 0x72, 0xffffffffffffff00, 0xf28a00, 0x12940d0)
	/usr/lib/go-1.11/src/internal/poll/fd_poll_runtime.go:85 +0x9a
internal/poll.(*pollDesc).waitRead(0xc000020498, 0xc0002e6000, 0x800, 0x800)
	/usr/lib/go-1.11/src/internal/poll/fd_poll_runtime.go:90 +0x3d
internal/poll.(*FD).Read(0xc000020480, 0xc0002e6000, 0x800, 0x800, 0x0, 0x0, 0x0)
	/usr/lib/go-1.11/src/internal/poll/fd_unix.go:169 +0x179
net.(*netFD).Read(0xc000020480, 0xc0002e6000, 0x800, 0x800, 0x421cdb, 0x1290d00, 0xe943e0)
	/usr/lib/go-1.11/src/net/fd_unix.go:202 +0x4f
net.(*conn).Read(0xc0001dc048, 0xc0002e6000, 0x800, 0x800, 0x0, 0x0, 0x0)
	/usr/lib/go-1.11/src/net/net.go:177 +0x68
crypto/tls.(*block).readFromUntil(0xc0000995f0, 0xf27f00, 0xc0001dc048, 0x5, 0xc0001dc048, 0x424d4f)
	/usr/lib/go-1.11/src/crypto/tls/conn.go:492 +0x89
crypto/tls.(*Conn).readRecord(0xc0001eb880, 0xef3617, 0xc0001eb9a0, 0x40)
	/usr/lib/go-1.11/src/crypto/tls/conn.go:593 +0xdd
crypto/tls.(*Conn).Read(0xc0001eb880, 0xc0004cc000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
	/usr/lib/go-1.11/src/crypto/tls/conn.go:1145 +0xf1
bufio.(*Reader).fill(0xc0001b4540)
	/usr/lib/go-1.11/src/bufio/bufio.go:100 +0x10f
bufio.(*Reader).ReadByte(0xc0001b4540, 0xc00053a0f0, 0x49c332, 0xc000020480)
	/usr/lib/go-1.11/src/bufio/bufio.go:242 +0x39
golang.org/x/net/websocket.hybiFrameReaderFactory.NewFrameReader(0xc0001b4540, 0x0, 0x0, 0x8001, 0x0)
	/home/irl/go/src/golang.org/x/net/websocket/hybi.go:123 +0x60
golang.org/x/net/websocket.(*Conn).Read(0xc000174120, 0xc000232000, 0x8000, 0x8000, 0x0, 0xf27d80, 0xc000010050)
	/home/irl/go/src/golang.org/x/net/websocket/websocket.go:197 +0x1b1
main.timeoutConn.Read(0xf2b680, 0xc000174120, 0xdf8475800, 0xc000232000, 0x8000, 0x8000, 0x21f, 0x0, 0x0)
	/tmp/snowflake/proxy-go/snowflake.go:198 +0x99
io.copyBuffer(0x7f65e1a4a518, 0xc0002d2020, 0x7f65e1a4a538, 0xc0002d2040, 0xc000232000, 0x8000, 0x8000, 0xeb7080, 0x0, 0x7f65e1a4a538)
	/usr/lib/go-1.11/src/io/io.go:402 +0x125
io.Copy(0x7f65e1a4a518, 0xc0002d2020, 0x7f65e1a4a538, 0xc0002d2040, 0xc0002d2040, 0xc0002ec190, 0x5348fe)
	/usr/lib/go-1.11/src/io/io.go:364 +0x5a
main.CopyLoopTimeout.func1(0xf2a660, 0xc0002d2020, 0xf2a660, 0xc0002d2040)
	/tmp/snowflake/proxy-go/snowflake.go:216 +0xd2
created by main.CopyLoopTimeout
	/tmp/snowflake/proxy-go/snowflake.go:221 +0x16d

goroutine 49 [chan receive]:
main.makePeerConnectionFromOffer.func3(0xc00040e000)
	/tmp/snowflake/proxy-go/snowflake.go:338 +0x4b
created by main.makePeerConnectionFromOffer
	/tmp/snowflake/proxy-go/snowflake.go:337 +0x35d

goroutine 118 [IO wait]:
internal/poll.runtime_pollWait(0x7f65e1a49c90, 0x72, 0xc00022a8d0)
	/usr/lib/go-1.11/src/runtime/netpoll.go:173 +0x66
internal/poll.(*pollDesc).wait(0xc000197498, 0x72, 0xffffffffffffff00, 0xf28a00, 0x12940d0)
	/usr/lib/go-1.11/src/internal/poll/fd_poll_runtime.go:85 +0x9a
internal/poll.(*pollDesc).waitRead(0xc000197498, 0xc0001d3800, 0x400, 0x400)
	/usr/lib/go-1.11/src/internal/poll/fd_poll_runtime.go:90 +0x3d
internal/poll.(*FD).Read(0xc000197480, 0xc0001d3800, 0x400, 0x400, 0x0, 0x0, 0x0)
	/usr/lib/go-1.11/src/internal/poll/fd_unix.go:169 +0x179
net.(*netFD).Read(0xc000197480, 0xc0001d3800, 0x400, 0x400, 0x421cdb, 0x1290d00, 0xe943e0)
	/usr/lib/go-1.11/src/net/fd_unix.go:202 +0x4f
net.(*conn).Read(0xc0001bc120, 0xc0001d3800, 0x400, 0x400, 0x0, 0x0, 0x0)
	/usr/lib/go-1.11/src/net/net.go:177 +0x68
crypto/tls.(*block).readFromUntil(0xc0003ffa40, 0xf27f00, 0xc0001bc120, 0x5, 0xc0001bc120, 0xc0001db301)
	/usr/lib/go-1.11/src/crypto/tls/conn.go:492 +0x89
crypto/tls.(*Conn).readRecord(0xc0004c6a80, 0xef3617, 0xc0004c6ba0, 0x40)
	/usr/lib/go-1.11/src/crypto/tls/conn.go:593 +0xdd
crypto/tls.(*Conn).Read(0xc0004c6a80, 0xc00061e000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
	/usr/lib/go-1.11/src/crypto/tls/conn.go:1145 +0xf1
bufio.(*Reader).fill(0xc0001e6cc0)
	/usr/lib/go-1.11/src/bufio/bufio.go:100 +0x10f
bufio.(*Reader).ReadByte(0xc0001e6cc0, 0xc0001dbe00, 0x49c332, 0xc000197480)
	/usr/lib/go-1.11/src/bufio/bufio.go:242 +0x39
golang.org/x/net/websocket.hybiFrameReaderFactory.NewFrameReader(0xc0001e6cc0, 0xef3600, 0xc0002a8658, 0xbf25b0e6dd49b702, 0x1980d4cc08)
	/home/irl/go/src/golang.org/x/net/websocket/hybi.go:123 +0x60
golang.org/x/net/websocket.(*Conn).Read(0xc0002a8630, 0xc000628000, 0x8000, 0x8000, 0x0, 0x0, 0x0)
	/home/irl/go/src/golang.org/x/net/websocket/websocket.go:197 +0x1b1
main.timeoutConn.Read(0xf2b680, 0xc0002a8630, 0xdf8475800, 0xc000628000, 0x8000, 0x8000, 0xe78f60, 0x1, 0xc000628000)
	/tmp/snowflake/proxy-go/snowflake.go:198 +0x99
io.copyBuffer(0x7f65e1a4a518, 0xc0002d3dc0, 0x7f65e1a4a538, 0xc0002d3de0, 0xc000628000, 0x8000, 0x8000, 0xeb7080, 0x0, 0x7f65e1a4a538)
	/usr/lib/go-1.11/src/io/io.go:402 +0x125
io.Copy(0x7f65e1a4a518, 0xc0002d3dc0, 0x7f65e1a4a538, 0xc0002d3de0, 0xc0002d3de0, 0x0, 0x0)
	/usr/lib/go-1.11/src/io/io.go:364 +0x5a
main.CopyLoopTimeout.func1(0xf2a660, 0xc0002d3dc0, 0xf2a660, 0xc0002d3de0)
	/tmp/snowflake/proxy-go/snowflake.go:216 +0xd2
created by main.CopyLoopTimeout
	/tmp/snowflake/proxy-go/snowflake.go:221 +0x16d

goroutine 119 [select]:
io.(*pipe).Read(0xc0001db450, 0xc000620000, 0x8000, 0x8000, 0x1b, 0x1b, 0xc000312600)
	/usr/lib/go-1.11/src/io/pipe.go:50 +0xea
io.(*PipeReader).Read(0xc0001bc110, 0xc000620000, 0x8000, 0x8000, 0x0, 0xf27d80, 0xc0002b6390)
	/usr/lib/go-1.11/src/io/pipe.go:127 +0x4c
main.(*webRTCConn).Read(0xc0003ff8f0, 0xc000620000, 0x8000, 0x8000, 0xf27d80, 0xc0002b6390, 0x12c0400)
	/tmp/snowflake/proxy-go/snowflake.go:77 +0x4d
main.timeoutConn.Read(0xf2b6e0, 0xc0003ff8f0, 0xdf8475800, 0xc000620000, 0x8000, 0x8000, 0xe78f60, 0x1, 0xc000620000)
	/tmp/snowflake/proxy-go/snowflake.go:198 +0x99
io.copyBuffer(0x7f65e1a4a518, 0xc0002d3e00, 0x7f65e1a4a538, 0xc0002d3e20, 0xc000620000, 0x8000, 0x8000, 0xeb7080, 0xc0000d4e00, 0x7f65e1a4a538)
	/usr/lib/go-1.11/src/io/io.go:402 +0x125
io.Copy(0x7f65e1a4a518, 0xc0002d3e00, 0x7f65e1a4a538, 0xc0002d3e20, 0xc0002d3e20, 0x3, 0x1)
	/usr/lib/go-1.11/src/io/io.go:364 +0x5a
main.CopyLoopTimeout.func1(0xf2a660, 0xc0002d3e00, 0xf2a660, 0xc0002d3e20)
	/tmp/snowflake/proxy-go/snowflake.go:216 +0xd2
created by main.CopyLoopTimeout
	/tmp/snowflake/proxy-go/snowflake.go:222 +0x245

goroutine 30 [semacquire]:
sync.runtime_Semacquire(0xc00026f108)
	/usr/lib/go-1.11/src/runtime/sema.go:56 +0x39
sync.(*WaitGroup).Wait(0xc00026f100)
	/usr/lib/go-1.11/src/sync/waitgroup.go:130 +0x64
main.CopyLoopTimeout(0xf2b6e0, 0xc0001ac000, 0xf2b680, 0xc000174120, 0xdf8475800)
	/tmp/snowflake/proxy-go/snowflake.go:223 +0x253
main.datachannelHandler(0xc0001ac000, 0xf29660, 0xc0001ac0c0)
	/tmp/snowflake/proxy-go/snowflake.go:258 +0x383
created by main.makePeerConnectionFromOffer.func2
	/tmp/snowflake/proxy-go/snowflake.go:303 +0x2ac

The second time I've run it it seems to be doing lots of WebRTC onmessage and write, which is guess is the correct operation.

Child Tickets

Change History (13)

comment:1 Changed 4 months ago by cohosh

This has been occurring as a result of the proxy-go deadlock patch from #25688.

The problem part of the code is here:

        // Set a timeout on peerconnection. If the connection state has not
        // advanced to PeerConnectionStateConnected in this time,
        // destroy the peer connection and return the token.
        go func() {
                <-time.After(dataChannelTimeout)
                if pc.ConnectionState() != webrtc.PeerConnectionStateConnected {

where pc (or some members of it) are nil and cause an invalid memory access

comment:2 Changed 4 months ago by cohosh

Owner: set to cohosh
Status: newaccepted

comment:3 Changed 4 months ago by cohosh

Status: acceptedneeds_revision

Here's a fix: https://github.com/cohosh/snowflake/compare/ticket30206

The proxy-go instances were seg faulting occasionally in cases where the client successfully made a data channel connection but the data channel was closed before the timeout occurred.

I added a second channel that will trigger when the data channel has been successfully opened (and therefore pc.Destroy() is handled by dataChannelHandler), and only destroy the connection if this channel has not been closed before the Timeout (which I've shortened to a more realistic time).

I'm going to patch our deployed proxy-go instances immediately, but wait to merge until this has been reviewed.

comment:4 Changed 4 months ago by irl

Status: needs_revisionneeds_review

I think you meant this.

comment:5 Changed 4 months ago by dcf

Status: needs_reviewneeds_information

I agree with your diagnosis. I can make the segfault happen by applying this change, closing the datachannel immediately after it is opened:

  • proxy-go/snowflake.go

    a b func makePeerConnectionFromOffer(sdp *webrtc.SessionDescription, config *webrtc. 
    280280
    281281               dc.OnOpen = func() {
    282282                       log.Println("OnOpen channel")
     283                       dc.Close()
    283284               }
    284285               dc.OnClose = func() {
    285286                       conn.lock.Lock()

I think the chain of events is as follows:

  • dc.OnClose calls pw.Close, where pw feeds into the read part of a webRTCConn.
  • Closing pw causes CopyLoopTimeout to exit, which causes datachannelHandler to exit, which makes a deferred call to webRTCConn.Close.
  • webRTCConn.Close calls pc.Destroy.
  • pc.Destroy calls CGO_DestroyPeer.
  • CGO_DestroyPeer removes the peer from localPeers, which drops the peer's reference count to 0, which sets pc_ = nullptr.
  • Later, when the dataChannelTimeout expires, it calls pc.ConnectionState, where pc is a stale object reference that has already had its destructor called. In particular, its pc_ member is null. CGO_IceConnectionState deferences the null pointer.

The fix looks okay to me. I presume there haven't been any more problems since you deployed it?

Was this change only to assist finding the bug, or is there another reason for it?

-const dataChannelTimeout = time.Minute
+const dataChannelTimeout = 20 * time.Second

comment:6 in reply to:  5 Changed 4 months ago by cohosh

Replying to dcf:
Thanks for taking a look at this!

I think the chain of events is as follows:

  • dc.OnClose calls pw.Close, where pw feeds into the read part of a webRTCConn.
  • Closing pw causes CopyLoopTimeout to exit, which causes datachannelHandler to exit, which makes a deferred call to webRTCConn.Close.
  • webRTCConn.Close calls pc.Destroy.
  • pc.Destroy calls CGO_DestroyPeer.
  • CGO_DestroyPeer removes the peer from localPeers, which drops the peer's reference count to 0, which sets pc_ = nullptr.
  • Later, when the dataChannelTimeout expires, it calls pc.ConnectionState, where pc is a stale object reference that has already had its destructor called. In particular, its pc_ member is null. CGO_IceConnectionState deferences the null pointer.

That checks out with my understanding of how this works.


The fix looks okay to me. I presume there haven't been any more problems since you deployed it?

Yup, no seg faults since I deployed the fix.

Was this change only to assist finding the bug, or is there another reason for it?

-const dataChannelTimeout = time.Minute
+const dataChannelTimeout = 20 * time.Second

There were two reasons for this:

  1. An entire minute is a long time to wait in the event that there was an ICE error and the client needs to find a new proxy.
  2. The current proxy timeout is 30 seconds, which means that the earliest a client will attempt to close a data channel they believe is open is 30 seconds later. So even without the seg fault fix, this would prevent a lot of failures. Obviously we don't need it with the fix, but it seems like a good idea to take into account our existing timeouts when creating this one.

comment:7 Changed 4 months ago by cohosh

Ah, also there's a typo here which I will fix

comment:8 Changed 4 months ago by dcf

Status: needs_informationmerge_ready

Okay.

comment:9 Changed 4 months ago by cohosh

Resolution: fixed
Status: merge_readyclosed

Merged to master

comment:10 Changed 3 months ago by arlolra

If sendAnswer() returns an error, pc.Destroy() is called and the token is returned,
https://github.com/keroserene/snowflake/blob/master/proxy-go/snowflake.go#L370

However, makePeerConnectionFromOffer() will have now set a timeout that will also call pc.Destroy(),
https://github.com/keroserene/snowflake/blob/master/proxy-go/snowflake.go#L345

This patch moves the timeout to after sendAnswer returns,
https://github.com/keroserene/snowflake/commit/2e4383434f33a4f8e801974bbe70d8a4568b3d93

comment:11 Changed 3 months ago by cohosh

Good catch! Thanks for that.

This patch looks good to me. I'm fine if you want to go ahead and merge it.

comment:12 in reply to:  11 ; Changed 3 months ago by arlolra

Replying to cohosh:

This patch looks good to me. I'm fine if you want to go ahead and merge it.

Merged as https://gitweb.torproject.org/pluggable-transports/snowflake.git/commit/?id=2e4383434f33a4f8e801974bbe70d8a4568b3d93

One thing of note is that the goroutine was removed, which blocks runSession() from returning. There's a similar question here as in ticket:30511#comment:4 on whether that deserves to called asynchronously.

comment:13 in reply to:  12 Changed 3 months ago by cohosh

Replying to arlolra:

One thing of note is that the goroutine was removed, which blocks runSession() from returning. There's a similar question here as in ticket:30511#comment:4 on whether that deserves to called asynchronously.

Yeah, we might want to add a timeout. I replied there: https://trac.torproject.org/projects/tor/ticket/30511#comment:5

Note: See TracTickets for help on using tickets.