Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

mqtt工具连接，mqtt服务挂掉问题 #16

Closed
jatywm opened this issue Dec 30, 2015 · 1 comment · Fixed by #17
Closed

mqtt工具连接，mqtt服务挂掉问题 #16

jatywm opened this issue Dec 30, 2015 · 1 comment · Fixed by #17
Assignees
@ruizeng
Labels
bug
Milestone
Release-0.10.0

Comments

@jatywm
Copy link

jatywm commented Dec 30, 2015

环境：
mqtt tls 关闭
mqtt工具连接

错误症状：
连接成功后，15-60秒mqtt服务出错挂掉！

详细日志：
{"ip":"10.170.113.18","level":"info","msg":"accepting new connection 116.30.211.113:53088","service":"mqttaccess","time":"2015-12-30T14:55:37+08:00"}
{"ip":"10.170.113.18","level":"info","msg":"recieve new connection from 116.30.211.113:53088","service":"mqttaccess","time":"2015-12-30T14:55:37+08:00"}
{"ip":"10.170.113.18","level":"info","msg":"116.30.211.113:53088, come msg===\n\u0026{{false 0 false} MQTT 4 false false true 0 60 8 true true 8 f336884f1fabc2c724724c50b34dfd66}\n=====","service":"mqttaccess","time":"2015-12-30T14:55:37+08:00"}
{"ip":"10.170.113.18","level":"info","msg":"accepting new connection 127.0.0.1:47314","service":"devicemanager","time":"2015-12-30T14:55:37+08:00"}
{"ip":"10.170.113.18","level":"info","msg":"116.30.211.113:53088, connected to server now","service":"mqttaccess","time":"2015-12-30T14:55:37+08:00"}
{"ip":"10.170.113.18","level":"debug","msg":"send msg to 116.30.211.113:53088=======\n\u0026{{false 0 false} 0}\n=========","service":"mqttaccess","time":"2015-12-30T14:55:37+08:00"}
{"ip":"10.170.113.18","level":"info","msg":"RegisterServer is done. Metadata is \u0026{"set" "{Key: /pando/servers/httpaccess/httphost/120.25.69.164:443, CreatedIndex: 4069, ModifiedIndex: 4069, TTL: 180}" "{Key: /pando/servers/httpaccess/httphost/120.25.69.164:443, CreatedIndex: 4062, ModifiedIndex: 4062, TTL: 120}" '\u0fe5'}\n","service":"httpaccess","time":"2015-12-30T14:56:16+08:00"}
{"ip":"10.170.113.18","level":"info","msg":"RegisterServer Success","service":"httpaccess","time":"2015-12-30T14:56:16+08:00"}
{"ip":"10.170.113.18","level":"info","msg":"UpdateServerHosts is done: map[httpaccess:map[httphost:[120.25.69.164:443]] mqttaccess:map[rpchost:[localhost:20030] tcphost:[120.25.69.164:1883]] registry:map[rpchost:[localhost:20034]] apiprovidor:map[httphost:[120.25.69.164:8443]] controller:map[rpchost:[localhost:20032]] devicemanager:map[rpchost:[localhost:20033]]]","service":"httpaccess","time":"2015-12-30T14:56:16+08:00"}
{"ip":"10.170.113.18","level":"info","msg":"UpdateServerHosts Success","service":"httpaccess","time":"2015-12-30T14:56:16+08:00"}
{"ip":"10.170.113.18","level":"info","msg":"RegisterServer is done. Metadata is \u0026{"set" "{Key: /pando/servers/apiprovidor/httphost/120.25.69.164:8443, CreatedIndex: 4070, ModifiedIndex: 4070, TTL: 180}" "{Key: /pando/servers/apiprovidor/httphost/120.25.69.164:8443, CreatedIndex: 4063, ModifiedIndex: 4063, TTL: 120}" '\u0fe6'}\n","service":"apiprovidor","time":"2015-12-30T14:56:16+08:00"}
{"ip":"10.170.113.18","level":"info","msg":"RegisterServer Success","service":"apiprovidor","time":"2015-12-30T14:56:16+08:00"}
{"ip":"10.170.113.18","level":"info","msg":"UpdateServerHosts is done: map[registry:map[rpchost:[localhost:20034]] apiprovidor:map[httphost:[120.25.69.164:8443]] controller:map[rpchost:[localhost:20032]] devicemanager:map[rpchost:[localhost:20033]] httpaccess:map[httphost:[120.25.69.164:443]] mqttaccess:map[rpchost:[localhost:20030] tcphost:[120.25.69.164:1883]]]","service":"apiprovidor","time":"2015-12-30T14:56:16+08:00"}
{"ip":"10.170.113.18","level":"info","msg":"UpdateServerHosts Success","service":"apiprovidor","time":"2015-12-30T14:56:16+08:00"}
{"ip":"10.170.113.18","level":"info","msg":"RegisterServer is done. Metadata is \u0026{"set" "{Key: /pando/servers/devicemanager/rpchost/localhost:20033, CreatedIndex: 4071, ModifiedIndex: 4071, TTL: 180}" "{Key: /pando/servers/devicemanager/rpchost/localhost:20033, CreatedIndex: 4064, ModifiedIndex: 4064, TTL: 120}" '\u0fe7'}\n","service":"devicemanager","time":"2015-12-30T14:56:16+08:00"}
{"ip":"10.170.113.18","level":"info","msg":"RegisterServer Success","service":"devicemanager","time":"2015-12-30T14:56:16+08:00"}
{"ip":"10.170.113.18","level":"info","msg":"UpdateServerHosts is done: map[apiprovidor:map[httphost:[120.25.69.164:8443]] controller:map[rpchost:[localhost:20032]] devicemanager:map[rpchost:[localhost:20033]] httpaccess:map[httphost:[120.25.69.164:443]] mqttaccess:map[rpchost:[localhost:20030] tcphost:[120.25.69.164:1883]] registry:map[rpchost:[localhost:20034]]]","service":"devicemanager","time":"2015-12-30T14:56:16+08:00"}
{"ip":"10.170.113.18","level":"info","msg":"UpdateServerHosts Success","service":"devicemanager","time":"2015-12-30T14:56:16+08:00"}
{"ip":"10.170.113.18","level":"info","msg":"RegisterServer is done. Metadata is \u0026{"set" "{Key: /pando/servers/registry/rpchost/localhost:20034, CreatedIndex: 4072, ModifiedIndex: 4072, TTL: 180}" "{Key: /pando/servers/registry/rpchost/localhost:20034, CreatedIndex: 4065, ModifiedIndex: 4065, TTL: 120}" '\u0fe8'}\n","service":"registry","time":"2015-12-30T14:56:16+08:00"}
{"ip":"10.170.113.18","level":"info","msg":"RegisterServer Success","service":"registry","time":"2015-12-30T14:56:16+08:00"}
{"ip":"10.170.113.18","level":"info","msg":"UpdateServerHosts is done: map[registry:map[rpchost:[localhost:20034]] apiprovidor:map[httphost:[120.25.69.164:8443]] controller:map[rpchost:[localhost:20032]] devicemanager:map[rpchost:[localhost:20033]] httpaccess:map[httphost:[120.25.69.164:443]] mqttaccess:map[rpchost:[localhost:20030] tcphost:[120.25.69.164:1883]]]","service":"registry","time":"2015-12-30T14:56:16+08:00"}
{"ip":"10.170.113.18","level":"info","msg":"UpdateServerHosts Success","service":"registry","time":"2015-12-30T14:56:16+08:00"}
{"ip":"10.170.113.18","level":"info","msg":"RegisterServer is done. Metadata is \u0026{"set" "{Key: /pando/servers/controller/rpchost/localhost:20032, CreatedIndex: 4073, ModifiedIndex: 4073, TTL: 180}" "{Key: /pando/servers/controller/rpchost/localhost:20032, CreatedIndex: 4066, ModifiedIndex: 4066, TTL: 120}" '\u0fe9'}\n","service":"controller","time":"2015-12-30T14:56:16+08:00"}
{"ip":"10.170.113.18","level":"info","msg":"RegisterServer Success","service":"controller","time":"2015-12-30T14:56:16+08:00"}
{"ip":"10.170.113.18","level":"info","msg":"UpdateServerHosts is done: map[apiprovidor:map[httphost:[120.25.69.164:8443]] controller:map[rpchost:[localhost:20032]] devicemanager:map[rpchost:[localhost:20033]] httpaccess:map[httphost:[120.25.69.164:443]] mqttaccess:map[rpchost:[localhost:20030] tcphost:[120.25.69.164:1883]] registry:map[rpchost:[localhost:20034]]]","service":"controller","time":"2015-12-30T14:56:16+08:00"}
{"ip":"10.170.113.18","level":"info","msg":"UpdateServerHosts Success","service":"controller","time":"2015-12-30T14:56:16+08:00"}
{"ip":"10.170.113.18","level":"error","msg":"116.30.211.113:53088 is end now","service":"mqttaccess","time":"2015-12-30T14:56:29+08:00"}
{"ip":"10.170.113.18","level":"debug","msg":"use of closed network connection","service":"mqttaccess","time":"2015-12-30T14:56:29+08:00"}
panic: close of closed channel

