环境:
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