goroutine 23 [running]:
github.com/PandoCloud/pando-cloud/pkg/mqtt.(_Connection).Close(0xc820112360)
/root/golang/src/github.com/PandoCloud/pando-cloud/pkg/mqtt/connection.go:119 +0x79
github.com/PandoCloud/pando-cloud/pkg/mqtt.(_Connection).RcvMsgFromClient(0xc820112360)
/root/golang/src/github.com/PandoCloud/pando-cloud/pkg/mqtt/connection.go:139 +0x551
created by github.com/PandoCloud/pando-cloud/pkg/mqtt.NewConnection
/root/golang/src/github.com/PandoCloud/pando-cloud/pkg/mqtt/connection.go:48 +0x157

goroutine 1 [sleep]:
time.Sleep(0xdf8475800)
/usr/local/go/src/runtime/time.go:59 +0xf9
github.com/PandoCloud/pando-cloud/pkg/server.Run(0x0, 0x0)
/root/golang/src/github.com/PandoCloud/pando-cloud/pkg/server/server.go:253 +0x880
main.main()
/root/golang/src/github.com/PandoCloud/pando-cloud/services/mqttaccess/main.go:36 +0x456

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

goroutine 6 [sleep]:
time.Sleep(0xdf8475800)
/usr/local/go/src/runtime/time.go:59 +0xf9
github.com/PandoCloud/pando-cloud/pkg/mqtt.(*Manager).CleanWorker(0xc8200dc660)
/root/golang/src/github.com/PandoCloud/pando-cloud/pkg/mqtt/manager.go:96 +0xe2
created by github.com/PandoCloud/pando-cloud/pkg/mqtt.NewManager
/root/golang/src/github.com/PandoCloud/pando-cloud/pkg/mqtt/manager.go:21 +0xd2

goroutine 7 [IO wait]:
net.runtime_pollWait(0x7f4733a57bd0, 0x72, 0xc820010180)
/usr/local/go/src/runtime/netpoll.go:157 +0x60
net.(_pollDesc).Wait(0xc82004e5a0, 0x72, 0x0, 0x0)
/usr/local/go/src/net/fd_poll_runtime.go:73 +0x3a
net.(_pollDesc).WaitRead(0xc82004e5a0, 0x0, 0x0)
/usr/local/go/src/net/fd_poll_runtime.go:78 +0x36
net.(_netFD).accept(0xc82004e540, 0x0, 0x7f4733a57d30, 0xc820114040)
/usr/local/go/src/net/fd_unix.go:408 +0x27c
net.(_TCPListener).AcceptTCP(0xc82002a110, 0xc82003bed8, 0x0, 0x0)
/usr/local/go/src/net/tcpsock_posix.go:254 +0x4d
net.(_TCPListener).Accept(0xc82002a110, 0x0, 0x0, 0x0, 0x0)
/usr/local/go/src/net/tcpsock_posix.go:264 +0x3d
github.com/PandoCloud/pando-cloud/pkg/server.(_TCPServer).Start.func1(0x7f4733a56c28, 0xc82002a110, 0xc8200dc6f0)
/root/golang/src/github.com/PandoCloud/pando-cloud/pkg/server/tcp_server.go:66 +0x45
created by github.com/PandoCloud/pando-cloud/pkg/server.(*TCPServer).Start
/root/golang/src/github.com/PandoCloud/pando-cloud/pkg/server/tcp_server.go:74 +0x9e4

goroutine 8 [IO wait]:
net.runtime_pollWait(0x7f4733a57b10, 0x72, 0xc820010180)
/usr/local/go/src/runtime/netpoll.go:157 +0x60
net.(_pollDesc).Wait(0xc82004e840, 0x72, 0x0, 0x0)
/usr/local/go/src/net/fd_poll_runtime.go:73 +0x3a
net.(_pollDesc).WaitRead(0xc82004e840, 0x0, 0x0)
/usr/local/go/src/net/fd_poll_runtime.go:78 +0x36
net.(_netFD).accept(0xc82004e7e0, 0x0, 0x7f4733a57d30, 0xc8200fa180)
/usr/local/go/src/net/fd_unix.go:408 +0x27c
net.(_TCPListener).AcceptTCP(0xc82002a1a0, 0x0, 0x0, 0x0)
/usr/local/go/src/net/tcpsock_posix.go:254 +0x4d
net.(_TCPListener).Accept(0xc82002a1a0, 0x0, 0x0, 0x0, 0x0)
/usr/local/go/src/net/tcpsock_posix.go:264 +0x3d
github.com/PandoCloud/pando-cloud/pkg/server.(_TCPServer).Start.func1(0x7f4733a56c28, 0xc82002a1a0, 0xc8200dc6c0)
/root/golang/src/github.com/PandoCloud/pando-cloud/pkg/server/tcp_server.go:66 +0x45
created by github.com/PandoCloud/pando-cloud/pkg/server.(*TCPServer).Start
/root/golang/src/github.com/PandoCloud/pando-cloud/pkg/server/tcp_server.go:74 +0x9e4

goroutine 24 [IO wait]:
net.runtime_pollWait(0x7f4733a578d0, 0x72, 0xc820010180)
/usr/local/go/src/runtime/netpoll.go:157 +0x60
net.(_pollDesc).Wait(0xc82004fb10, 0x72, 0x0, 0x0)
/usr/local/go/src/net/fd_poll_runtime.go:73 +0x3a
net.(_pollDesc).WaitRead(0xc82004fb10, 0x0, 0x0)
/usr/local/go/src/net/fd_poll_runtime.go:78 +0x36
net.(_netFD).Read(0xc82004fab0, 0xc820119000, 0x1000, 0x1000, 0x0, 0x7f4733a52050, 0xc820010180)
/usr/local/go/src/net/fd_unix.go:232 +0x23a
net.(_conn).Read(0xc82002a450, 0xc820119000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
/usr/local/go/src/net/net.go:172 +0xe4
bufio.(_Reader).fill(0xc8201124e0)
/usr/local/go/src/bufio/bufio.go:97 +0x1e9
bufio.(_Reader).Read(0xc8201124e0, 0xc8201160f0, 0x1, 0x9, 0x0, 0x0, 0x0)
/usr/local/go/src/bufio/bufio.go:207 +0x260
io.ReadAtLeast(0x7f4733a582d0, 0xc8201124e0, 0xc8201160f0, 0x1, 0x9, 0x1, 0x0, 0x0, 0x0)
/usr/local/go/src/io/io.go:298 +0xe6
io.ReadFull(0x7f4733a582d0, 0xc8201124e0, 0xc8201160f0, 0x1, 0x9, 0xc820079af0, 0x0, 0x0)
/usr/local/go/src/io/io.go:316 +0x62
encoding/gob.decodeUintReader(0x7f4733a582d0, 0xc8201124e0, 0xc8201160f0, 0x9, 0x9, 0x0, 0x1, 0x0, 0x0)
/usr/local/go/src/encoding/gob/decode.go:121 +0x92
encoding/gob.(_Decoder).recvMessage(0xc820079a80, 0xc820123bc0)
/usr/local/go/src/encoding/gob/decoder.go:76 +0x5e
encoding/gob.(_Decoder).decodeTypeSequence(0xc820079a80, 0xc5f100, 0xc820079a80)
/usr/local/go/src/encoding/gob/decoder.go:140 +0x47
encoding/gob.(_Decoder).DecodeValue(0xc820079a80, 0x8d0140, 0xc82011a390, 0x16, 0x0, 0x0)
/usr/local/go/src/encoding/gob/decoder.go:208 +0x15d
encoding/gob.(_Decoder).Decode(0xc820079a80, 0x8d0140, 0xc82011a390, 0x0, 0x0)
/usr/local/go/src/encoding/gob/decoder.go:185 +0x289
net/rpc.(_gobClientCodec).ReadResponseHeader(0xc8200ddfb0, 0xc82011a390, 0x0, 0x0)
/usr/local/go/src/net/rpc/client.go:223 +0x51
net/rpc.(_Client).input(0xc8201125a0)
/usr/local/go/src/net/rpc/client.go:109 +0xbf
created by net/rpc.NewClientWithCodec
/usr/local/go/src/net/rpc/client.go:201 +0xd2

goroutine 13 [IO wait]:
net.runtime_pollWait(0x7f4733a57a50, 0x72, 0xc820010180)
/usr/local/go/src/runtime/netpoll.go:157 +0x60
net.(_pollDesc).Wait(0xc82004ed10, 0x72, 0x0, 0x0)
/usr/local/go/src/net/fd_poll_runtime.go:73 +0x3a
net.(_pollDesc).WaitRead(0xc82004ed10, 0x0, 0x0)
/usr/local/go/src/net/fd_poll_runtime.go:78 +0x36
net.(_netFD).Read(0xc82004ecb0, 0xc8200f3000, 0x1000, 0x1000, 0x0, 0x7f4733a52050, 0xc820010180)
/usr/local/go/src/net/fd_unix.go:232 +0x23a
net.(_conn).Read(0xc82002a258, 0xc8200f3000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
/usr/local/go/src/net/net.go:172 +0xe4
net/http.noteEOFReader.Read(0x7f4733a58090, 0xc82002a258, 0xc8200ee478, 0xc8200f3000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
/usr/local/go/src/net/http/transport.go:1370 +0x67
net/http.(_noteEOFReader).Read(0xc8200fa200, 0xc8200f3000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
:126 +0xd0
bufio.(_Reader).fill(0xc82001cba0)
/usr/local/go/src/bufio/bufio.go:97 +0x1e9
bufio.(_Reader).Peek(0xc82001cba0, 0x1, 0x0, 0x0, 0x0, 0x0, 0x0)
/usr/local/go/src/bufio/bufio.go:132 +0xcc
net/http.(_persistConn).readLoop(0xc8200ee420)
/usr/local/go/src/net/http/transport.go:876 +0xf7
created by net/http.(*Transport).dialConn
/usr/local/go/src/net/http/transport.go:685 +0xc78

goroutine 14 [select]:
net/http.(_persistConn).writeLoop(0xc8200ee420)
/usr/local/go/src/net/http/transport.go:1009 +0x40c
created by net/http.(_Transport).dialConn
/usr/local/go/src/net/http/transport.go:686 +0xc9d
@ruizeng ruizeng added this to the Release-0.10.0 milestone Dec 31, 2015
@ruizeng ruizeng added the bug label Dec 31, 2015
@ruizeng ruizeng self-assigned this Dec 31, 2015
@ruizeng
Copy link
Owner

ruizeng commented Dec 31, 2015

mqtt tls开启的时候这个错误复现不？

ruizeng added a commit that referenced this issue Dec 31, 2015
@ruizeng
fix Issue #16
46e63b2
ruizeng added a commit that referenced this issue Dec 31, 2015
@ruizeng
fix Issue #16
50d1354 
connection cleanning gorotine fix.
@ruizeng ruizeng mentioned this issue Dec 31, 2015
Merged
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@ruizeng ruizeng

Labels
bug
Projects
None yet
Milestone
Release-0.10.0
Development

Successfully merging a pull request may close this issue.

Bug fix mqttaccess notls crash ruizeng/pando-cloud
2 participants
@ruizeng @jatywm