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.

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

the mqtt client has been hanging out,by dead lock #473

Closed
yunfuyiren opened this issue Dec 24, 2020 · 10 comments
Closed

the mqtt client has been hanging out,by dead lock #473

yunfuyiren opened this issue Dec 24, 2020 · 10 comments

Comments

@yunfuyiren
Copy link

yunfuyiren commented Dec 24, 2020

Hi,guys, I use this client sdk by version paho 1.3.0, the broker version is mosquitto 2.0.0.

this is my client code

mosquittoClient := &MosquittoClient{
		client:      nil,
		Topic:       Topic,
		QoS:         0,
	}
	userName, passWord, _ := getMqttUserNameAndPassword()
	opts := mqtt.NewClientOptions().SetClientID(id).AddBroker(PROTOCAL + "://" + MQTTHOST) //.SetTLSConfig(tlsconfig)
	opts.SetKeepAlive(60 * time.Second)
	opts.SetWill(Topic, "the pub device has dropped off "+id, 1, true)
	opts.SetAutoReconnect(true)
	opts.SetCleanSession(true)
	opts.SetOnConnectHandler(func(client mqtt.Client) {
		log.Info("client has been connect success ")
		client.Subscribe(channel, mosquittoClient.QoS, mosquittoClient.handlerFun)
		log.Info("client reconnect  channel: ", channel)	
	})
	opts.SetConnectionLostHandler(func(client mqtt.Client, err error) {
		log.Error("SetConnectionLostHandler has been triggered : ", err.Error())
	})
	opts.SetUsername(userName)
	opts.SetPassword(passWord)
	opts.SetDefaultPublishHandler(func(client mqtt.Client, message mqtt.Message) {
		log.Info("Topic: %s\n", message.Topic())
		log.Info("MSG: %s\n", message.Payload())
	})
	c := mqtt.NewClient(opts)
	mosquittoClient.client = c
	if token := c.Connect(); token.Wait() && token.Error() != nil {
		//tea add alert
		log.Error("mqtt connect failed: ", token.Error().Error())
		go func(client mqtt.Client) {
			for {
				time.Sleep(10 * time.Second)
				if token = client.Connect(); token.Wait() && token.Error() != nil {
					continue
				} else {
					log.Info("Initial Reconnect to MQTT successed ")
					break
				}
			}
		}(c)
	}
	return mosquittoClient

but after a while , the connection of the mqtt is lost, without any logs of function 'SetConnectionLostHandler'. I check the debug logs.
logs are:
2020/12/20 21:08:26 [CRIT] [pinger] pingresp not received, disconnecting
2020/12/20 21:08:26 [DEBUG] [client] internalConnLost called
2020/12/20 21:08:26 [DEBUG] [client] stopCommsWorkers called
2020/12/20 21:08:26 [DEBUG] [client] startCommsWorkers output redirector finnished
2020/12/20 21:08:26 [DEBUG] [net] outgoing waiting for an outbound message
2020/12/20 21:08:26 [DEBUG] [net] outgoing waiting for an outbound message
2020/12/20 21:08:26 [DEBUG] [client] internalConnLost waiting on workers
2020/12/20 21:08:26 [DEBUG] [client] stopCommsWorkers waiting for workers

could any body help me, how the deadlock come out and how to fix it. @MattBrittan , follow your advise in #453 , i raise a new issue and appretiate your help

@MattBrittan
Copy link
Contributor

MattBrittan commented Dec 24, 2020

I assume the code you have published is connecting successfully? If the initial connection fails i believe you may have issues (any atttempt to use the client before the connection is up will cause an error; probably better to use the inbuilt ConnectRetry functionality) other than that I cant see any issue with the code provided.

However I'm guessing you are publishing/subscribing at some point? Please show that code (working code would be ideal) and more of the logs (activity before the "pingresp not received"; that is the problem; the cause is likely to be earlier in the log). This issue is usually due to a handler function that blocks (does not return) within the users code (not saying this is the case here; currently there is insufficient information to allow much analysis).

@bartmeuris
Copy link

Have a similar issue, not really had the time to debug it further but:

I don't seem to receive any data from subscriptions , but I get this debug log from the mqtt client

INFO[0000] [net]      startIncoming Received Message    
INFO[0000] [net]      startIncoming Received Message    
INFO[0000] [net]      startIncomingComms: got msg on ibound 
INFO[0000] [net]      startIncomingComms: received publish, msgId: 0 

Then my message that I publish fails after a while with a publish was broken by timeout error. Also the internal ping fails and hangs from that point on, and the disconnect hangs:

INFO[0050] [pinger]   pingresp not received, disconnecting 
INFO[0050] [client]   internalConnLost called           
INFO[0050] [client]   stopCommsWorkers called           
INFO[0050] [client]   internalConnLost waiting on workers 
INFO[0050] [client]   startCommsWorkers output redirector finnished 
INFO[0050] [net]      outgoing waiting for an outbound message 
INFO[0050] [net]      outgoing waiting for an outbound message 
INFO[0050] [client]   stopCommsWorkers waiting for workers 

Also, disconnecting the MQTT client also hangs. I get the same behavior when I terminate my application with Ctrl-C, where in the signal handler I call a Disconnect():

INFO[0000] Terminating mqtt connection...                timeout=10s
INFO[0000] [client]   disconnecting                     
INFO[0000] [client]   calling WaitTimeout               
INFO[0000] [net]      obound priority msg to write, type *packets.DisconnectPacket 
INFO[0000] [net]      outbound wrote disconnect, closing connection 
INFO[0000] [client]   WaitTimeout done                  
INFO[0000] [client]   stopCommsWorkers called           
INFO[0000] [net]      outgoing waiting for an outbound message 
INFO[0000] [net]      outgoing waiting for an outbound message 
INFO[0000] [net]      outgoing waiting for an outbound message 
INFO[0000] [client]   stopCommsWorkers waiting for workers 
INFO[0000] [client]   startCommsWorkers output redirector finnished 
INFO[0000] [pinger]   keepalive stopped                 

When I switch back to 1.2.0, it all just works again.

@MattBrittan
Copy link
Contributor

MattBrittan commented Dec 25, 2020

@bartmeuris - please raise this as a separate issue (without additional information its not possible to ascertain if these have the same cause so its simpler to assume they differ).

Given that your code was working with 1.2.0 its most likely your issue is due to the change mentioned in the release notes:

Note that this commit changes internal message channels from buffered to unbuffered and may impact users who publish from within a message handler (the documentation has been updated to highlight the issue; running potentially blocking operations within a message handle has always been problematic).

The section of the logs you included (from Ctrl-C press) gives some indications this may be the case (there is no matchAndDispatch exiting). Unfortunately you have not included enough of the log to draw any further conclusions (pingresp not received, disconnecting is a symptom; the cause will most likely be earlier in the logs).

@yunfuyiren
Copy link
Author

yunfuyiren commented Dec 30, 2020

Firstly, I want to say thank you to @bartmeuris @MattBrittan , I've seen your dialogue in #474 ,and learned a lot about the blocking of the client channel. And I think it's also maybe the channel buffering makes my client hang out. here is my code of subscription :

z.MqttClient.SubMsgWithTopicAndQoS(func(client mqtt.Client, message mqtt.Message) {
			go handleFunc(msg)
		}, channel, 1)

this client just a subscriber to sub a topic named by channel. And my handler function is a go routine function.
here is my scenario which is not used in a local area network:
the broker is a server deployed in America, and pub client is at the same city with broker while the sub one is in Africa. And messages
which sent to sub client are just a mass of touch operation orders and can not be out of order. so I have to set the 'SetOrderMatters' to default 'true' to keep messages in order. but i am not sure if it is the long distance and bad internet of the sub client which makes the messages are not reachable and when the client is hanging out, i try to use tcpdump to grab packages to check the heartbeats but they are not sent any more which are like this in a healthy state:
image

I look for reason by review the code of mqtt client and find its been block here :
image
i've added some debug log local and only this "c.workers.Done()" is not run while the other two c.workers.Done() can be run normally.
so I was wandering how this happens and how to recurrent it in local network.

Secondly, as my scenario needs to be in ordered. so i support the 'SetOrderMatters' default value is need to be true. appreciate for your suggestion @MattBrittan

@MattBrittan
Copy link
Contributor

z.MqttClient.SubMsgWithTopicAndQoS(func(client mqtt.Client, message mqtt.Message) {

Can you please show your wrapper function (note that its very difficult to diagnose these issues without a full example and/or full logs). As you appear to be calling the handler in a go routine the comments regarding deadlocks should not apply. Note that the main impact of calling SetOrderMatters(false) is to avoid the use of go routines thus ensuring that messages are processed in order (the ACK is only send when the handler exits) so, as it stands, your code may end up processing multiple messages simultaneously. I would also note that none of this actually guarantees in-order delivery; that will come down to your broker configuration (I generally accept the messages in any order and reassemble before processing because this is significantly faster over dubious network links).

i've added some debug log local and only this "c.workers.Done()" is not run while the other two c.workers.Done() can be run normally. so I was wandering how this happens and how to recurrent it in local network

So this just means that matchAndDispatch is not exiting (which I had assumed was the case based on the snippet of logs you provided). There was a separate issue which has now been fixed (released v1.3.1 yesterday); I think your problem may be different but definitely worth trying that fix (I was unable to duplicate the issue myself but could see how it could potentially happen).

In order to look into this further I'm really going to need full logs (a minimal example would be even better). It definitely looks like there is a deadlock somewhere but I don't currently have enough information to investigate. Note that I'm heading into the mountains tomorrow for a couple of weeks and will have no internet access.

@yunfuyiren
Copy link
Author

@MattBrittan hi, Matt, thank you for your answer, I will try the new version client and here is my whole logs of the dead block. As I said my programs with mqtt now are running at different countries (sub client is in A country, and pub client / broker in another), the blocking scenario will appear coincidentally while running on my local laptop, the connection and message passing run normally, so i only can provide you the log and cant give you a demo of this.

2020/12/28 18:54:04 [DEBUG] [net]      startIncomingComms: received publish, msgId: 3001
2020/12/28 18:54:04 [DEBUG] [net]      logic waiting for msg on ibound
2020/12/28 18:54:04 [DEBUG] [net]      putting puback msg on obound
2020/12/28 18:54:04 [DEBUG] [store]    memorystore del: message 3001 was deleted
2020/12/28 18:54:04 [DEBUG] [net]      done putting puback msg on obound
2020/12/28 18:54:04 [DEBUG] [client]   startCommsWorkers c.oboundP msg:  &{0xc010b92080 <nil>}
2020/12/28 18:54:04 [DEBUG] [net]      obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:04 [DEBUG] [net]      outgoing waiting for an outbound message
2020/12/28 18:54:04 [DEBUG] [client]   enter Publish
2020/12/28 18:54:04 [DEBUG] [client]   sending publish message, topic: stf-692AFE13-0877-5F58-8B5B-949EEACFAE61/353013085721500
2020/12/28 18:54:04 [DEBUG] [client]   #####Publish  c.obound:  #######
2020/12/28 18:54:04 [DEBUG] [client]   startCommsWorkers c.obound msg:  &{0xc00fdb32c0 0xc00fdb3280}
2020/12/28 18:54:04 [DEBUG] [net]      obound msg to write 818
2020/12/28 18:54:04 [DEBUG] [net]      obound wrote msg, id: 818
2020/12/28 18:54:04 [DEBUG] [net]      outgoing waiting for an outbound message
2020/12/28 18:54:04 [DEBUG] [net]      startIncoming Received Message
2020/12/28 18:54:04 [DEBUG] [net]      startIncomingComms: got msg on ibound
2020/12/28 18:54:04 [DEBUG] [store]    memorystore del: message 818 was deleted
2020/12/28 18:54:04 [DEBUG] [net]      startIncomingComms: received puback, id: 818
2020/12/28 18:54:04 [DEBUG] [net]      logic waiting for msg on ibound
2020/12/28 18:54:04 [DEBUG] [net]      startIncoming Received Message
2020/12/28 18:54:04 [DEBUG] [net]      startIncomingComms: got msg on ibound
2020/12/28 18:54:04 [DEBUG] [net]      startIncomingComms: received publish, msgId: 3002
2020/12/28 18:54:04 [DEBUG] [net]      logic waiting for msg on ibound
2020/12/28 18:54:04 [DEBUG] [net]      putting puback msg on obound
2020/12/28 18:54:04 [DEBUG] [store]    memorystore del: message 3002 was deleted
2020/12/28 18:54:04 [DEBUG] [net]      done putting puback msg on obound
2020/12/28 18:54:04 [DEBUG] [client]   startCommsWorkers c.oboundP msg:  &{0xc00062c280 <nil>}
2020/12/28 18:54:04 [DEBUG] [net]      obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:04 [DEBUG] [net]      outgoing waiting for an outbound message
2020/12/28 18:54:04 [DEBUG] [net]      startIncoming Received Message
2020/12/28 18:54:04 [DEBUG] [net]      startIncomingComms: got msg on ibound
2020/12/28 18:54:04 [DEBUG] [net]      startIncomingComms: received publish, msgId: 3003
2020/12/28 18:54:04 [DEBUG] [net]      logic waiting for msg on ibound
2020/12/28 18:54:04 [DEBUG] [net]      putting puback msg on obound
2020/12/28 18:54:04 [DEBUG] [store]    memorystore del: message 3003 was deleted
2020/12/28 18:54:04 [DEBUG] [net]      done putting puback msg on obound
2020/12/28 18:54:04 [DEBUG] [client]   startCommsWorkers c.oboundP msg:  &{0xc000491540 <nil>}
2020/12/28 18:54:04 [DEBUG] [net]      obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:04 [DEBUG] [net]      outgoing waiting for an outbound message
2020/12/28 18:54:06 [DEBUG] [net]      startIncoming Received Message
2020/12/28 18:54:06 [DEBUG] [net]      startIncomingComms: got msg on ibound
2020/12/28 18:54:06 [DEBUG] [net]      startIncomingComms: received publish, msgId: 3004
2020/12/28 18:54:06 [DEBUG] [net]      logic waiting for msg on ibound
2020/12/28 18:54:06 [DEBUG] [net]      putting puback msg on obound
2020/12/28 18:54:06 [DEBUG] [store]    memorystore del: message 3004 was deleted
2020/12/28 18:54:06 [DEBUG] [net]      done putting puback msg on obound
2020/12/28 18:54:06 [DEBUG] [client]   startCommsWorkers c.oboundP msg:  &{0xc00062c680 <nil>}
2020/12/28 18:54:06 [DEBUG] [net]      obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:06 [DEBUG] [net]      outgoing waiting for an outbound message
2020/12/28 18:54:06 [DEBUG] [net]      startIncoming Received Message
2020/12/28 18:54:06 [DEBUG] [net]      startIncomingComms: got msg on ibound
2020/12/28 18:54:06 [DEBUG] [net]      startIncomingComms: received publish, msgId: 3005
2020/12/28 18:54:06 [DEBUG] [net]      logic waiting for msg on ibound
2020/12/28 18:54:06 [DEBUG] [net]      putting puback msg on obound
2020/12/28 18:54:06 [DEBUG] [store]    memorystore del: message 3005 was deleted
2020/12/28 18:54:06 [DEBUG] [net]      done putting puback msg on obound
2020/12/28 18:54:06 [DEBUG] [client]   startCommsWorkers c.oboundP msg:  &{0xc00062c9e0 <nil>}
2020/12/28 18:54:06 [DEBUG] [net]      obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:06 [DEBUG] [net]      outgoing waiting for an outbound message
2020/12/28 18:54:06 [DEBUG] [net]      startIncoming Received Message
2020/12/28 18:54:06 [DEBUG] [net]      startIncomingComms: got msg on ibound
2020/12/28 18:54:06 [DEBUG] [net]      startIncomingComms: received publish, msgId: 3006
2020/12/28 18:54:06 [DEBUG] [net]      logic waiting for msg on ibound
2020/12/28 18:54:06 [DEBUG] [net]      putting puback msg on obound
2020/12/28 18:54:06 [DEBUG] [store]    memorystore del: message 3006 was deleted
2020/12/28 18:54:06 [DEBUG] [net]      done putting puback msg on obound
2020/12/28 18:54:06 [DEBUG] [client]   startCommsWorkers c.oboundP msg:  &{0xc010b921c0 <nil>}
2020/12/28 18:54:06 [DEBUG] [net]      obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:06 [DEBUG] [net]      outgoing waiting for an outbound message
2020/12/28 18:54:07 [DEBUG] [client]   enter Publish
2020/12/28 18:54:07 [DEBUG] [client]   sending publish message, topic: stf-692AFE13-0877-5F58-8B5B-949EEACFAE61/9C071FFAZ000J6
2020/12/28 18:54:07 [DEBUG] [client]   #####Publish  c.obound:  #######
2020/12/28 18:54:07 [DEBUG] [client]   startCommsWorkers c.obound msg:  &{0xc0074fbe80 0xc0074fbe40}
2020/12/28 18:54:07 [DEBUG] [net]      obound msg to write 819
2020/12/28 18:54:07 [DEBUG] [net]      obound wrote msg, id: 819
2020/12/28 18:54:07 [DEBUG] [net]      outgoing waiting for an outbound message
2020/12/28 18:54:07 [DEBUG] [net]      startIncoming Received Message
2020/12/28 18:54:07 [DEBUG] [net]      startIncomingComms: got msg on ibound
2020/12/28 18:54:07 [DEBUG] [store]    memorystore del: message 819 was deleted
2020/12/28 18:54:07 [DEBUG] [net]      startIncomingComms: received puback, id: 819
2020/12/28 18:54:07 [DEBUG] [net]      logic waiting for msg on ibound
2020/12/28 18:54:08 [DEBUG] [pinger]   ping check 1.279685498
2020/12/28 18:54:13 [DEBUG] [net]      startIncoming Received Message
2020/12/28 18:54:13 [DEBUG] [net]      startIncomingComms: got msg on ibound
2020/12/28 18:54:13 [DEBUG] [net]      startIncomingComms: received publish, msgId: 3007
2020/12/28 18:54:13 [DEBUG] [net]      logic waiting for msg on ibound
2020/12/28 18:54:13 [DEBUG] [net]      putting puback msg on obound
2020/12/28 18:54:13 [DEBUG] [store]    memorystore del: message 3007 was deleted
2020/12/28 18:54:13 [DEBUG] [net]      done putting puback msg on obound
2020/12/28 18:54:13 [DEBUG] [client]   startCommsWorkers c.oboundP msg:  &{0xc010b923e0 <nil>}
2020/12/28 18:54:13 [DEBUG] [net]      obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:13 [DEBUG] [net]      outgoing waiting for an outbound message
2020/12/28 18:54:13 [DEBUG] [pinger]   ping check 0.45940204
2020/12/28 18:54:14 [DEBUG] [client]   enter Publish
2020/12/28 18:54:14 [DEBUG] [client]   sending publish message, topic: stf-692AFE13-0877-5F58-8B5B-949EEACFAE61/353013085721500
2020/12/28 18:54:14 [DEBUG] [client]   #####Publish  c.obound:  #######
2020/12/28 18:54:14 [DEBUG] [client]   startCommsWorkers c.obound msg:  &{0xc00c95cb00 0xc00c95c940}
2020/12/28 18:54:14 [DEBUG] [net]      obound msg to write 820
2020/12/28 18:54:14 [DEBUG] [net]      obound wrote msg, id: 820
2020/12/28 18:54:14 [DEBUG] [net]      outgoing waiting for an outbound message
2020/12/28 18:54:14 [DEBUG] [net]      startIncoming Received Message
2020/12/28 18:54:14 [DEBUG] [net]      startIncomingComms: got msg on ibound
2020/12/28 18:54:14 [DEBUG] [store]    memorystore del: message 820 was deleted
2020/12/28 18:54:14 [DEBUG] [net]      startIncomingComms: received puback, id: 820
2020/12/28 18:54:14 [DEBUG] [net]      logic waiting for msg on ibound
2020/12/28 18:54:14 [DEBUG] [net]      startIncoming Received Message
2020/12/28 18:54:14 [DEBUG] [net]      startIncomingComms: got msg on ibound
2020/12/28 18:54:14 [DEBUG] [net]      startIncomingComms: received publish, msgId: 3008
2020/12/28 18:54:14 [DEBUG] [net]      logic waiting for msg on ibound
2020/12/28 18:54:14 [DEBUG] [net]      putting puback msg on obound
2020/12/28 18:54:14 [DEBUG] [store]    memorystore del: message 3008 was deleted
2020/12/28 18:54:14 [DEBUG] [net]      done putting puback msg on obound
2020/12/28 18:54:14 [DEBUG] [client]   startCommsWorkers c.oboundP msg:  &{0xc010b92660 <nil>}
2020/12/28 18:54:14 [DEBUG] [net]      obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:14 [DEBUG] [net]      outgoing waiting for an outbound message
2020/12/28 18:54:14 [DEBUG] [net]      startIncoming Received Message
2020/12/28 18:54:14 [DEBUG] [net]      startIncomingComms: got msg on ibound
2020/12/28 18:54:14 [DEBUG] [net]      startIncomingComms: received publish, msgId: 3009
2020/12/28 18:54:14 [DEBUG] [net]      logic waiting for msg on ibound
2020/12/28 18:54:14 [DEBUG] [net]      putting puback msg on obound
2020/12/28 18:54:14 [DEBUG] [store]    memorystore del: message 3009 was deleted
2020/12/28 18:54:14 [DEBUG] [net]      done putting puback msg on obound
2020/12/28 18:54:14 [DEBUG] [client]   startCommsWorkers c.oboundP msg:  &{0xc00062dc20 <nil>}
2020/12/28 18:54:14 [DEBUG] [net]      obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:14 [DEBUG] [net]      outgoing waiting for an outbound message
2020/12/28 18:54:16 [DEBUG] [net]      startIncoming Received Message
2020/12/28 18:54:16 [DEBUG] [net]      startIncomingComms: got msg on ibound
2020/12/28 18:54:16 [DEBUG] [net]      startIncomingComms: received publish, msgId: 3010
2020/12/28 18:54:16 [DEBUG] [net]      logic waiting for msg on ibound
2020/12/28 18:54:16 [DEBUG] [net]      putting puback msg on obound
2020/12/28 18:54:16 [DEBUG] [store]    memorystore del: message 3010 was deleted
2020/12/28 18:54:16 [DEBUG] [net]      done putting puback msg on obound
2020/12/28 18:54:16 [DEBUG] [client]   startCommsWorkers c.oboundP msg:  &{0xc00567e0e0 <nil>}
2020/12/28 18:54:16 [DEBUG] [net]      obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:16 [DEBUG] [net]      outgoing waiting for an outbound message
2020/12/28 18:54:17 [DEBUG] [client]   enter Publish
2020/12/28 18:54:17 [DEBUG] [client]   sending publish message, topic: stf-692AFE13-0877-5F58-8B5B-949EEACFAE61/9C071FFAZ000J6
2020/12/28 18:54:17 [DEBUG] [client]   #####Publish  c.obound:  #######
2020/12/28 18:54:17 [DEBUG] [client]   startCommsWorkers c.obound msg:  &{0xc00c67bc40 0xc00c67bc00}
2020/12/28 18:54:17 [DEBUG] [net]      obound msg to write 821
2020/12/28 18:54:17 [DEBUG] [net]      obound wrote msg, id: 821
2020/12/28 18:54:17 [DEBUG] [net]      outgoing waiting for an outbound message
2020/12/28 18:54:17 [DEBUG] [net]      startIncoming Received Message
2020/12/28 18:54:17 [DEBUG] [net]      startIncomingComms: got msg on ibound
2020/12/28 18:54:17 [DEBUG] [store]    memorystore del: message 821 was deleted
2020/12/28 18:54:17 [DEBUG] [net]      startIncomingComms: received puback, id: 821
2020/12/28 18:54:17 [DEBUG] [net]      logic waiting for msg on ibound
2020/12/28 18:54:18 [DEBUG] [pinger]   ping check 1.335859114
2020/12/28 18:54:23 [DEBUG] [net]      startIncoming Received Message
2020/12/28 18:54:23 [DEBUG] [net]      startIncomingComms: got msg on ibound
2020/12/28 18:54:23 [DEBUG] [net]      startIncomingComms: received publish, msgId: 3011
2020/12/28 18:54:23 [DEBUG] [net]      logic waiting for msg on ibound
2020/12/28 18:54:23 [DEBUG] [net]      putting puback msg on obound
2020/12/28 18:54:23 [DEBUG] [store]    memorystore del: message 3011 was deleted
2020/12/28 18:54:23 [DEBUG] [net]      done putting puback msg on obound
2020/12/28 18:54:23 [DEBUG] [client]   startCommsWorkers c.oboundP msg:  &{0xc01123c840 <nil>}
2020/12/28 18:54:23 [DEBUG] [net]      obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:23 [DEBUG] [net]      outgoing waiting for an outbound message
2020/12/28 18:54:23 [DEBUG] [pinger]   ping check 0.476932603
2020/12/28 18:54:24 [DEBUG] [client]   enter Publish
2020/12/28 18:54:24 [DEBUG] [client]   sending publish message, topic: stf-692AFE13-0877-5F58-8B5B-949EEACFAE61/353013085721500
2020/12/28 18:54:24 [DEBUG] [client]   #####Publish  c.obound:  #######
2020/12/28 18:54:24 [DEBUG] [client]   startCommsWorkers c.obound msg:  &{0xc00fe2cac0 0xc00fe2ca80}
2020/12/28 18:54:24 [DEBUG] [net]      obound msg to write 822
2020/12/28 18:54:24 [DEBUG] [net]      obound wrote msg, id: 822
2020/12/28 18:54:24 [DEBUG] [net]      outgoing waiting for an outbound message
2020/12/28 18:54:24 [DEBUG] [net]      startIncoming Received Message
2020/12/28 18:54:24 [DEBUG] [net]      startIncomingComms: got msg on ibound
2020/12/28 18:54:24 [DEBUG] [store]    memorystore del: message 822 was deleted
2020/12/28 18:54:24 [DEBUG] [net]      startIncomingComms: received puback, id: 822
2020/12/28 18:54:24 [DEBUG] [net]      logic waiting for msg on ibound
2020/12/28 18:54:26 [DEBUG] [net]      startIncoming Received Message
2020/12/28 18:54:26 [DEBUG] [net]      startIncomingComms: got msg on ibound
2020/12/28 18:54:26 [DEBUG] [net]      startIncomingComms: received publish, msgId: 3012
2020/12/28 18:54:26 [DEBUG] [net]      logic waiting for msg on ibound
2020/12/28 18:54:26 [DEBUG] [net]      putting puback msg on obound
2020/12/28 18:54:26 [DEBUG] [store]    memorystore del: message 3012 was deleted
2020/12/28 18:54:26 [DEBUG] [net]      done putting puback msg on obound
2020/12/28 18:54:26 [DEBUG] [client]   startCommsWorkers c.oboundP msg:  &{0xc000477fc0 <nil>}
2020/12/28 18:54:26 [DEBUG] [net]      obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:26 [DEBUG] [net]      outgoing waiting for an outbound message
2020/12/28 18:54:27 [DEBUG] [client]   enter Publish
2020/12/28 18:54:27 [DEBUG] [client]   sending publish message, topic: stf-692AFE13-0877-5F58-8B5B-949EEACFAE61/9C071FFAZ000J6
2020/12/28 18:54:27 [DEBUG] [client]   #####Publish  c.obound:  #######
2020/12/28 18:54:27 [DEBUG] [client]   startCommsWorkers c.obound msg:  &{0xc00fe2cd40 0xc00fe2cc80}
2020/12/28 18:54:27 [DEBUG] [net]      obound msg to write 823
2020/12/28 18:54:27 [DEBUG] [net]      obound wrote msg, id: 823
2020/12/28 18:54:27 [DEBUG] [net]      outgoing waiting for an outbound message
2020/12/28 18:54:27 [DEBUG] [net]      startIncoming Received Message
2020/12/28 18:54:27 [DEBUG] [net]      startIncomingComms: got msg on ibound
2020/12/28 18:54:27 [DEBUG] [store]    memorystore del: message 823 was deleted
2020/12/28 18:54:27 [DEBUG] [net]      startIncomingComms: received puback, id: 823
2020/12/28 18:54:27 [DEBUG] [net]      logic waiting for msg on ibound
2020/12/28 18:54:28 [DEBUG] [pinger]   ping check 1.365129176
2020/12/28 18:54:33 [DEBUG] [net]      startIncoming Received Message
2020/12/28 18:54:33 [DEBUG] [net]      startIncomingComms: got msg on ibound
2020/12/28 18:54:33 [DEBUG] [net]      startIncomingComms: received publish, msgId: 3013
2020/12/28 18:54:33 [DEBUG] [net]      logic waiting for msg on ibound
2020/12/28 18:54:33 [DEBUG] [net]      putting puback msg on obound
2020/12/28 18:54:33 [DEBUG] [store]    memorystore del: message 3013 was deleted
2020/12/28 18:54:33 [DEBUG] [net]      done putting puback msg on obound
2020/12/28 18:54:33 [DEBUG] [client]   startCommsWorkers c.oboundP msg:  &{0xc00567e000 <nil>}
2020/12/28 18:54:33 [DEBUG] [net]      obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:33 [DEBUG] [net]      outgoing waiting for an outbound message
2020/12/28 18:54:33 [DEBUG] [pinger]   ping check 0.456312549
2020/12/28 18:54:34 [DEBUG] [client]   enter Publish
2020/12/28 18:54:34 [DEBUG] [client]   sending publish message, topic: stf-692AFE13-0877-5F58-8B5B-949EEACFAE61/353013085721500
2020/12/28 18:54:34 [DEBUG] [client]   #####Publish  c.obound:  #######
2020/12/28 18:54:34 [DEBUG] [client]   startCommsWorkers c.obound msg:  &{0xc00e416280 0xc00e416240}
2020/12/28 18:54:34 [DEBUG] [net]      obound msg to write 824
2020/12/28 18:54:34 [DEBUG] [net]      obound wrote msg, id: 824
2020/12/28 18:54:34 [DEBUG] [net]      outgoing waiting for an outbound message
2020/12/28 18:54:34 [DEBUG] [net]      startIncoming Received Message
2020/12/28 18:54:34 [DEBUG] [net]      startIncomingComms: got msg on ibound
2020/12/28 18:54:34 [DEBUG] [store]    memorystore del: message 824 was deleted
2020/12/28 18:54:34 [DEBUG] [net]      startIncomingComms: received puback, id: 824
2020/12/28 18:54:34 [DEBUG] [net]      logic waiting for msg on ibound
2020/12/28 18:54:36 [DEBUG] [net]      startIncoming Received Message
2020/12/28 18:54:36 [DEBUG] [net]      startIncomingComms: got msg on ibound
2020/12/28 18:54:36 [DEBUG] [net]      startIncomingComms: received publish, msgId: 3014
2020/12/28 18:54:36 [DEBUG] [net]      logic waiting for msg on ibound
2020/12/28 18:54:36 [DEBUG] [net]      putting puback msg on obound
2020/12/28 18:54:36 [DEBUG] [store]    memorystore del: message 3014 was deleted
2020/12/28 18:54:36 [DEBUG] [net]      done putting puback msg on obound
2020/12/28 18:54:36 [DEBUG] [client]   startCommsWorkers c.oboundP msg:  &{0xc00567e640 <nil>}
2020/12/28 18:54:36 [DEBUG] [net]      obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:36 [DEBUG] [net]      outgoing waiting for an outbound message
2020/12/28 18:54:37 [DEBUG] [client]   enter Publish
2020/12/28 18:54:37 [DEBUG] [client]   sending publish message, topic: stf-692AFE13-0877-5F58-8B5B-949EEACFAE61/9C071FFAZ000J6
2020/12/28 18:54:37 [DEBUG] [client]   #####Publish  c.obound:  #######
2020/12/28 18:54:37 [DEBUG] [client]   startCommsWorkers c.obound msg:  &{0xc00fdb20c0 0xc00fdb2080}
2020/12/28 18:54:37 [DEBUG] [net]      obound msg to write 825
2020/12/28 18:54:37 [DEBUG] [net]      obound wrote msg, id: 825
2020/12/28 18:54:37 [DEBUG] [net]      outgoing waiting for an outbound message
2020/12/28 18:54:37 [DEBUG] [net]      startIncoming Received Message
2020/12/28 18:54:37 [DEBUG] [net]      startIncomingComms: got msg on ibound
2020/12/28 18:54:37 [DEBUG] [store]    memorystore del: message 825 was deleted
2020/12/28 18:54:37 [DEBUG] [net]      startIncomingComms: received puback, id: 825
2020/12/28 18:54:37 [DEBUG] [net]      logic waiting for msg on ibound
2020/12/28 18:54:38 [DEBUG] [pinger]   ping check 1.311000699
2020/12/28 18:54:41 [DEBUG] [net]      startIncoming Received Message
2020/12/28 18:54:41 [DEBUG] [net]      startIncomingComms: got msg on ibound
2020/12/28 18:54:41 [DEBUG] [net]      startIncomingComms: received publish, msgId: 3015
2020/12/28 18:54:41 [DEBUG] [net]      logic waiting for msg on ibound
2020/12/28 18:54:42 [DEBUG] [net]      putting puback msg on obound
2020/12/28 18:54:42 [DEBUG] [store]    memorystore del: message 3015 was deleted
2020/12/28 18:54:42 [DEBUG] [net]      done putting puback msg on obound
2020/12/28 18:54:42 [DEBUG] [client]   startCommsWorkers c.oboundP msg:  &{0xc013762b60 <nil>}
2020/12/28 18:54:42 [DEBUG] [net]      obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:42 [DEBUG] [net]      outgoing waiting for an outbound message
2020/12/28 18:54:43 [DEBUG] [net]      startIncoming Received Message
2020/12/28 18:54:43 [DEBUG] [net]      startIncomingComms: got msg on ibound
2020/12/28 18:54:43 [DEBUG] [net]      startIncomingComms: received publish, msgId: 3016
2020/12/28 18:54:43 [DEBUG] [net]      logic waiting for msg on ibound
2020/12/28 18:54:43 [DEBUG] [net]      putting puback msg on obound
2020/12/28 18:54:43 [DEBUG] [store]    memorystore del: message 3016 was deleted
2020/12/28 18:54:43 [DEBUG] [net]      done putting puback msg on obound
2020/12/28 18:54:43 [DEBUG] [client]   startCommsWorkers c.oboundP msg:  &{0xc00060f940 <nil>}
2020/12/28 18:54:43 [DEBUG] [net]      obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:43 [DEBUG] [net]      outgoing waiting for an outbound message
2020/12/28 18:54:43 [DEBUG] [net]      startIncoming Received Message
2020/12/28 18:54:43 [DEBUG] [net]      startIncomingComms: got msg on ibound
2020/12/28 18:54:43 [DEBUG] [net]      startIncomingComms: received publish, msgId: 3017
2020/12/28 18:54:43 [DEBUG] [net]      logic waiting for msg on ibound
2020/12/28 18:54:43 [DEBUG] [net]      putting puback msg on obound
2020/12/28 18:54:43 [DEBUG] [store]    memorystore del: message 3017 was deleted
2020/12/28 18:54:43 [DEBUG] [net]      done putting puback msg on obound
2020/12/28 18:54:43 [DEBUG] [client]   startCommsWorkers c.oboundP msg:  &{0xc001c207c0 <nil>}
2020/12/28 18:54:43 [DEBUG] [net]      obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:43 [DEBUG] [net]      outgoing waiting for an outbound message
2020/12/28 18:54:43 [DEBUG] [net]      startIncoming Received Message
2020/12/28 18:54:43 [DEBUG] [net]      startIncomingComms: got msg on ibound
2020/12/28 18:54:43 [DEBUG] [net]      startIncomingComms: received publish, msgId: 3018
2020/12/28 18:54:43 [DEBUG] [net]      logic waiting for msg on ibound
2020/12/28 18:54:43 [DEBUG] [net]      putting puback msg on obound
2020/12/28 18:54:43 [DEBUG] [store]    memorystore del: message 3018 was deleted
2020/12/28 18:54:43 [DEBUG] [net]      done putting puback msg on obound
2020/12/28 18:54:43 [DEBUG] [client]   startCommsWorkers c.oboundP msg:  &{0xc001c20840 <nil>}
2020/12/28 18:54:43 [DEBUG] [net]      obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:43 [DEBUG] [net]      outgoing waiting for an outbound message
2020/12/28 18:54:43 [DEBUG] [pinger]   ping check 0.479193262
2020/12/28 18:54:44 [DEBUG] [net]      startIncoming Received Message
2020/12/28 18:54:44 [DEBUG] [net]      startIncomingComms: got msg on ibound
2020/12/28 18:54:44 [DEBUG] [net]      startIncomingComms: received publish, msgId: 3019
2020/12/28 18:54:44 [DEBUG] [net]      logic waiting for msg on ibound
2020/12/28 18:54:44 [DEBUG] [net]      putting puback msg on obound
2020/12/28 18:54:44 [DEBUG] [store]    memorystore del: message 3019 was deleted
2020/12/28 18:54:44 [DEBUG] [net]      done putting puback msg on obound
2020/12/28 18:54:44 [DEBUG] [client]   startCommsWorkers c.oboundP msg:  &{0xc01123cd00 <nil>}
2020/12/28 18:54:44 [DEBUG] [net]      obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:44 [DEBUG] [net]      outgoing waiting for an outbound message
2020/12/28 18:54:44 [DEBUG] [net]      startIncoming Received Message
2020/12/28 18:54:44 [DEBUG] [net]      startIncomingComms: got msg on ibound
2020/12/28 18:54:44 [DEBUG] [net]      startIncomingComms: received publish, msgId: 3020
2020/12/28 18:54:44 [DEBUG] [net]      logic waiting for msg on ibound
2020/12/28 18:54:44 [DEBUG] [net]      putting puback msg on obound
2020/12/28 18:54:44 [DEBUG] [store]    memorystore del: message 3020 was deleted
2020/12/28 18:54:44 [DEBUG] [net]      done putting puback msg on obound
2020/12/28 18:54:44 [DEBUG] [client]   startCommsWorkers c.oboundP msg:  &{0xc001c20aa0 <nil>}
2020/12/28 18:54:44 [DEBUG] [net]      obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:44 [DEBUG] [net]      outgoing waiting for an outbound message
2020/12/28 18:54:44 [DEBUG] [client]   enter Publish
2020/12/28 18:54:44 [DEBUG] [client]   sending publish message, topic: stf-692AFE13-0877-5F58-8B5B-949EEACFAE61/353013085721500
2020/12/28 18:54:44 [DEBUG] [client]   #####Publish  c.obound:  #######
2020/12/28 18:54:44 [DEBUG] [client]   startCommsWorkers c.obound msg:  &{0xc00fe2c840 0xc00fe2c7c0}
2020/12/28 18:54:44 [DEBUG] [net]      obound msg to write 826
2020/12/28 18:54:44 [DEBUG] [net]      obound wrote msg, id: 826
2020/12/28 18:54:44 [DEBUG] [net]      outgoing waiting for an outbound message
2020/12/28 18:54:44 [DEBUG] [net]      startIncoming Received Message
2020/12/28 18:54:44 [DEBUG] [net]      startIncomingComms: got msg on ibound
2020/12/28 18:54:44 [DEBUG] [store]    memorystore del: message 826 was deleted
2020/12/28 18:54:44 [DEBUG] [net]      startIncomingComms: received puback, id: 826
2020/12/28 18:54:44 [DEBUG] [net]      logic waiting for msg on ibound
2020/12/28 18:54:44 [DEBUG] [net]      startIncoming Received Message
2020/12/28 18:54:44 [DEBUG] [net]      startIncomingComms: got msg on ibound
2020/12/28 18:54:44 [DEBUG] [net]      startIncomingComms: received publish, msgId: 3021
2020/12/28 18:54:44 [DEBUG] [net]      logic waiting for msg on ibound
2020/12/28 18:54:44 [DEBUG] [net]      putting puback msg on obound
2020/12/28 18:54:44 [DEBUG] [store]    memorystore del: message 3021 was deleted
2020/12/28 18:54:44 [DEBUG] [net]      done putting puback msg on obound
2020/12/28 18:54:44 [DEBUG] [client]   startCommsWorkers c.oboundP msg:  &{0xc01123cdc0 <nil>}
2020/12/28 18:54:44 [DEBUG] [net]      obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:44 [DEBUG] [net]      outgoing waiting for an outbound message
2020/12/28 18:54:44 [DEBUG] [net]      startIncoming Received Message
2020/12/28 18:54:44 [DEBUG] [net]      startIncomingComms: got msg on ibound
2020/12/28 18:54:44 [DEBUG] [net]      startIncomingComms: received publish, msgId: 3022
2020/12/28 18:54:44 [DEBUG] [net]      logic waiting for msg on ibound
2020/12/28 18:54:44 [DEBUG] [net]      putting puback msg on obound
2020/12/28 18:54:44 [DEBUG] [store]    memorystore del: message 3022 was deleted
2020/12/28 18:54:44 [DEBUG] [net]      done putting puback msg on obound
2020/12/28 18:54:44 [DEBUG] [client]   startCommsWorkers c.oboundP msg:  &{0xc000222080 <nil>}
2020/12/28 18:54:44 [DEBUG] [net]      obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:44 [DEBUG] [net]      outgoing waiting for an outbound message
2020/12/28 18:54:45 [DEBUG] [net]      startIncoming Received Message
2020/12/28 18:54:45 [DEBUG] [net]      startIncomingComms: got msg on ibound
2020/12/28 18:54:45 [DEBUG] [net]      startIncomingComms: received publish, msgId: 3023
2020/12/28 18:54:45 [DEBUG] [net]      logic waiting for msg on ibound
2020/12/28 18:54:45 [DEBUG] [net]      putting puback msg on obound
2020/12/28 18:54:45 [DEBUG] [store]    memorystore del: message 3023 was deleted
2020/12/28 18:54:45 [DEBUG] [net]      done putting puback msg on obound
2020/12/28 18:54:45 [DEBUG] [client]   startCommsWorkers c.oboundP msg:  &{0xc01123ce80 <nil>}
2020/12/28 18:54:45 [DEBUG] [net]      obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:45 [DEBUG] [net]      outgoing waiting for an outbound message
2020/12/28 18:54:45 [DEBUG] [net]      startIncoming Received Message
2020/12/28 18:54:45 [DEBUG] [net]      startIncomingComms: got msg on ibound
2020/12/28 18:54:45 [DEBUG] [net]      startIncomingComms: received publish, msgId: 3024
2020/12/28 18:54:45 [DEBUG] [net]      logic waiting for msg on ibound
2020/12/28 18:54:45 [DEBUG] [net]      putting puback msg on obound
2020/12/28 18:54:45 [DEBUG] [store]    memorystore del: message 3024 was deleted
2020/12/28 18:54:45 [DEBUG] [net]      done putting puback msg on obound
2020/12/28 18:54:45 [DEBUG] [client]   startCommsWorkers c.oboundP msg:  &{0xc0002221c0 <nil>}
2020/12/28 18:54:45 [DEBUG] [net]      obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:45 [DEBUG] [net]      outgoing waiting for an outbound message
2020/12/28 18:54:46 [DEBUG] [net]      startIncoming Received Message
2020/12/28 18:54:46 [DEBUG] [net]      startIncomingComms: got msg on ibound
2020/12/28 18:54:46 [DEBUG] [net]      startIncomingComms: received publish, msgId: 3025
2020/12/28 18:54:46 [DEBUG] [net]      logic waiting for msg on ibound
2020/12/28 18:54:46 [DEBUG] [net]      putting puback msg on obound
2020/12/28 18:54:46 [DEBUG] [store]    memorystore del: message 3025 was deleted
2020/12/28 18:54:46 [DEBUG] [net]      done putting puback msg on obound
2020/12/28 18:54:46 [DEBUG] [client]   startCommsWorkers c.oboundP msg:  &{0xc01123cf60 <nil>}
2020/12/28 18:54:46 [DEBUG] [net]      obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:46 [DEBUG] [net]      outgoing waiting for an outbound message
2020/12/28 18:54:47 [DEBUG] [net]      startIncoming Received Message
2020/12/28 18:54:47 [DEBUG] [net]      startIncomingComms: got msg on ibound
2020/12/28 18:54:47 [DEBUG] [net]      startIncomingComms: received publish, msgId: 3026
2020/12/28 18:54:47 [DEBUG] [net]      logic waiting for msg on ibound
2020/12/28 18:54:47 [DEBUG] [net]      putting puback msg on obound
2020/12/28 18:54:47 [DEBUG] [store]    memorystore del: message 3026 was deleted
2020/12/28 18:54:47 [DEBUG] [net]      done putting puback msg on obound
2020/12/28 18:54:47 [DEBUG] [client]   startCommsWorkers c.oboundP msg:  &{0xc0002226a0 <nil>}
2020/12/28 18:54:47 [DEBUG] [net]      obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:47 [DEBUG] [net]      outgoing waiting for an outbound message
2020/12/28 18:54:47 [DEBUG] [net]      startIncoming Received Message
2020/12/28 18:54:47 [DEBUG] [net]      startIncomingComms: got msg on ibound
2020/12/28 18:54:47 [DEBUG] [net]      startIncomingComms: received publish, msgId: 0
2020/12/28 18:54:47 [DEBUG] [net]      logic waiting for msg on ibound
2020/12/28 18:54:47 [DEBUG] [net]      startIncoming Received Message
2020/12/28 18:54:47 [DEBUG] [net]      startIncomingComms: got msg on ibound
2020/12/28 18:54:47 [DEBUG] [net]      startIncomingComms: received publish, msgId: 3027
2020/12/28 18:54:47 [DEBUG] [net]      logic waiting for msg on ibound
2020/12/28 18:54:47 [DEBUG] [net]      putting puback msg on obound
2020/12/28 18:54:47 [DEBUG] [store]    memorystore del: message 3027 was deleted
2020/12/28 18:54:47 [DEBUG] [net]      done putting puback msg on obound
2020/12/28 18:54:47 [DEBUG] [client]   startCommsWorkers c.oboundP msg:  &{0xc01123cfa0 <nil>}
2020/12/28 18:54:47 [DEBUG] [net]      obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:47 [DEBUG] [net]      outgoing waiting for an outbound message
2020/12/28 18:54:47 [DEBUG] [client]   enter Publish
2020/12/28 18:54:47 [DEBUG] [client]   sending publish message, topic: stf-692AFE13-0877-5F58-8B5B-949EEACFAE61/9C071FFAZ000J6
2020/12/28 18:54:47 [DEBUG] [client]   #####Publish  c.obound:  #######
2020/12/28 18:54:47 [DEBUG] [client]   startCommsWorkers c.obound msg:  &{0xc010a42840 0xc010a42800}
2020/12/28 18:54:47 [DEBUG] [net]      obound msg to write 827
2020/12/28 18:54:47 [DEBUG] [net]      obound wrote msg, id: 827
2020/12/28 18:54:47 [DEBUG] [net]      outgoing waiting for an outbound message
2020/12/28 18:54:47 [DEBUG] [net]      startIncoming Received Message
2020/12/28 18:54:47 [DEBUG] [net]      startIncomingComms: got msg on ibound
2020/12/28 18:54:47 [DEBUG] [store]    memorystore del: message 827 was deleted
2020/12/28 18:54:47 [DEBUG] [net]      startIncomingComms: received puback, id: 827
2020/12/28 18:54:47 [DEBUG] [net]      logic waiting for msg on ibound
2020/12/28 18:54:48 [DEBUG] [pinger]   ping check 1.453831872
2020/12/28 18:54:51 [DEBUG] [net]      startIncoming Received Message
2020/12/28 18:54:51 [DEBUG] [net]      startIncomingComms: got msg on ibound
2020/12/28 18:54:51 [DEBUG] [net]      startIncomingComms: received publish, msgId: 3028
2020/12/28 18:54:51 [DEBUG] [net]      logic waiting for msg on ibound
2020/12/28 18:54:51 [DEBUG] [net]      startIncoming Received Message
2020/12/28 18:54:51 [DEBUG] [net]      startIncomingComms: got msg on ibound
2020/12/28 18:54:51 [DEBUG] [net]      startIncomingComms: received publish, msgId: 3029
2020/12/28 18:54:51 [DEBUG] [net]      logic waiting for msg on ibound
2020/12/28 18:54:51 [DEBUG] [net]      startIncoming Received Message
2020/12/28 18:54:51 [DEBUG] [net]      startIncomingComms: got msg on ibound
2020/12/28 18:54:51 [DEBUG] [net]      startIncomingComms: received publish, msgId: 3030
2020/12/28 18:54:51 [DEBUG] [net]      logic waiting for msg on ibound
2020/12/28 18:54:52 [DEBUG] [client]   enter Publish
2020/12/28 18:54:52 [DEBUG] [client]   sending publish message, topic: stf-692AFE13-0877-5F58-8B5B-949EEACFAE61/5c922e1d
2020/12/28 18:54:52 [DEBUG] [client]   #####Publish  c.obound:  #######
2020/12/28 18:54:52 [DEBUG] [client]   startCommsWorkers c.obound msg:  &{0xc00fdb2600 0xc00fdb25c0}
2020/12/28 18:54:52 [DEBUG] [net]      obound msg to write 828
2020/12/28 18:54:52 [DEBUG] [net]      obound wrote msg, id: 828
2020/12/28 18:54:52 [DEBUG] [net]      outgoing waiting for an outbound message
2020/12/28 18:54:52 [DEBUG] [net]      startIncoming Received Message
2020/12/28 18:54:52 [DEBUG] [net]      startIncomingComms: got msg on ibound
2020/12/28 18:54:52 [DEBUG] [store]    memorystore del: message 828 was deleted
2020/12/28 18:54:52 [DEBUG] [net]      startIncomingComms: received puback, id: 828
2020/12/28 18:54:52 [DEBUG] [net]      logic waiting for msg on ibound
2020/12/28 18:54:52 [DEBUG] [net]      putting puback msg on obound
2020/12/28 18:54:52 [DEBUG] [store]    memorystore del: message 3028 was deleted
2020/12/28 18:54:52 [DEBUG] [net]      done putting puback msg on obound
2020/12/28 18:54:52 [DEBUG] [client]   startCommsWorkers c.oboundP msg:  &{0xc0137636e0 <nil>}
2020/12/28 18:54:52 [DEBUG] [net]      putting puback msg on obound
2020/12/28 18:54:52 [DEBUG] [net]      obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:52 [DEBUG] [store]    memorystore del: message 3029 was deleted
2020/12/28 18:54:52 [DEBUG] [net]      done putting puback msg on obound
2020/12/28 18:54:52 [DEBUG] [client]   startCommsWorkers c.oboundP msg:  &{0xc013763740 <nil>}
2020/12/28 18:54:52 [DEBUG] [net]      outgoing waiting for an outbound message
2020/12/28 18:54:52 [DEBUG] [net]      obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:52 [DEBUG] [net]      outgoing waiting for an outbound message
2020/12/28 18:54:52 [DEBUG] [net]      putting puback msg on obound
2020/12/28 18:54:52 [DEBUG] [store]    memorystore del: message 3030 was deleted
2020/12/28 18:54:52 [DEBUG] [net]      done putting puback msg on obound
2020/12/28 18:54:52 [DEBUG] [client]   startCommsWorkers c.oboundP msg:  &{0xc013763760 <nil>}
2020/12/28 18:54:52 [DEBUG] [net]      obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:52 [DEBUG] [net]      outgoing waiting for an outbound message
2020/12/28 18:54:52 [DEBUG] [net]      startIncoming Received Message
2020/12/28 18:54:52 [DEBUG] [net]      startIncomingComms: got msg on ibound
2020/12/28 18:54:52 [DEBUG] [net]      startIncomingComms: received publish, msgId: 3031
2020/12/28 18:54:52 [DEBUG] [net]      logic waiting for msg on ibound
2020/12/28 18:54:52 [DEBUG] [net]      putting puback msg on obound
2020/12/28 18:54:52 [DEBUG] [store]    memorystore del: message 3031 was deleted
2020/12/28 18:54:52 [DEBUG] [net]      done putting puback msg on obound
2020/12/28 18:54:52 [DEBUG] [client]   startCommsWorkers c.oboundP msg:  &{0xc01123d320 <nil>}
2020/12/28 18:54:52 [DEBUG] [net]      obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:52 [DEBUG] [net]      outgoing waiting for an outbound message
2020/12/28 18:54:52 [DEBUG] [net]      startIncoming Received Message
2020/12/28 18:54:52 [DEBUG] [net]      startIncomingComms: got msg on ibound
2020/12/28 18:54:52 [DEBUG] [net]      startIncomingComms: received publish, msgId: 3032
2020/12/28 18:54:52 [DEBUG] [net]      logic waiting for msg on ibound
2020/12/28 18:54:52 [DEBUG] [net]      putting puback msg on obound
2020/12/28 18:54:52 [DEBUG] [store]    memorystore del: message 3032 was deleted
2020/12/28 18:54:52 [DEBUG] [net]      done putting puback msg on obound
2020/12/28 18:54:52 [DEBUG] [client]   startCommsWorkers c.oboundP msg:  &{0xc010b928a0 <nil>}
2020/12/28 18:54:52 [DEBUG] [net]      obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:52 [DEBUG] [net]      outgoing waiting for an outbound message
2020/12/28 18:54:53 [DEBUG] [net]      startIncoming Received Message
2020/12/28 18:54:53 [DEBUG] [net]      startIncomingComms: got msg on ibound
2020/12/28 18:54:53 [DEBUG] [net]      startIncomingComms: received publish, msgId: 3033
2020/12/28 18:54:53 [DEBUG] [net]      logic waiting for msg on ibound
2020/12/28 18:54:53 [DEBUG] [net]      putting puback msg on obound
2020/12/28 18:54:53 [DEBUG] [store]    memorystore del: message 3033 was deleted
2020/12/28 18:54:53 [DEBUG] [net]      done putting puback msg on obound
2020/12/28 18:54:53 [DEBUG] [client]   startCommsWorkers c.oboundP msg:  &{0xc013763960 <nil>}
2020/12/28 18:54:53 [DEBUG] [net]      obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:53 [DEBUG] [net]      outgoing waiting for an outbound message
2020/12/28 18:54:53 [DEBUG] [net]      startIncoming Received Message
2020/12/28 18:54:53 [DEBUG] [net]      startIncomingComms: got msg on ibound
2020/12/28 18:54:53 [DEBUG] [net]      startIncomingComms: received publish, msgId: 3034
2020/12/28 18:54:53 [DEBUG] [net]      logic waiting for msg on ibound
2020/12/28 18:54:53 [DEBUG] [net]      putting puback msg on obound
2020/12/28 18:54:53 [DEBUG] [store]    memorystore del: message 3034 was deleted
2020/12/28 18:54:53 [DEBUG] [net]      done putting puback msg on obound
2020/12/28 18:54:53 [DEBUG] [client]   startCommsWorkers c.oboundP msg:  &{0xc0137639c0 <nil>}
2020/12/28 18:54:53 [DEBUG] [net]      obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:53 [DEBUG] [net]      outgoing waiting for an outbound message
2020/12/28 18:54:53 [DEBUG] [pinger]   ping check 0.118052986
2020/12/28 18:54:53 [DEBUG] [net]      startIncoming Received Message
2020/12/28 18:54:53 [DEBUG] [net]      startIncomingComms: got msg on ibound
2020/12/28 18:54:53 [DEBUG] [net]      startIncomingComms: received publish, msgId: 3035
2020/12/28 18:54:53 [DEBUG] [net]      logic waiting for msg on ibound
2020/12/28 18:54:53 [DEBUG] [net]      putting puback msg on obound
2020/12/28 18:54:53 [DEBUG] [store]    memorystore del: message 3035 was deleted
2020/12/28 18:54:53 [DEBUG] [net]      done putting puback msg on obound
2020/12/28 18:54:53 [DEBUG] [client]   startCommsWorkers c.oboundP msg:  &{0xc013763e00 <nil>}
2020/12/28 18:54:53 [DEBUG] [net]      obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:53 [DEBUG] [net]      outgoing waiting for an outbound message
2020/12/28 18:54:54 [DEBUG] [client]   enter Publish
2020/12/28 18:54:54 [DEBUG] [client]   sending publish message, topic: stf-692AFE13-0877-5F58-8B5B-949EEACFAE61/353013085721500
2020/12/28 18:54:54 [DEBUG] [client]   #####Publish  c.obound:  #######
2020/12/28 18:54:54 [DEBUG] [client]   startCommsWorkers c.obound msg:  &{0xc00fe2d140 0xc00fe2d100}
2020/12/28 18:54:54 [DEBUG] [net]      obound msg to write 829
2020/12/28 18:54:54 [DEBUG] [net]      obound wrote msg, id: 829
2020/12/28 18:54:54 [DEBUG] [net]      outgoing waiting for an outbound message
2020/12/28 18:54:54 [DEBUG] [net]      startIncoming Received Message
2020/12/28 18:54:54 [DEBUG] [net]      startIncomingComms: got msg on ibound
2020/12/28 18:54:54 [DEBUG] [store]    memorystore del: message 829 was deleted
2020/12/28 18:54:54 [DEBUG] [net]      startIncomingComms: received puback, id: 829
2020/12/28 18:54:54 [DEBUG] [net]      logic waiting for msg on ibound
2020/12/28 18:54:54 [DEBUG] [net]      startIncoming Received Message
2020/12/28 18:54:54 [DEBUG] [net]      startIncomingComms: got msg on ibound
2020/12/28 18:54:54 [DEBUG] [net]      startIncomingComms: received publish, msgId: 3036
2020/12/28 18:54:54 [DEBUG] [net]      logic waiting for msg on ibound
2020/12/28 18:54:54 [DEBUG] [net]      putting puback msg on obound
2020/12/28 18:54:54 [DEBUG] [store]    memorystore del: message 3036 was deleted
2020/12/28 18:54:54 [DEBUG] [net]      done putting puback msg on obound
2020/12/28 18:54:54 [DEBUG] [client]   startCommsWorkers c.oboundP msg:  &{0xc01123d560 <nil>}
2020/12/28 18:54:54 [DEBUG] [net]      obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:54 [DEBUG] [net]      outgoing waiting for an outbound message
2020/12/28 18:54:54 [DEBUG] [net]      startIncoming Received Message
2020/12/28 18:54:54 [DEBUG] [net]      startIncomingComms: got msg on ibound
2020/12/28 18:54:54 [DEBUG] [net]      startIncomingComms: received publish, msgId: 3037
2020/12/28 18:54:54 [DEBUG] [net]      logic waiting for msg on ibound
2020/12/28 18:54:54 [DEBUG] [net]      putting puback msg on obound
2020/12/28 18:54:54 [DEBUG] [store]    memorystore del: message 3037 was deleted
2020/12/28 18:54:54 [DEBUG] [net]      done putting puback msg on obound
2020/12/28 18:54:54 [DEBUG] [client]   startCommsWorkers c.oboundP msg:  &{0xc00003c320 <nil>}
2020/12/28 18:54:54 [DEBUG] [net]      obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:54 [DEBUG] [net]      outgoing waiting for an outbound message
2020/12/28 18:54:56 [DEBUG] [net]      startIncoming Received Message
2020/12/28 18:54:56 [DEBUG] [net]      startIncomingComms: got msg on ibound
2020/12/28 18:54:56 [DEBUG] [net]      startIncomingComms: received publish, msgId: 3038
2020/12/28 18:54:56 [DEBUG] [net]      logic waiting for msg on ibound
2020/12/28 18:54:56 [DEBUG] [net]      putting puback msg on obound
2020/12/28 18:54:56 [DEBUG] [store]    memorystore del: message 3038 was deleted
2020/12/28 18:54:56 [DEBUG] [net]      done putting puback msg on obound
2020/12/28 18:54:56 [DEBUG] [client]   startCommsWorkers c.oboundP msg:  &{0xc01123d600 <nil>}
2020/12/28 18:54:56 [DEBUG] [net]      obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:56 [DEBUG] [net]      outgoing waiting for an outbound message
2020/12/28 18:54:56 [DEBUG] [net]      startIncoming Received Message
2020/12/28 18:54:56 [DEBUG] [net]      startIncomingComms: got msg on ibound
2020/12/28 18:54:56 [DEBUG] [net]      startIncomingComms: received publish, msgId: 3039
2020/12/28 18:54:56 [DEBUG] [net]      logic waiting for msg on ibound
2020/12/28 18:54:56 [DEBUG] [net]      putting puback msg on obound
2020/12/28 18:54:56 [DEBUG] [store]    memorystore del: message 3039 was deleted
2020/12/28 18:54:56 [DEBUG] [net]      done putting puback msg on obound
2020/12/28 18:54:56 [DEBUG] [client]   startCommsWorkers c.oboundP msg:  &{0xc00567e960 <nil>}
2020/12/28 18:54:56 [DEBUG] [net]      obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:56 [DEBUG] [net]      outgoing waiting for an outbound message
2020/12/28 18:54:56 [DEBUG] [net]      startIncoming Received Message
2020/12/28 18:54:56 [DEBUG] [net]      startIncomingComms: got msg on ibound
2020/12/28 18:54:56 [DEBUG] [net]      startIncomingComms: received publish, msgId: 3040
2020/12/28 18:54:56 [DEBUG] [net]      logic waiting for msg on ibound
2020/12/28 18:54:56 [DEBUG] [net]      putting puback msg on obound
2020/12/28 18:54:56 [DEBUG] [store]    memorystore del: message 3040 was deleted
2020/12/28 18:54:56 [DEBUG] [net]      done putting puback msg on obound
2020/12/28 18:54:56 [DEBUG] [client]   startCommsWorkers c.oboundP msg:  &{0xc00567e980 <nil>}
2020/12/28 18:54:56 [DEBUG] [net]      obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:56 [DEBUG] [net]      outgoing waiting for an outbound message
2020/12/28 18:54:57 [DEBUG] [client]   enter Publish
2020/12/28 18:54:57 [DEBUG] [client]   sending publish message, topic: stf-692AFE13-0877-5F58-8B5B-949EEACFAE61/9C071FFAZ000J6
2020/12/28 18:54:57 [DEBUG] [client]   #####Publish  c.obound:  #######
2020/12/28 18:54:57 [DEBUG] [client]   startCommsWorkers c.obound msg:  &{0xc00fe2d3c0 0xc00fe2d380}
2020/12/28 18:54:57 [DEBUG] [net]      obound msg to write 830
2020/12/28 18:54:57 [DEBUG] [net]      obound wrote msg, id: 830
2020/12/28 18:54:57 [DEBUG] [net]      outgoing waiting for an outbound message
2020/12/28 18:54:57 [DEBUG] [net]      startIncoming Received Message
2020/12/28 18:54:57 [DEBUG] [net]      startIncomingComms: got msg on ibound
2020/12/28 18:54:57 [DEBUG] [store]    memorystore del: message 830 was deleted
2020/12/28 18:54:57 [DEBUG] [net]      startIncomingComms: received puback, id: 830
2020/12/28 18:54:57 [DEBUG] [net]      logic waiting for msg on ibound
2020/12/28 18:54:58 [DEBUG] [net]      startIncoming Received Message
2020/12/28 18:54:58 [DEBUG] [net]      startIncomingComms: got msg on ibound
2020/12/28 18:54:58 [DEBUG] [net]      startIncomingComms: received publish, msgId: 3041
2020/12/28 18:54:58 [DEBUG] [net]      logic waiting for msg on ibound
2020/12/28 18:54:58 [DEBUG] [net]      putting puback msg on obound
2020/12/28 18:54:58 [DEBUG] [store]    memorystore del: message 3041 was deleted
2020/12/28 18:54:58 [DEBUG] [net]      done putting puback msg on obound
2020/12/28 18:54:58 [DEBUG] [client]   startCommsWorkers c.oboundP msg:  &{0xc00003d100 <nil>}
2020/12/28 18:54:58 [DEBUG] [net]      obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:58 [DEBUG] [net]      outgoing waiting for an outbound message
2020/12/28 18:54:58 [DEBUG] [net]      startIncoming Received Message
2020/12/28 18:54:58 [DEBUG] [net]      startIncomingComms: got msg on ibound
2020/12/28 18:54:58 [DEBUG] [net]      startIncomingComms: received publish, msgId: 0
2020/12/28 18:54:58 [DEBUG] [net]      logic waiting for msg on ibound
2020/12/28 18:54:58 [DEBUG] [net]      startIncoming Received Message
2020/12/28 18:54:58 [DEBUG] [net]      startIncomingComms: got msg on ibound
2020/12/28 18:54:58 [DEBUG] [net]      startIncomingComms: received publish, msgId: 3042
2020/12/28 18:54:58 [DEBUG] [net]      logic waiting for msg on ibound
2020/12/28 18:54:58 [DEBUG] [net]      putting puback msg on obound
2020/12/28 18:54:58 [DEBUG] [store]    memorystore del: message 3042 was deleted
2020/12/28 18:54:58 [DEBUG] [net]      done putting puback msg on obound
2020/12/28 18:54:58 [DEBUG] [client]   startCommsWorkers c.oboundP msg:  &{0xc010b92c00 <nil>}
2020/12/28 18:54:58 [DEBUG] [net]      obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:58 [DEBUG] [net]      outgoing waiting for an outbound message
2020/12/28 18:54:58 [DEBUG] [pinger]   ping check 0.183955869
2020/12/28 18:54:59 [DEBUG] [net]      startIncoming Received Message
2020/12/28 18:54:59 [DEBUG] [net]      startIncomingComms: got msg on ibound
2020/12/28 18:54:59 [DEBUG] [net]      startIncomingComms: received publish, msgId: 3043
2020/12/28 18:54:59 [DEBUG] [net]      logic waiting for msg on ibound
2020/12/28 18:54:59 [DEBUG] [net]      putting puback msg on obound
2020/12/28 18:54:59 [DEBUG] [store]    memorystore del: message 3043 was deleted
2020/12/28 18:54:59 [DEBUG] [net]      done putting puback msg on obound
2020/12/28 18:54:59 [DEBUG] [client]   startCommsWorkers c.oboundP msg:  &{0xc00567f100 <nil>}
2020/12/28 18:54:59 [DEBUG] [net]      obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:59 [DEBUG] [net]      outgoing waiting for an outbound message
2020/12/28 18:54:59 [DEBUG] [net]      startIncoming Received Message
2020/12/28 18:54:59 [DEBUG] [net]      startIncomingComms: got msg on ibound
2020/12/28 18:54:59 [DEBUG] [net]      startIncomingComms: received publish, msgId: 3044
2020/12/28 18:54:59 [DEBUG] [net]      logic waiting for msg on ibound
2020/12/28 18:54:59 [DEBUG] [net]      putting puback msg on obound
2020/12/28 18:54:59 [DEBUG] [store]    memorystore del: message 3044 was deleted
2020/12/28 18:54:59 [DEBUG] [net]      done putting puback msg on obound
2020/12/28 18:54:59 [DEBUG] [client]   startCommsWorkers c.oboundP msg:  &{0xc010b92fc0 <nil>}
2020/12/28 18:54:59 [DEBUG] [net]      obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:59 [DEBUG] [net]      outgoing waiting for an outbound message
2020/12/28 18:55:00 [DEBUG] [net]      startIncoming Received Message
2020/12/28 18:55:00 [DEBUG] [net]      startIncomingComms: got msg on ibound
2020/12/28 18:55:00 [DEBUG] [net]      startIncomingComms: received publish, msgId: 3045
2020/12/28 18:55:00 [DEBUG] [net]      logic waiting for msg on ibound
2020/12/28 18:55:00 [DEBUG] [net]      putting puback msg on obound
2020/12/28 18:55:00 [DEBUG] [store]    memorystore del: message 3045 was deleted
2020/12/28 18:55:00 [DEBUG] [net]      done putting puback msg on obound
2020/12/28 18:55:00 [DEBUG] [client]   startCommsWorkers c.oboundP msg:  &{0xc010b931e0 <nil>}
2020/12/28 18:55:00 [DEBUG] [net]      obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:55:00 [DEBUG] [net]      outgoing waiting for an outbound message
2020/12/28 18:55:00 [DEBUG] [net]      startIncoming Received Message
2020/12/28 18:55:00 [DEBUG] [net]      startIncomingComms: got msg on ibound
2020/12/28 18:55:00 [DEBUG] [net]      startIncomingComms: received publish, msgId: 3046
2020/12/28 18:55:00 [DEBUG] [net]      logic waiting for msg on ibound
2020/12/28 18:55:00 [DEBUG] [net]      putting puback msg on obound
2020/12/28 18:55:00 [DEBUG] [store]    memorystore del: message 3046 was deleted
2020/12/28 18:55:00 [DEBUG] [net]      done putting puback msg on obound
2020/12/28 18:55:00 [DEBUG] [client]   startCommsWorkers c.oboundP msg:  &{0xc0004af200 <nil>}
2020/12/28 18:55:00 [DEBUG] [net]      obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:55:00 [DEBUG] [net]      outgoing waiting for an outbound message
2020/12/28 18:55:01 [DEBUG] [net]      startIncoming Received Message
2020/12/28 18:55:01 [DEBUG] [net]      startIncomingComms: got msg on ibound
2020/12/28 18:55:01 [DEBUG] [net]      startIncomingComms: received publish, msgId: 3047
2020/12/28 18:55:01 [DEBUG] [net]      logic waiting for msg on ibound
2020/12/28 18:55:01 [DEBUG] [net]      putting puback msg on obound
2020/12/28 18:55:01 [DEBUG] [store]    memorystore del: message 3047 was deleted
2020/12/28 18:55:01 [DEBUG] [net]      done putting puback msg on obound
2020/12/28 18:55:01 [DEBUG] [client]   startCommsWorkers c.oboundP msg:  &{0xc01123dd80 <nil>}
2020/12/28 18:55:01 [DEBUG] [net]      obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:55:01 [DEBUG] [net]      outgoing waiting for an outbound message
2020/12/28 18:55:01 [DEBUG] [net]      startIncoming Received Message
2020/12/28 18:55:01 [DEBUG] [net]      startIncomingComms: got msg on ibound
2020/12/28 18:55:01 [DEBUG] [net]      startIncomingComms: received publish, msgId: 3048
2020/12/28 18:55:01 [DEBUG] [net]      logic waiting for msg on ibound
2020/12/28 18:55:01 [DEBUG] [net]      startIncoming Received Message
2020/12/28 18:55:01 [DEBUG] [net]      startIncomingComms: got msg on ibound
2020/12/28 18:55:01 [DEBUG] [net]      startIncomingComms: received publish, msgId: 3049
2020/12/28 18:55:01 [DEBUG] [net]      logic waiting for msg on ibound
2020/12/28 18:55:02 [DEBUG] [net]      startIncoming Received Message
2020/12/28 18:55:02 [DEBUG] [net]      startIncomingComms: got msg on ibound
2020/12/28 18:55:02 [DEBUG] [net]      startIncomingComms: received publish, msgId: 3050
2020/12/28 18:55:02 [DEBUG] [net]      logic waiting for msg on ibound
2020/12/28 18:55:02 [DEBUG] [net]      startIncoming Received Message
2020/12/28 18:55:02 [DEBUG] [net]      startIncomingComms: got msg on ibound
2020/12/28 18:55:02 [DEBUG] [net]      startIncomingComms: received publish, msgId: 0
2020/12/28 18:55:02 [DEBUG] [client]   enter Publish
2020/12/28 18:55:02 [DEBUG] [client]   sending publish message, topic: stf-692AFE13-0877-5F58-8B5B-949EEACFAE61/5c922e1d
2020/12/28 18:55:02 [DEBUG] [client]   #####Publish  c.obound:  #######
2020/12/28 18:55:02 [DEBUG] [client]   startCommsWorkers c.obound msg:  &{0xc00c95dc00 0xc00c95dbc0}
2020/12/28 18:55:02 [DEBUG] [net]      obound msg to write 831
2020/12/28 18:55:02 [DEBUG] [net]      obound wrote msg, id: 831
2020/12/28 18:55:02 [DEBUG] [net]      outgoing waiting for an outbound message
2020/12/28 18:55:02 [DEBUG] [net]      startIncoming Received Message
2020/12/28 18:55:03 [DEBUG] [pinger]   ping check 1.872589665
2020/12/28 18:55:08 [DEBUG] [pinger]   ping check 6.87293455
2020/12/28 18:55:13 [DEBUG] [pinger]   ping check 11.900795076
2020/12/28 18:55:18 [DEBUG] [pinger]   ping check 16.873234248
2020/12/28 18:55:23 [DEBUG] [pinger]   ping check 21.90367372
2020/12/28 18:55:28 [DEBUG] [pinger]   ping check 26.87759304
2020/12/28 18:55:33 [DEBUG] [pinger]   ping check 31.871691928
2020/12/28 18:55:38 [DEBUG] [pinger]   ping check 36.885652448
2020/12/28 18:55:44 [DEBUG] [pinger]   ping check 41.946738907
2020/12/28 18:55:48 [DEBUG] [pinger]   ping check 46.87123913
2020/12/28 18:55:53 [DEBUG] [pinger]   ping check 51.876050751
2020/12/28 18:55:58 [DEBUG] [pinger]   ping check 56.872241076
2020/12/28 18:56:03 [DEBUG] [pinger]   ping check 61.871172425
2020/12/28 18:56:08 [DEBUG] [pinger]   ping check 66.875206823
2020/12/28 18:56:13 [DEBUG] [pinger]   ping check 71.874094389
2020/12/28 18:56:18 [DEBUG] [pinger]   ping check 76.871257706
2020/12/28 18:56:23 [DEBUG] [pinger]   ping check 81.887289891
2020/12/28 18:56:28 [DEBUG] [pinger]   ping check 86.88227673
2020/12/28 18:56:33 [DEBUG] [pinger]   ping check 91.872222389
2020/12/28 18:56:38 [DEBUG] [pinger]   ping check 96.880015293
2020/12/28 18:56:43 [DEBUG] [pinger]   ping check 101.879905674
2020/12/28 18:56:49 [DEBUG] [pinger]   ping check 106.950685648
2020/12/28 18:56:53 [DEBUG] [pinger]   ping check 111.887278252
2020/12/28 18:56:58 [DEBUG] [pinger]   ping check 116.879197592
2020/12/28 18:57:03 [DEBUG] [pinger]   ping check 121.890659963
2020/12/28 18:57:08 [DEBUG] [pinger]   ping check 126.882503995
2020/12/28 18:57:13 [DEBUG] [pinger]   ping check 131.888095769
2020/12/28 18:57:18 [DEBUG] [pinger]   ping check 136.894459158
2020/12/28 18:57:23 [DEBUG] [pinger]   ping check 141.893740683
2020/12/28 18:57:28 [DEBUG] [pinger]   ping check 146.895498901
2020/12/28 18:57:33 [DEBUG] [pinger]   ping check 151.896772964
2020/12/28 18:57:38 [DEBUG] [pinger]   ping check 156.917567966
2020/12/28 18:57:43 [DEBUG] [pinger]   ping check 161.872913588
2020/12/28 18:57:48 [DEBUG] [pinger]   ping check 166.894009244
2020/12/28 18:57:53 [DEBUG] [pinger]   ping check 171.924919796
2020/12/28 18:57:58 [DEBUG] [pinger]   ping check 176.876066261
2020/12/28 18:58:03 [DEBUG] [pinger]   ping check 181.871120643
2020/12/28 18:58:08 [DEBUG] [pinger]   ping check 186.916778914
2020/12/28 18:58:13 [DEBUG] [pinger]   ping check 191.871151304
2020/12/28 18:58:18 [DEBUG] [pinger]   ping check 196.894813459
2020/12/28 18:58:23 [DEBUG] [pinger]   ping check 201.884660824
2020/12/28 18:58:28 [DEBUG] [pinger]   ping check 206.881708149
2020/12/28 18:58:34 [DEBUG] [pinger]   ping check 211.946752845
2020/12/28 18:58:38 [DEBUG] [pinger]   ping check 216.894292691
2020/12/28 18:58:43 [DEBUG] [pinger]   ping check 221.886063422
2020/12/28 18:58:48 [DEBUG] [pinger]   ping check 226.872439777
2020/12/28 18:58:53 [DEBUG] [pinger]   ping check 231.903365241
2020/12/28 18:58:58 [DEBUG] [pinger]   ping check 236.871690075
2020/12/28 18:59:03 [DEBUG] [pinger]   ping check 241.872224307
2020/12/28 18:59:08 [DEBUG] [pinger]   ping check 246.872293608
2020/12/28 18:59:13 [DEBUG] [pinger]   ping check 251.885761097
2020/12/28 18:59:18 [DEBUG] [pinger]   ping check 256.872677532
2020/12/28 18:59:23 [DEBUG] [pinger]   ping check 261.871915896
2020/12/28 18:59:29 [DEBUG] [pinger]   ping check 266.94323031
2020/12/28 18:59:33 [DEBUG] [pinger]   ping check 271.871173669
2020/12/28 18:59:38 [DEBUG] [pinger]   ping check 276.874400984
2020/12/28 18:59:43 [DEBUG] [pinger]   ping check 281.934717686
2020/12/28 18:59:48 [DEBUG] [pinger]   ping check 286.885194154
2020/12/28 18:59:53 [DEBUG] [pinger]   ping check 291.88239686
2020/12/28 18:59:58 [DEBUG] [pinger]   ping check 296.887537738
2020/12/28 19:00:03 [DEBUG] [pinger]   ping check 301.877492839
2020/12/28 19:00:08 [DEBUG] [pinger]   ping check 306.881997648
2020/12/28 19:00:13 [DEBUG] [pinger]   ping check 311.886916863
2020/12/28 19:00:18 [DEBUG] [pinger]   ping check 316.881473751
2020/12/28 19:00:23 [DEBUG] [pinger]   ping check 321.871081772
2020/12/28 19:00:28 [DEBUG] [pinger]   ping check 326.873282093
2020/12/28 19:00:33 [DEBUG] [pinger]   ping check 331.873796386
2020/12/28 19:00:38 [DEBUG] [pinger]   ping check 336.873702743
2020/12/28 19:00:43 [DEBUG] [pinger]   ping check 341.898005436
2020/12/28 19:00:48 [DEBUG] [pinger]   ping check 346.890559087
2020/12/28 19:00:53 [DEBUG] [pinger]   ping check 351.871989069
2020/12/28 19:00:58 [DEBUG] [pinger]   ping check 356.874558575
2020/12/28 19:01:03 [DEBUG] [pinger]   ping check 361.874361263
2020/12/28 19:01:08 [DEBUG] [pinger]   ping check 366.892902613
2020/12/28 19:01:13 [DEBUG] [pinger]   ping check 371.892875777
2020/12/28 19:01:18 [DEBUG] [pinger]   ping check 376.895517155
2020/12/28 19:01:23 [DEBUG] [pinger]   ping check 381.893908065
2020/12/28 19:01:28 [DEBUG] [pinger]   ping check 386.908873572
2020/12/28 19:01:33 [DEBUG] [pinger]   ping check 391.878903646
2020/12/28 19:01:38 [DEBUG] [pinger]   ping check 396.871251185
2020/12/28 19:01:44 [DEBUG] [pinger]   ping check 401.995463532
2020/12/28 19:01:48 [DEBUG] [pinger]   ping check 406.942938848
2020/12/28 19:01:53 [DEBUG] [pinger]   ping check 411.889605482
2020/12/28 19:01:58 [DEBUG] [pinger]   ping check 416.874886907
2020/12/28 19:02:03 [DEBUG] [pinger]   ping check 421.890605726
2020/12/28 19:02:08 [DEBUG] [pinger]   ping check 426.871226776
2020/12/28 19:02:13 [DEBUG] [pinger]   ping check 431.877273847
2020/12/28 19:02:18 2020/12/28 19:02:18 Error reading: EOF
2020/12/28 19:02:18 2020/12/28 19:02:18 Agent Error reading: EOF
2020/12/28 19:02:18 2020/12/28 19:02:18 read finished for 9C071FFAZ000J6
2020/12/28 19:02:18 2020/12/28 19:02:18 scrcpy is dead on device 9C071FFAZ000J6
2020/12/28 19:02:18 2020/12/28 19:02:18 os: process already finished
2020/12/28 19:02:18 2020/12/28 19:02:18 Starting making scrcpy server for device %S 9C071FFAZ000J6
2020/12/28 19:02:18 2020/12/28 19:02:18 9C071FFAZ000J6 process kill err: os: process already finished
2020/12/28 19:02:18 2020/12/28 19:02:18 push server.jar fail: exit status 1
2020/12/28 19:02:18 [DEBUG] [pinger]   ping check 436.873068092
2020/12/28 19:02:19 2020/12/28 19:02:19 Starting making scrcpy server for device %S 9C071FFAZ000J6
2020/12/28 19:02:19 2020/12/28 19:02:19 Error reading: read tcp 127.0.0.1:49997->127.0.0.1:50010: use of closed network connection
2020/12/28 19:02:19 2020/12/28 19:02:19 push server.jar fail: exit status 1
2020/12/28 19:02:20 2020/12/28 19:02:20 Error reading: read tcp 127.0.0.1:49997->127.0.0.1:50010: use of closed network connection
2020/12/28 19:02:20 2020/12/28 19:02:20 Starting making scrcpy server for device %S 9C071FFAZ000J6
2020/12/28 19:02:20 2020/12/28 19:02:20 push server.jar fail: exit status 1
2020/12/28 19:02:20 2020/12/28 19:02:20 shut down everything for scrcpy on 9C071FFAZ000J6
2020/12/28 19:02:20 2020/12/28 19:02:20 os: process already finished
2020/12/28 19:02:20 2020/12/28 19:02:20 shut down everything for agent server on 9C071FFAZ000J6
2020/12/28 19:02:20 2020/12/28 19:02:20 Control for 9C071FFAZ000J6 stoped
2020/12/28 19:02:20 2020/12/28 19:02:20 9C071FFAZ000J6 process kill err: os: process already finished
2020/12/28 19:02:21 [DEBUG] [client]   enter Unsubscribe
2020/12/28 19:02:21 [DEBUG] [client]   sending unsubscribe message, topics: [agent-692AFE13-0877-5F58-8B5B-949EEACFAE61/9C071FFAZ000J6]
2020/12/28 19:02:21 [DEBUG] [client]   ####Unsubscribe  oboundP receive a message #####
2020/12/28 19:02:21 [DEBUG] [client]   exit Unsubscribe
2020/12/28 19:02:21 [DEBUG] [client]   startCommsWorkers c.oboundP msg:  &{0xc010014d20 0xc00d176a80}
2020/12/28 19:02:21 [DEBUG] [net]      obound priority msg to write, type *packets.UnsubscribePacket
2020/12/28 19:02:21 [DEBUG] [net]      outgoing waiting for an outbound message
2020/12/28 19:02:21 2020/12/28 19:02:21 Screening finished for 9C071FFAZ000J6
2020/12/28 19:02:21 2020/12/28 19:02:21 finish initiating server for  9C071FFAZ000J6
2020/12/28 19:02:23 [DEBUG] [pinger]   ping check 2.5371631629999998
2020/12/28 19:02:28 [DEBUG] [pinger]   ping check 7.534591538
2020/12/28 19:02:33 [DEBUG] [pinger]   ping check 12.535742837
2020/12/28 19:02:37 2020/12/28 19:02:37 finish initiating server for  9C071FFAZ000J6
2020/12/28 19:02:38 [DEBUG] [pinger]   ping check 17.548698441
2020/12/28 19:02:43 [DEBUG] [pinger]   ping check 22.560391177
2020/12/28 19:02:48 [DEBUG] [pinger]   ping check 27.536675739
2020/12/28 19:02:53 [DEBUG] [pinger]   ping check 32.561630977
2020/12/28 19:02:58 [DEBUG] [pinger]   ping check 37.536556433
2020/12/28 19:03:03 [DEBUG] [pinger]   ping check 42.574990324
2020/12/28 19:03:08 [DEBUG] [pinger]   ping check 47.541282015
2020/12/28 19:03:13 [DEBUG] [pinger]   ping check 52.5584123
2020/12/28 19:03:18 [DEBUG] [pinger]   ping check 57.535337644
2020/12/28 19:03:23 [DEBUG] [pinger]   ping check 62.559060043
2020/12/28 19:03:28 [DEBUG] [pinger]   ping check 67.561595564
2020/12/28 19:03:33 [DEBUG] [pinger]   ping check 72.534744877
2020/12/28 19:03:37 [DEBUG] [client]   enter Publish
2020/12/28 19:03:37 [DEBUG] [client]   sending publish message, topic: stf-692AFE13-0877-5F58-8B5B-949EEACFAE61/9C071FFAZ000J6
2020/12/28 19:03:37 [DEBUG] [client]   #####Publish  c.obound:  #######
2020/12/28 19:03:37 [DEBUG] [client]   startCommsWorkers c.obound msg:  &{0xc00db5bb40 0xc00db5bb00}
2020/12/28 19:03:37 [DEBUG] [net]      obound msg to write 833
2020/12/28 19:03:37 [DEBUG] [net]      obound wrote msg, id: 833
2020/12/28 19:03:37 [DEBUG] [net]      outgoing waiting for an outbound message
2020/12/28 19:03:38 [DEBUG] [pinger]   ping check 1.385413411
2020/12/28 19:03:43 [DEBUG] [pinger]   ping check 6.433137042
2020/12/28 19:03:48 [DEBUG] [pinger]   ping check 11.381266375
2020/12/28 19:03:53 [DEBUG] [pinger]   ping check 16.41252487
2020/12/28 19:03:58 [DEBUG] [pinger]   ping check 21.378576052
2020/12/28 19:04:03 [DEBUG] [pinger]   ping check 26.378504355
2020/12/28 19:04:08 [DEBUG] [pinger]   ping check 31.381645796
2020/12/28 19:04:13 [DEBUG] [pinger]   ping check 36.395564331
2020/12/28 19:04:18 [DEBUG] [pinger]   ping check 41.381531796
2020/12/28 19:04:23 [DEBUG] [pinger]   ping check 46.402866521
2020/12/28 19:04:28 [DEBUG] [pinger]   ping check 51.41327018
2020/12/28 19:04:33 [DEBUG] [pinger]   ping check 56.378523871
2020/12/28 19:04:38 [DEBUG] [pinger]   ping check 61.381385266
2020/12/28 19:04:43 [DEBUG] [pinger]   ping check 66.386516631
2020/12/28 19:04:48 [DEBUG] [pinger]   ping check 71.421782476
2020/12/28 19:04:54 [DEBUG] [pinger]   ping check 76.466843257
2020/12/28 19:04:58 [DEBUG] [pinger]   ping check 81.378573708
2020/12/28 19:05:03 [DEBUG] [pinger]   ping check 86.386321059
2020/12/28 19:05:03 [DEBUG] [pinger]   keepalive sending ping
2020/12/28 19:05:08 [DEBUG] [pinger]   ping check 5.02801415
2020/12/28 19:05:08 2020/12/28 19:05:08 ping check Intercept
2020/12/28 19:05:14 2020/12/28 19:05:14 ping check Intercept
2020/12/28 19:05:14 [DEBUG] [pinger]   ping check 10.07152941
2020/12/28 19:05:18 2020/12/28 19:05:18 ping check Intercept
2020/12/28 19:05:18 [DEBUG] [pinger]   ping check 15.062565754
2020/12/28 19:05:23 2020/12/28 19:05:23 ping check Intercept
2020/12/28 19:05:23 [DEBUG] [pinger]   ping check 19.99413201
2020/12/28 19:05:28 2020/12/28 19:05:28 ping check Intercept
2020/12/28 19:05:28 [DEBUG] [pinger]   ping check 25.019997198
2020/12/28 19:05:34 2020/12/28 19:05:34 ping check Intercept
2020/12/28 19:05:34 [DEBUG] [pinger]   ping check 30.067929456
2020/12/28 19:05:38 [DEBUG] [pinger]   ping check 34.992124266
2020/12/28 19:05:38 2020/12/28 19:05:38 ping check Intercept
2020/12/28 19:05:43 2020/12/28 19:05:43 ping check Intercept
2020/12/28 19:05:43 [DEBUG] [pinger]   ping check 40.009211112
2020/12/28 19:05:49 2020/12/28 19:05:49 ping check Intercept
2020/12/28 19:05:49 [DEBUG] [pinger]   ping check 45.068973113
2020/12/28 19:05:53 2020/12/28 19:05:53 ping check Intercept
2020/12/28 19:05:53 [DEBUG] [pinger]   ping check 50.019180143
2020/12/28 19:05:58 [DEBUG] [pinger]   ping check 54.993858575
2020/12/28 19:05:58 2020/12/28 19:05:58 ping check Intercept
2020/12/28 19:06:03 2020/12/28 19:06:03 ping check Intercept
2020/12/28 19:06:03 [DEBUG] [pinger]   ping check 60.028736356
2020/12/28 19:06:03 [CRIT] [pinger]   pingresp not received, disconnecting
2020/12/28 19:06:03 [DEBUG] [client]   internalConnLost called
2020/12/28 19:06:03 [DEBUG] [client]   stopCommsWorkers called
2020/12/28 19:06:03 [DEBUG] [client]   startCommsWorkers output redirector finnished
2020/12/28 19:06:03 [DEBUG] [client]   ### startCommsWorkers #####
2020/12/28 19:06:03 [DEBUG] [net]      outgoing waiting for an outbound message
2020/12/28 19:06:03 [DEBUG] [net]      outgoing waiting for an outbound message
2020/12/28 19:06:03 [DEBUG] [pinger]   #### keepalive c.workers.Done ####
2020/12/28 19:06:03 [DEBUG] [client]   internalConnLost waiting on workers
2020/12/28 19:06:03 [DEBUG] [client]   stopCommsWorkers waiting for workers

@MattBrittan
Copy link
Contributor

Thanks - unfortunately I'm not going to have time to look at this in detail before heading away. It looks like your issue is here:

2020/12/28 18:55:02 [DEBUG] [net]      logic waiting for msg on ibound
2020/12/28 18:55:02 [DEBUG] [net]      startIncoming Received Message
2020/12/28 18:55:02 [DEBUG] [net]      startIncomingComms: got msg on ibound
2020/12/28 18:55:02 [DEBUG] [net]      startIncomingComms: received publish, msgId: 0
2020/12/28 18:55:02 [DEBUG] [client]   enter Publish
2020/12/28 18:55:02 [DEBUG] [client]   sending publish message, topic: stf-692AFE13-0877-5F58-8B5B-949EEACFAE61/5c922e1d
2020/12/28 18:55:02 [DEBUG] [client]   #####Publish  c.obound:  #######

The fact that logic waiting for msg on ibound is not logged again indicates that output <- incomingComms{incomingPub: m} is blocking. This would generally happen when matchAndDispatch is blocked (i.e. by the handler). I would suggest un-comenting the logging in matchAndDispatch and identifying where it is blocking.

I am guessing that you are triggering a Publish based on an incoming message. This should be fine if the handler is in a go routine but will cause a deadlock if not (your log is what I would expect to see in that case),

cant give you a demo of this.
Are you able to share source? (I'm happy to check a private repo as long as its not too convoluted).

@MattBrittan
Copy link
Contributor

Sorry for not reviewing this again sooner. I believe that my previous analysis stands (a handler in your code is probably blocking). I have updated the documentation (in @master) to clarify this. Please try calling SetOrderMatters(false) on your ClientOptions - doing this will mean that the handlers will be called in a goroutine avoiding this kind of issue. Note that just having SetOrderMatters(true) does not guarantee in order delivery of messages (your broker would also need to be configured for this) so in most cases SetOrderMatters(false) is the best option.

@Suparerk8866
Copy link

ข้ามไปที่เนื้อหา
คราส
/
paho.mqtt.golang
รหัส
ประเด็น
12
ดึงคำขอ
5
การดำเนินการ
โครงการ
วิกิ
ความปลอดภัย
ข้อมูลเชิงลึก
ข้ามไปที่ด้านล่าง
ไคลเอนต์ mqtt ถูกแฮงเอาท์ dead โดยล็อคตาย # 473
เปิด
yunfuyiren เปิดประเด็นนี้ on 24 Dec 2020 · 8 ความคิดเห็น
ความคิดเห็น
@yunfuyiren Yunfuyiren แสดงความคิดเห็น on 24 Dec 2020 •
แก้ไข 2 ครั้ง
สวัสดีพวก, ฉันใช้ sdk ไคลเอนต์นี้ตามเวอร์ชัน paho 1.3.0 เวอร์ชันโบรกเกอร์คือ mosquitto 2.0.0

นี่คือรหัสลูกค้าของฉัน

mosquittoClient := &MosquittoClient{
client: nil,
Topic: Topic,
QoS: 0,
}
userName, passWord, _ := getMqttUserNameAndPassword()
opts := mqtt.NewClientOptions().SetClientID(id).AddBroker(PROTOCAL + "://" + MQTTHOST) //.SetTLSConfig(tlsconfig)
opts.SetKeepAlive(60 * time.Second)
opts.SetWill(Topic, "the pub device has dropped off "+id, 1, true)
opts.SetAutoReconnect(true)
opts.SetCleanSession(true)
opts.SetOnConnectHandler(func(client mqtt.Client) {
log.Info("client has been connect success ")
client.Subscribe(channel, mosquittoClient.QoS, mosquittoClient.handlerFun)
log.Info("client reconnect channel: ", channel)
})
opts.SetConnectionLostHandler(func(client mqtt.Client, err error) {
log.Error("SetConnectionLostHandler has been triggered : ", err.Error())
})
opts.SetUsername(userName)
opts.SetPassword(passWord)
opts.SetDefaultPublishHandler(func(client mqtt.Client, message mqtt.Message) {
log.Info("Topic: %s\n", message.Topic())
log.Info("MSG: %s\n", message.Payload())
})
c := mqtt.NewClient(opts)
mosquittoClient.client = c
if token := c.Connect(); token.Wait() && token.Error() != nil {
//tea add alert
log.Error("mqtt connect failed: ", token.Error().Error())
go func(client mqtt.Client) {
for {
time.Sleep(10 * time.Second)
if token = client.Connect(); token.Wait() && token.Error() != nil {
continue
} else {
log.Info("Initial Reconnect to MQTT successed ")
break
}
}
}(c)
}
return mosquittoClient
แต่หลังจากนั้นไม่นานการเชื่อมต่อของ mqtt จะขาดหายไปโดยไม่มีบันทึกของฟังก์ชัน 'SetConnectionLostHandler' ฉันตรวจสอบบันทึกการแก้ไขข้อบกพร่อง
บันทึกคือ:
2020/12/20 21:08:26 [CRIT] [pinger] ไม่ได้รับ
pingresp กำลังตัดการเชื่อมต่อ2020/12/20 21:08:26 [DEBUG] [ไคลเอนต์] internalConnLost เรียกว่า
2020/12/20 21:08 : 26 [แก้ปัญหา] [ไคลเอนต์] stopCommsWorkers เรียกว่า
2020/12/20 21:08:26 [DEBUG] [ไคลเอนต์] ตัวเปลี่ยนเส้นทางเอาต์พุต
startCommsWorkers สิ้นสุด 2020/12/20 21:08:26 [DEBUG] [net] ขาออกกำลังรอ ข้อความขาออก
2020/12/20 21:08:26 [DEBUG] [net] ขา
ออกกำลังรอข้อความขาออก2020/12/20 21:08:26 [แก้ปัญหา] [ลูกค้า] internalConnLost รอคนงาน
2020/12/20 21:08:26 [แก้ปัญหา] [ลูกค้า] stopCommsWorkers กำลังรอคนงาน

ร่างกายใดช่วยฉันได้บ้างว่าการหยุดชะงักเกิดขึ้นได้อย่างไรและจะแก้ไขได้อย่างไร @MattBrittanทำตามคำแนะนำของคุณใน# 453ฉันแจ้งปัญหาใหม่และขอความช่วยเหลือจากคุณ

@MattBrittan MattBrittan แสดงความคิดเห็น on 24 Dec 2020 •
ฉันถือว่ารหัสที่คุณเผยแพร่นั้นเชื่อมต่อสำเร็จแล้ว? หากการเชื่อมต่อเริ่มต้นล้มเหลวฉันเชื่อว่าคุณอาจมีปัญหา (ความพยายามใด ๆ ที่จะใช้ไคลเอนต์ก่อนการเชื่อมต่อจะทำให้เกิดข้อผิดพลาดน่าจะดีกว่าที่จะใช้ฟังก์ชัน ConnectRetry ในตัว) นอกเหนือจากที่ฉันไม่เห็นปัญหาใด ๆ กับรหัสที่ให้มา

อย่างไรก็ตามฉันคาดเดาว่าคุณกำลังเผยแพร่ / สมัครรับข้อมูล ณ จุดใดจุดหนึ่ง? โปรดแสดงรหัสนั้น (รหัสที่ใช้งานได้จะดีที่สุด) และบันทึกอื่น ๆ (กิจกรรมก่อน "ไม่ได้รับ pingresp" นั่นคือปัญหาสาเหตุน่าจะเกิดก่อนหน้านี้ในบันทึก) ปัญหานี้มักเกิดจากฟังก์ชันตัวจัดการที่บล็อก (ไม่ส่งคืน) ภายในรหัสผู้ใช้ (ไม่ได้บอกว่าเป็นกรณีนี้ขณะนี้มีข้อมูลไม่เพียงพอที่จะให้วิเคราะห์ได้มาก)

@bartmeuris bartmeuris แสดงความคิดเห็น on 25 Dec 2020
มีปัญหาที่คล้ายกันไม่มีเวลาแก้ไขข้อบกพร่องเพิ่มเติม แต่:

ดูเหมือนว่าฉันจะไม่ได้รับข้อมูลใด ๆ จากการสมัครสมาชิก แต่ฉันได้รับบันทึกการดีบักนี้จากไคลเอนต์ mqtt

INFO[0000] [net] startIncoming Received Message
INFO[0000] [net] startIncoming Received Message
INFO[0000] [net] startIncomingComms: got msg on ibound
INFO[0000] [net] startIncomingComms: received publish, msgId: 0
Then my message that I publish fails after a while with a publish was broken by timeout error. Also the internal ping fails and hangs from that point on, and the disconnect hangs:

INFO[0050] [pinger] pingresp not received, disconnecting
INFO[0050] [client] internalConnLost called
INFO[0050] [client] stopCommsWorkers called
INFO[0050] [client] internalConnLost waiting on workers
INFO[0050] [client] startCommsWorkers output redirector finnished
INFO[0050] [net] outgoing waiting for an outbound message
INFO[0050] [net] outgoing waiting for an outbound message
INFO[0050] [client] stopCommsWorkers waiting for workers
Also, disconnecting the MQTT client also hangs. I get the same behavior when I terminate my application with Ctrl-C, where in the signal handler I call a Disconnect():

INFO[0000] Terminating mqtt connection... timeout=10s
INFO[0000] [client] disconnecting
INFO[0000] [client] calling WaitTimeout
INFO[0000] [net] obound priority msg to write, type *packets.DisconnectPacket
INFO[0000] [net] outbound wrote disconnect, closing connection
INFO[0000] [client] WaitTimeout done
INFO[0000] [client] stopCommsWorkers called
INFO[0000] [net] outgoing waiting for an outbound message
INFO[0000] [net] outgoing waiting for an outbound message
INFO[0000] [net] outgoing waiting for an outbound message
INFO[0000] [client] stopCommsWorkers waiting for workers
INFO[0000] [client] startCommsWorkers output redirector finnished
INFO[0000] [pinger] keepalive stopped
When I switch back to 1.2.0, it all just works again.

@MattBrittan MattBrittan commented on 26 Dec 2020 •
@bartmeuris - please raise this as a separate issue (without additional information its not possible to ascertain if these have the same cause so its simpler to assume they differ).

Given that your code was working with 1.2.0 its most likely your issue is due to the change mentioned in the release notes:

Note that this commit changes internal message channels from buffered to unbuffered and may impact users who publish from within a message handler (the documentation has been updated to highlight the issue; running potentially blocking operations within a message handle has always been problematic).

The section of the logs you included (from Ctrl-C press) gives some indications this may be the case (there is no matchAndDispatch exiting). Unfortunately you have not included enough of the log to draw any further conclusions (pingresp not received, disconnecting is a symptom; the cause will most likely be earlier in the logs).

@bartmeuris bartmeuris mentioned this issue on 26 Dec 2020
Deadlocks in library when not wrapping callbacks in goroutine #474
Closed
@yunfuyiren yunfuyiren commented on 30 Dec 2020 •
Firstly, I want to say thank you to @bartmeuris @MattBrittan , I've seen your dialogue in #474 ,and learned a lot about the blocking of the client channel. And I think it's also maybe the channel buffering makes my client hang out. here is my code of subscription :

z.MqttClient.SubMsgWithTopicAndQoS(func(client mqtt.Client, message mqtt.Message) {
go handleFunc(msg)
}, channel, 1)
this client just a subscriber to sub a topic named by channel. And my handler function is a go routine function.
here is my scenario which is not used in a local area network:
the broker is a server deployed in America, and pub client is at the same city with broker while the sub one is in Africa. And messages
which sent to sub client are just a mass of touch operation orders and can not be out of order. so I have to set the 'SetOrderMatters' to default 'true' to keep messages in order. but i am not sure if it is the long distance and bad internet of the sub client which makes the messages are not reachable and when the client is hanging out, i try to use tcpdump to grab packages to check the heartbeats but they are not sent any more which are like this in a healthy state:
image

I look for reason by review the code of mqtt client and find its been block here :
image
i've added some debug log local and only this "c.workers.Done()" is not run while the other two c.workers.Done() can be run normally.
so I was wandering how this happens and how to recurrent it in local network.

Secondly, as my scenario needs to be in ordered. so i support the 'SetOrderMatters' default value is need to be true. appreciate for your suggestion @MattBrittan

@MattBrittan MattBrittan commented on 31 Dec 2020
z.MqttClient.SubMsgWithTopicAndQoS(func(client mqtt.Client, message mqtt.Message) {

Can you please show your wrapper function (note that its very difficult to diagnose these issues without a full example and/or full logs). As you appear to be calling the handler in a go routine the comments regarding deadlocks should not apply. Note that the main impact of calling SetOrderMatters(false) is to avoid the use of go routines thus ensuring that messages are processed in order (the ACK is only send when the handler exits) so, as it stands, your code may end up processing multiple messages simultaneously. I would also note that none of this actually guarantees in-order delivery; that will come down to your broker configuration (I generally accept the messages in any order and reassemble before processing because this is significantly faster over dubious network links).

i've added some debug log local and only this "c.workers.Done()" is not run while the other two c.workers.Done() can be run normally. so I was wandering how this happens and how to recurrent it in local network

So this just means that matchAndDispatch is not exiting (which I had assumed was the case based on the snippet of logs you provided). There was a separate issue which has now been fixed (released v1.3.1 yesterday); I think your problem may be different but definitely worth trying that fix (I was unable to duplicate the issue myself but could see how it could potentially happen).

In order to look into this further I'm really going to need full logs (a minimal example would be even better). It definitely looks like there is a deadlock somewhere but I don't currently have enough information to investigate. Note that I'm heading into the mountains tomorrow for a couple of weeks and will have no internet access.

@yunfuyiren yunfuyiren commented on 31 Dec 2020
@MattBrittan hi, Matt, thank you for your answer, I will try the new version client and here is my whole logs of the dead block. As I said my programs with mqtt now are running at different countries (sub client is in A country, and pub client / broker in another), the blocking scenario will appear coincidentally while running on my local laptop, the connection and message passing run normally, so i only can provide you the log and cant give you a demo of this.

2020/12/28 18:54:04 [DEBUG] [net] startIncomingComms: received publish, msgId: 3001
2020/12/28 18:54:04 [DEBUG] [net] logic waiting for msg on ibound
2020/12/28 18:54:04 [DEBUG] [net] putting puback msg on obound
2020/12/28 18:54:04 [DEBUG] [store] memorystore del: message 3001 was deleted
2020/12/28 18:54:04 [DEBUG] [net] done putting puback msg on obound
2020/12/28 18:54:04 [DEBUG] [client] startCommsWorkers c.oboundP msg: &{0xc010b92080 }
2020/12/28 18:54:04 [DEBUG] [net] obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:04 [DEBUG] [net] outgoing waiting for an outbound message
2020/12/28 18:54:04 [DEBUG] [client] enter Publish
2020/12/28 18:54:04 [DEBUG] [client] sending publish message, topic: stf-692AFE13-0877-5F58-8B5B-949EEACFAE61/353013085721500
2020/12/28 18:54:04 [DEBUG] [client] #####Publish c.obound: #######
2020/12/28 18:54:04 [DEBUG] [client] startCommsWorkers c.obound msg: &{0xc00fdb32c0 0xc00fdb3280}
2020/12/28 18:54:04 [DEBUG] [net] obound msg to write 818
2020/12/28 18:54:04 [DEBUG] [net] obound wrote msg, id: 818
2020/12/28 18:54:04 [DEBUG] [net] outgoing waiting for an outbound message
2020/12/28 18:54:04 [DEBUG] [net] startIncoming Received Message
2020/12/28 18:54:04 [DEBUG] [net] startIncomingComms: got msg on ibound
2020/12/28 18:54:04 [DEBUG] [store] memorystore del: message 818 was deleted
2020/12/28 18:54:04 [DEBUG] [net] startIncomingComms: received puback, id: 818
2020/12/28 18:54:04 [DEBUG] [net] logic waiting for msg on ibound
2020/12/28 18:54:04 [DEBUG] [net] startIncoming Received Message
2020/12/28 18:54:04 [DEBUG] [net] startIncomingComms: got msg on ibound
2020/12/28 18:54:04 [DEBUG] [net] startIncomingComms: received publish, msgId: 3002
2020/12/28 18:54:04 [DEBUG] [net] logic waiting for msg on ibound
2020/12/28 18:54:04 [DEBUG] [net] putting puback msg on obound
2020/12/28 18:54:04 [DEBUG] [store] memorystore del: message 3002 was deleted
2020/12/28 18:54:04 [DEBUG] [net] done putting puback msg on obound
2020/12/28 18:54:04 [DEBUG] [client] startCommsWorkers c.oboundP msg: &{0xc00062c280 }
2020/12/28 18:54:04 [DEBUG] [net] obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:04 [DEBUG] [net] outgoing waiting for an outbound message
2020/12/28 18:54:04 [DEBUG] [net] startIncoming Received Message
2020/12/28 18:54:04 [DEBUG] [net] startIncomingComms: got msg on ibound
2020/12/28 18:54:04 [DEBUG] [net] startIncomingComms: received publish, msgId: 3003
2020/12/28 18:54:04 [DEBUG] [net] logic waiting for msg on ibound
2020/12/28 18:54:04 [DEBUG] [net] putting puback msg on obound
2020/12/28 18:54:04 [DEBUG] [store] memorystore del: message 3003 was deleted
2020/12/28 18:54:04 [DEBUG] [net] done putting puback msg on obound
2020/12/28 18:54:04 [DEBUG] [client] startCommsWorkers c.oboundP msg: &{0xc000491540 }
2020/12/28 18:54:04 [DEBUG] [net] obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:04 [DEBUG] [net] outgoing waiting for an outbound message
2020/12/28 18:54:06 [DEBUG] [net] startIncoming Received Message
2020/12/28 18:54:06 [DEBUG] [net] startIncomingComms: got msg on ibound
2020/12/28 18:54:06 [DEBUG] [net] startIncomingComms: received publish, msgId: 3004
2020/12/28 18:54:06 [DEBUG] [net] logic waiting for msg on ibound
2020/12/28 18:54:06 [DEBUG] [net] putting puback msg on obound
2020/12/28 18:54:06 [DEBUG] [store] memorystore del: message 3004 was deleted
2020/12/28 18:54:06 [DEBUG] [net] done putting puback msg on obound
2020/12/28 18:54:06 [DEBUG] [client] startCommsWorkers c.oboundP msg: &{0xc00062c680 }
2020/12/28 18:54:06 [DEBUG] [net] obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:06 [DEBUG] [net] outgoing waiting for an outbound message
2020/12/28 18:54:06 [DEBUG] [net] startIncoming Received Message
2020/12/28 18:54:06 [DEBUG] [net] startIncomingComms: got msg on ibound
2020/12/28 18:54:06 [DEBUG] [net] startIncomingComms: received publish, msgId: 3005
2020/12/28 18:54:06 [DEBUG] [net] logic waiting for msg on ibound
2020/12/28 18:54:06 [DEBUG] [net] putting puback msg on obound
2020/12/28 18:54:06 [DEBUG] [store] memorystore del: message 3005 was deleted
2020/12/28 18:54:06 [DEBUG] [net] done putting puback msg on obound
2020/12/28 18:54:06 [DEBUG] [client] startCommsWorkers c.oboundP msg: &{0xc00062c9e0 }
2020/12/28 18:54:06 [DEBUG] [net] obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:06 [DEBUG] [net] outgoing waiting for an outbound message
2020/12/28 18:54:06 [DEBUG] [net] startIncoming Received Message
2020/12/28 18:54:06 [DEBUG] [net] startIncomingComms: got msg on ibound
2020/12/28 18:54:06 [DEBUG] [net] startIncomingComms: received publish, msgId: 3006
2020/12/28 18:54:06 [DEBUG] [net] logic waiting for msg on ibound
2020/12/28 18:54:06 [DEBUG] [net] putting puback msg on obound
2020/12/28 18:54:06 [DEBUG] [store] memorystore del: message 3006 was deleted
2020/12/28 18:54:06 [DEBUG] [net] done putting puback msg on obound
2020/12/28 18:54:06 [DEBUG] [client] startCommsWorkers c.oboundP msg: &{0xc010b921c0 }
2020/12/28 18:54:06 [DEBUG] [net] obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:06 [DEBUG] [net] outgoing waiting for an outbound message
2020/12/28 18:54:07 [DEBUG] [client] enter Publish
2020/12/28 18:54:07 [DEBUG] [client] sending publish message, topic: stf-692AFE13-0877-5F58-8B5B-949EEACFAE61/9C071FFAZ000J6
2020/12/28 18:54:07 [DEBUG] [client] #####Publish c.obound: #######
2020/12/28 18:54:07 [DEBUG] [client] startCommsWorkers c.obound msg: &{0xc0074fbe80 0xc0074fbe40}
2020/12/28 18:54:07 [DEBUG] [net] obound msg to write 819
2020/12/28 18:54:07 [DEBUG] [net] obound wrote msg, id: 819
2020/12/28 18:54:07 [DEBUG] [net] outgoing waiting for an outbound message
2020/12/28 18:54:07 [DEBUG] [net] startIncoming Received Message
2020/12/28 18:54:07 [DEBUG] [net] startIncomingComms: got msg on ibound
2020/12/28 18:54:07 [DEBUG] [store] memorystore del: message 819 was deleted
2020/12/28 18:54:07 [DEBUG] [net] startIncomingComms: received puback, id: 819
2020/12/28 18:54:07 [DEBUG] [net] logic waiting for msg on ibound
2020/12/28 18:54:08 [DEBUG] [pinger] ping check 1.279685498
2020/12/28 18:54:13 [DEBUG] [net] startIncoming Received Message
2020/12/28 18:54:13 [DEBUG] [net] startIncomingComms: got msg on ibound
2020/12/28 18:54:13 [DEBUG] [net] startIncomingComms: received publish, msgId: 3007
2020/12/28 18:54:13 [DEBUG] [net] logic waiting for msg on ibound
2020/12/28 18:54:13 [DEBUG] [net] putting puback msg on obound
2020/12/28 18:54:13 [DEBUG] [store] memorystore del: message 3007 was deleted
2020/12/28 18:54:13 [DEBUG] [net] done putting puback msg on obound
2020/12/28 18:54:13 [DEBUG] [client] startCommsWorkers c.oboundP msg: &{0xc010b923e0 }
2020/12/28 18:54:13 [DEBUG] [net] obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:13 [DEBUG] [net] outgoing waiting for an outbound message
2020/12/28 18:54:13 [DEBUG] [pinger] ping check 0.45940204
2020/12/28 18:54:14 [DEBUG] [client] enter Publish
2020/12/28 18:54:14 [DEBUG] [client] sending publish message, topic: stf-692AFE13-0877-5F58-8B5B-949EEACFAE61/353013085721500
2020/12/28 18:54:14 [DEBUG] [client] #####Publish c.obound: #######
2020/12/28 18:54:14 [DEBUG] [client] startCommsWorkers c.obound msg: &{0xc00c95cb00 0xc00c95c940}
2020/12/28 18:54:14 [DEBUG] [net] obound msg to write 820
2020/12/28 18:54:14 [DEBUG] [net] obound wrote msg, id: 820
2020/12/28 18:54:14 [DEBUG] [net] outgoing waiting for an outbound message
2020/12/28 18:54:14 [DEBUG] [net] startIncoming Received Message
2020/12/28 18:54:14 [DEBUG] [net] startIncomingComms: got msg on ibound
2020/12/28 18:54:14 [DEBUG] [store] memorystore del: message 820 was deleted
2020/12/28 18:54:14 [DEBUG] [net] startIncomingComms: received puback, id: 820
2020/12/28 18:54:14 [DEBUG] [net] logic waiting for msg on ibound
2020/12/28 18:54:14 [DEBUG] [net] startIncoming Received Message
2020/12/28 18:54:14 [DEBUG] [net] startIncomingComms: got msg on ibound
2020/12/28 18:54:14 [DEBUG] [net] startIncomingComms: received publish, msgId: 3008
2020/12/28 18:54:14 [DEBUG] [net] logic waiting for msg on ibound
2020/12/28 18:54:14 [DEBUG] [net] putting puback msg on obound
2020/12/28 18:54:14 [DEBUG] [store] memorystore del: message 3008 was deleted
2020/12/28 18:54:14 [DEBUG] [net] done putting puback msg on obound
2020/12/28 18:54:14 [DEBUG] [client] startCommsWorkers c.oboundP msg: &{0xc010b92660 }
2020/12/28 18:54:14 [DEBUG] [net] obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:14 [DEBUG] [net] outgoing waiting for an outbound message
2020/12/28 18:54:14 [DEBUG] [net] startIncoming Received Message
2020/12/28 18:54:14 [DEBUG] [net] startIncomingComms: got msg on ibound
2020/12/28 18:54:14 [DEBUG] [net] startIncomingComms: received publish, msgId: 3009
2020/12/28 18:54:14 [DEBUG] [net] logic waiting for msg on ibound
2020/12/28 18:54:14 [DEBUG] [net] putting puback msg on obound
2020/12/28 18:54:14 [DEBUG] [store] memorystore del: message 3009 was deleted
2020/12/28 18:54:14 [DEBUG] [net] done putting puback msg on obound
2020/12/28 18:54:14 [DEBUG] [client] startCommsWorkers c.oboundP msg: &{0xc00062dc20 }
2020/12/28 18:54:14 [DEBUG] [net] obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:14 [DEBUG] [net] outgoing waiting for an outbound message
2020/12/28 18:54:16 [DEBUG] [net] startIncoming Received Message
2020/12/28 18:54:16 [DEBUG] [net] startIncomingComms: got msg on ibound
2020/12/28 18:54:16 [DEBUG] [net] startIncomingComms: received publish, msgId: 3010
2020/12/28 18:54:16 [DEBUG] [net] logic waiting for msg on ibound
2020/12/28 18:54:16 [DEBUG] [net] putting puback msg on obound
2020/12/28 18:54:16 [DEBUG] [store] memorystore del: message 3010 was deleted
2020/12/28 18:54:16 [DEBUG] [net] done putting puback msg on obound
2020/12/28 18:54:16 [DEBUG] [client] startCommsWorkers c.oboundP msg: &{0xc00567e0e0 }
2020/12/28 18:54:16 [DEBUG] [net] obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:16 [DEBUG] [net] outgoing waiting for an outbound message
2020/12/28 18:54:17 [DEBUG] [client] enter Publish
2020/12/28 18:54:17 [DEBUG] [client] sending publish message, topic: stf-692AFE13-0877-5F58-8B5B-949EEACFAE61/9C071FFAZ000J6
2020/12/28 18:54:17 [DEBUG] [client] #####Publish c.obound: #######
2020/12/28 18:54:17 [DEBUG] [client] startCommsWorkers c.obound msg: &{0xc00c67bc40 0xc00c67bc00}
2020/12/28 18:54:17 [DEBUG] [net] obound msg to write 821
2020/12/28 18:54:17 [DEBUG] [net] obound wrote msg, id: 821
2020/12/28 18:54:17 [DEBUG] [net] outgoing waiting for an outbound message
2020/12/28 18:54:17 [DEBUG] [net] startIncoming Received Message
2020/12/28 18:54:17 [DEBUG] [net] startIncomingComms: got msg on ibound
2020/12/28 18:54:17 [DEBUG] [store] memorystore del: message 821 was deleted
2020/12/28 18:54:17 [DEBUG] [net] startIncomingComms: received puback, id: 821
2020/12/28 18:54:17 [DEBUG] [net] logic waiting for msg on ibound
2020/12/28 18:54:18 [DEBUG] [pinger] ping check 1.335859114
2020/12/28 18:54:23 [DEBUG] [net] startIncoming Received Message
2020/12/28 18:54:23 [DEBUG] [net] startIncomingComms: got msg on ibound
2020/12/28 18:54:23 [DEBUG] [net] startIncomingComms: received publish, msgId: 3011
2020/12/28 18:54:23 [DEBUG] [net] logic waiting for msg on ibound
2020/12/28 18:54:23 [DEBUG] [net] putting puback msg on obound
2020/12/28 18:54:23 [DEBUG] [store] memorystore del: message 3011 was deleted
2020/12/28 18:54:23 [DEBUG] [net] done putting puback msg on obound
2020/12/28 18:54:23 [DEBUG] [client] startCommsWorkers c.oboundP msg: &{0xc01123c840 }
2020/12/28 18:54:23 [DEBUG] [net] obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:23 [DEBUG] [net] outgoing waiting for an outbound message
2020/12/28 18:54:23 [DEBUG] [pinger] ping check 0.476932603
2020/12/28 18:54:24 [DEBUG] [client] enter Publish
2020/12/28 18:54:24 [DEBUG] [client] sending publish message, topic: stf-692AFE13-0877-5F58-8B5B-949EEACFAE61/353013085721500
2020/12/28 18:54:24 [DEBUG] [client] #####Publish c.obound: #######
2020/12/28 18:54:24 [DEBUG] [client] startCommsWorkers c.obound msg: &{0xc00fe2cac0 0xc00fe2ca80}
2020/12/28 18:54:24 [DEBUG] [net] obound msg to write 822
2020/12/28 18:54:24 [DEBUG] [net] obound wrote msg, id: 822
2020/12/28 18:54:24 [DEBUG] [net] outgoing waiting for an outbound message
2020/12/28 18:54:24 [DEBUG] [net] startIncoming Received Message
2020/12/28 18:54:24 [DEBUG] [net] startIncomingComms: got msg on ibound
2020/12/28 18:54:24 [DEBUG] [store] memorystore del: message 822 was deleted
2020/12/28 18:54:24 [DEBUG] [net] startIncomingComms: received puback, id: 822
2020/12/28 18:54:24 [DEBUG] [net] logic waiting for msg on ibound
2020/12/28 18:54:26 [DEBUG] [net] startIncoming Received Message
2020/12/28 18:54:26 [DEBUG] [net] startIncomingComms: got msg on ibound
2020/12/28 18:54:26 [DEBUG] [net] startIncomingComms: received publish, msgId: 3012
2020/12/28 18:54:26 [DEBUG] [net] logic waiting for msg on ibound
2020/12/28 18:54:26 [DEBUG] [net] putting puback msg on obound
2020/12/28 18:54:26 [DEBUG] [store] memorystore del: message 3012 was deleted
2020/12/28 18:54:26 [DEBUG] [net] done putting puback msg on obound
2020/12/28 18:54:26 [DEBUG] [client] startCommsWorkers c.oboundP msg: &{0xc000477fc0 }
2020/12/28 18:54:26 [DEBUG] [net] obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:26 [DEBUG] [net] outgoing waiting for an outbound message
2020/12/28 18:54:27 [DEBUG] [client] enter Publish
2020/12/28 18:54:27 [DEBUG] [client] sending publish message, topic: stf-692AFE13-0877-5F58-8B5B-949EEACFAE61/9C071FFAZ000J6
2020/12/28 18:54:27 [DEBUG] [client] #####Publish c.obound: #######
2020/12/28 18:54:27 [DEBUG] [client] startCommsWorkers c.obound msg: &{0xc00fe2cd40 0xc00fe2cc80}
2020/12/28 18:54:27 [DEBUG] [net] obound msg to write 823
2020/12/28 18:54:27 [DEBUG] [net] obound wrote msg, id: 823
2020/12/28 18:54:27 [DEBUG] [net] outgoing waiting for an outbound message
2020/12/28 18:54:27 [DEBUG] [net] startIncoming Received Message
2020/12/28 18:54:27 [DEBUG] [net] startIncomingComms: got msg on ibound
2020/12/28 18:54:27 [DEBUG] [store] memorystore del: message 823 was deleted
2020/12/28 18:54:27 [DEBUG] [net] startIncomingComms: received puback, id: 823
2020/12/28 18:54:27 [DEBUG] [net] logic waiting for msg on ibound
2020/12/28 18:54:28 [DEBUG] [pinger] ping check 1.365129176
2020/12/28 18:54:33 [DEBUG] [net] startIncoming Received Message
2020/12/28 18:54:33 [DEBUG] [net] startIncomingComms: got msg on ibound
2020/12/28 18:54:33 [DEBUG] [net] startIncomingComms: received publish, msgId: 3013
2020/12/28 18:54:33 [DEBUG] [net] logic waiting for msg on ibound
2020/12/28 18:54:33 [DEBUG] [net] putting puback msg on obound
2020/12/28 18:54:33 [DEBUG] [store] memorystore del: message 3013 was deleted
2020/12/28 18:54:33 [DEBUG] [net] done putting puback msg on obound
2020/12/28 18:54:33 [DEBUG] [client] startCommsWorkers c.oboundP msg: &{0xc00567e000 }
2020/12/28 18:54:33 [DEBUG] [net] obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:33 [DEBUG] [net] outgoing waiting for an outbound message
2020/12/28 18:54:33 [DEBUG] [pinger] ping check 0.456312549
2020/12/28 18:54:34 [DEBUG] [client] enter Publish
2020/12/28 18:54:34 [DEBUG] [client] sending publish message, topic: stf-692AFE13-0877-5F58-8B5B-949EEACFAE61/353013085721500
2020/12/28 18:54:34 [DEBUG] [client] #####Publish c.obound: #######
2020/12/28 18:54:34 [DEBUG] [client] startCommsWorkers c.obound msg: &{0xc00e416280 0xc00e416240}
2020/12/28 18:54:34 [DEBUG] [net] obound msg to write 824
2020/12/28 18:54:34 [DEBUG] [net] obound wrote msg, id: 824
2020/12/28 18:54:34 [DEBUG] [net] outgoing waiting for an outbound message
2020/12/28 18:54:34 [DEBUG] [net] startIncoming Received Message
2020/12/28 18:54:34 [DEBUG] [net] startIncomingComms: got msg on ibound
2020/12/28 18:54:34 [DEBUG] [store] memorystore del: message 824 was deleted
2020/12/28 18:54:34 [DEBUG] [net] startIncomingComms: received puback, id: 824
2020/12/28 18:54:34 [DEBUG] [net] logic waiting for msg on ibound
2020/12/28 18:54:36 [DEBUG] [net] startIncoming Received Message
2020/12/28 18:54:36 [DEBUG] [net] startIncomingComms: got msg on ibound
2020/12/28 18:54:36 [DEBUG] [net] startIncomingComms: received publish, msgId: 3014
2020/12/28 18:54:36 [DEBUG] [net] logic waiting for msg on ibound
2020/12/28 18:54:36 [DEBUG] [net] putting puback msg on obound
2020/12/28 18:54:36 [DEBUG] [store] memorystore del: message 3014 was deleted
2020/12/28 18:54:36 [DEBUG] [net] done putting puback msg on obound
2020/12/28 18:54:36 [DEBUG] [client] startCommsWorkers c.oboundP msg: &{0xc00567e640 }
2020/12/28 18:54:36 [DEBUG] [net] obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:36 [DEBUG] [net] outgoing waiting for an outbound message
2020/12/28 18:54:37 [DEBUG] [client] enter Publish
2020/12/28 18:54:37 [DEBUG] [client] sending publish message, topic: stf-692AFE13-0877-5F58-8B5B-949EEACFAE61/9C071FFAZ000J6
2020/12/28 18:54:37 [DEBUG] [client] #####Publish c.obound: #######
2020/12/28 18:54:37 [DEBUG] [client] startCommsWorkers c.obound msg: &{0xc00fdb20c0 0xc00fdb2080}
2020/12/28 18:54:37 [DEBUG] [net] obound msg to write 825
2020/12/28 18:54:37 [DEBUG] [net] obound wrote msg, id: 825
2020/12/28 18:54:37 [DEBUG] [net] outgoing waiting for an outbound message
2020/12/28 18:54:37 [DEBUG] [net] startIncoming Received Message
2020/12/28 18:54:37 [DEBUG] [net] startIncomingComms: got msg on ibound
2020/12/28 18:54:37 [DEBUG] [store] memorystore del: message 825 was deleted
2020/12/28 18:54:37 [DEBUG] [net] startIncomingComms: received puback, id: 825
2020/12/28 18:54:37 [DEBUG] [net] logic waiting for msg on ibound
2020/12/28 18:54:38 [DEBUG] [pinger] ping check 1.311000699
2020/12/28 18:54:41 [DEBUG] [net] startIncoming Received Message
2020/12/28 18:54:41 [DEBUG] [net] startIncomingComms: got msg on ibound
2020/12/28 18:54:41 [DEBUG] [net] startIncomingComms: received publish, msgId: 3015
2020/12/28 18:54:41 [DEBUG] [net] logic waiting for msg on ibound
2020/12/28 18:54:42 [DEBUG] [net] putting puback msg on obound
2020/12/28 18:54:42 [DEBUG] [store] memorystore del: message 3015 was deleted
2020/12/28 18:54:42 [DEBUG] [net] done putting puback msg on obound
2020/12/28 18:54:42 [DEBUG] [client] startCommsWorkers c.oboundP msg: &{0xc013762b60 }
2020/12/28 18:54:42 [DEBUG] [net] obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:42 [DEBUG] [net] outgoing waiting for an outbound message
2020/12/28 18:54:43 [DEBUG] [net] startIncoming Received Message
2020/12/28 18:54:43 [DEBUG] [net] startIncomingComms: got msg on ibound
2020/12/28 18:54:43 [DEBUG] [net] startIncomingComms: received publish, msgId: 3016
2020/12/28 18:54:43 [DEBUG] [net] logic waiting for msg on ibound
2020/12/28 18:54:43 [DEBUG] [net] putting puback msg on obound
2020/12/28 18:54:43 [DEBUG] [store] memorystore del: message 3016 was deleted
2020/12/28 18:54:43 [DEBUG] [net] done putting puback msg on obound
2020/12/28 18:54:43 [DEBUG] [client] startCommsWorkers c.oboundP msg: &{0xc00060f940 }
2020/12/28 18:54:43 [DEBUG] [net] obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:43 [DEBUG] [net] outgoing waiting for an outbound message
2020/12/28 18:54:43 [DEBUG] [net] startIncoming Received Message
2020/12/28 18:54:43 [DEBUG] [net] startIncomingComms: got msg on ibound
2020/12/28 18:54:43 [DEBUG] [net] startIncomingComms: received publish, msgId: 3017
2020/12/28 18:54:43 [DEBUG] [net] logic waiting for msg on ibound
2020/12/28 18:54:43 [DEBUG] [net] putting puback msg on obound
2020/12/28 18:54:43 [DEBUG] [store] memorystore del: message 3017 was deleted
2020/12/28 18:54:43 [DEBUG] [net] done putting puback msg on obound
2020/12/28 18:54:43 [DEBUG] [client] startCommsWorkers c.oboundP msg: &{0xc001c207c0 }
2020/12/28 18:54:43 [DEBUG] [net] obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:43 [DEBUG] [net] outgoing waiting for an outbound message
2020/12/28 18:54:43 [DEBUG] [net] startIncoming Received Message
2020/12/28 18:54:43 [DEBUG] [net] startIncomingComms: got msg on ibound
2020/12/28 18:54:43 [DEBUG] [net] startIncomingComms: received publish, msgId: 3018
2020/12/28 18:54:43 [DEBUG] [net] logic waiting for msg on ibound
2020/12/28 18:54:43 [DEBUG] [net] putting puback msg on obound
2020/12/28 18:54:43 [DEBUG] [store] memorystore del: message 3018 was deleted
2020/12/28 18:54:43 [DEBUG] [net] done putting puback msg on obound
2020/12/28 18:54:43 [DEBUG] [client] startCommsWorkers c.oboundP msg: &{0xc001c20840 }
2020/12/28 18:54:43 [DEBUG] [net] obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:43 [DEBUG] [net] outgoing waiting for an outbound message
2020/12/28 18:54:43 [DEBUG] [pinger] ping check 0.479193262
2020/12/28 18:54:44 [DEBUG] [net] startIncoming Received Message
2020/12/28 18:54:44 [DEBUG] [net] startIncomingComms: got msg on ibound
2020/12/28 18:54:44 [DEBUG] [net] startIncomingComms: received publish, msgId: 3019
2020/12/28 18:54:44 [DEBUG] [net] logic waiting for msg on ibound
2020/12/28 18:54:44 [DEBUG] [net] putting puback msg on obound
2020/12/28 18:54:44 [DEBUG] [store] memorystore del: message 3019 was deleted
2020/12/28 18:54:44 [DEBUG] [net] done putting puback msg on obound
2020/12/28 18:54:44 [DEBUG] [client] startCommsWorkers c.oboundP msg: &{0xc01123cd00 }
2020/12/28 18:54:44 [DEBUG] [net] obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:44 [DEBUG] [net] outgoing waiting for an outbound message
2020/12/28 18:54:44 [DEBUG] [net] startIncoming Received Message
2020/12/28 18:54:44 [DEBUG] [net] startIncomingComms: got msg on ibound
2020/12/28 18:54:44 [DEBUG] [net] startIncomingComms: received publish, msgId: 3020
2020/12/28 18:54:44 [DEBUG] [net] logic waiting for msg on ibound
2020/12/28 18:54:44 [DEBUG] [net] putting puback msg on obound
2020/12/28 18:54:44 [DEBUG] [store] memorystore del: message 3020 was deleted
2020/12/28 18:54:44 [DEBUG] [net] done putting puback msg on obound
2020/12/28 18:54:44 [DEBUG] [client] startCommsWorkers c.oboundP msg: &{0xc001c20aa0 }
2020/12/28 18:54:44 [DEBUG] [net] obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:44 [DEBUG] [net] outgoing waiting for an outbound message
2020/12/28 18:54:44 [DEBUG] [client] enter Publish
2020/12/28 18:54:44 [DEBUG] [client] sending publish message, topic: stf-692AFE13-0877-5F58-8B5B-949EEACFAE61/353013085721500
2020/12/28 18:54:44 [DEBUG] [client] #####Publish c.obound: #######
2020/12/28 18:54:44 [DEBUG] [client] startCommsWorkers c.obound msg: &{0xc00fe2c840 0xc00fe2c7c0}
2020/12/28 18:54:44 [DEBUG] [net] obound msg to write 826
2020/12/28 18:54:44 [DEBUG] [net] obound wrote msg, id: 826
2020/12/28 18:54:44 [DEBUG] [net] outgoing waiting for an outbound message
2020/12/28 18:54:44 [DEBUG] [net] startIncoming Received Message
2020/12/28 18:54:44 [DEBUG] [net] startIncomingComms: got msg on ibound
2020/12/28 18:54:44 [DEBUG] [store] memorystore del: message 826 was deleted
2020/12/28 18:54:44 [DEBUG] [net] startIncomingComms: received puback, id: 826
2020/12/28 18:54:44 [DEBUG] [net] logic waiting for msg on ibound
2020/12/28 18:54:44 [DEBUG] [net] startIncoming Received Message
2020/12/28 18:54:44 [DEBUG] [net] startIncomingComms: got msg on ibound
2020/12/28 18:54:44 [DEBUG] [net] startIncomingComms: received publish, msgId: 3021
2020/12/28 18:54:44 [DEBUG] [net] logic waiting for msg on ibound
2020/12/28 18:54:44 [DEBUG] [net] putting puback msg on obound
2020/12/28 18:54:44 [DEBUG] [store] memorystore del: message 3021 was deleted
2020/12/28 18:54:44 [DEBUG] [net] done putting puback msg on obound
2020/12/28 18:54:44 [DEBUG] [client] startCommsWorkers c.oboundP msg: &{0xc01123cdc0 }
2020/12/28 18:54:44 [DEBUG] [net] obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:44 [DEBUG] [net] outgoing waiting for an outbound message
2020/12/28 18:54:44 [DEBUG] [net] startIncoming Received Message
2020/12/28 18:54:44 [DEBUG] [net] startIncomingComms: got msg on ibound
2020/12/28 18:54:44 [DEBUG] [net] startIncomingComms: received publish, msgId: 3022
2020/12/28 18:54:44 [DEBUG] [net] logic waiting for msg on ibound
2020/12/28 18:54:44 [DEBUG] [net] putting puback msg on obound
2020/12/28 18:54:44 [DEBUG] [store] memorystore del: message 3022 was deleted
2020/12/28 18:54:44 [DEBUG] [net] done putting puback msg on obound
2020/12/28 18:54:44 [DEBUG] [client] startCommsWorkers c.oboundP msg: &{0xc000222080 }
2020/12/28 18:54:44 [DEBUG] [net] obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:44 [DEBUG] [net] outgoing waiting for an outbound message
2020/12/28 18:54:45 [DEBUG] [net] startIncoming Received Message
2020/12/28 18:54:45 [DEBUG] [net] startIncomingComms: got msg on ibound
2020/12/28 18:54:45 [DEBUG] [net] startIncomingComms: received publish, msgId: 3023
2020/12/28 18:54:45 [DEBUG] [net] logic waiting for msg on ibound
2020/12/28 18:54:45 [DEBUG] [net] putting puback msg on obound
2020/12/28 18:54:45 [DEBUG] [store] memorystore del: message 3023 was deleted
2020/12/28 18:54:45 [DEBUG] [net] done putting puback msg on obound
2020/12/28 18:54:45 [DEBUG] [client] startCommsWorkers c.oboundP msg: &{0xc01123ce80 }
2020/12/28 18:54:45 [DEBUG] [net] obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:45 [DEBUG] [net] outgoing waiting for an outbound message
2020/12/28 18:54:45 [DEBUG] [net] startIncoming Received Message
2020/12/28 18:54:45 [DEBUG] [net] startIncomingComms: got msg on ibound
2020/12/28 18:54:45 [DEBUG] [net] startIncomingComms: received publish, msgId: 3024
2020/12/28 18:54:45 [DEBUG] [net] logic waiting for msg on ibound
2020/12/28 18:54:45 [DEBUG] [net] putting puback msg on obound
2020/12/28 18:54:45 [DEBUG] [store] memorystore del: message 3024 was deleted
2020/12/28 18:54:45 [DEBUG] [net] done putting puback msg on obound
2020/12/28 18:54:45 [DEBUG] [client] startCommsWorkers c.oboundP msg: &{0xc0002221c0 }
2020/12/28 18:54:45 [DEBUG] [net] obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:45 [DEBUG] [net] outgoing waiting for an outbound message
2020/12/28 18:54:46 [DEBUG] [net] startIncoming Received Message
2020/12/28 18:54:46 [DEBUG] [net] startIncomingComms: got msg on ibound
2020/12/28 18:54:46 [DEBUG] [net] startIncomingComms: received publish, msgId: 3025
2020/12/28 18:54:46 [DEBUG] [net] logic waiting for msg on ibound
2020/12/28 18:54:46 [DEBUG] [net] putting puback msg on obound
2020/12/28 18:54:46 [DEBUG] [store] memorystore del: message 3025 was deleted
2020/12/28 18:54:46 [DEBUG] [net] done putting puback msg on obound
2020/12/28 18:54:46 [DEBUG] [client] startCommsWorkers c.oboundP msg: &{0xc01123cf60 }
2020/12/28 18:54:46 [DEBUG] [net] obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:46 [DEBUG] [net] outgoing waiting for an outbound message
2020/12/28 18:54:47 [DEBUG] [net] startIncoming Received Message
2020/12/28 18:54:47 [DEBUG] [net] startIncomingComms: got msg on ibound
2020/12/28 18:54:47 [DEBUG] [net] startIncomingComms: received publish, msgId: 3026
2020/12/28 18:54:47 [DEBUG] [net] logic waiting for msg on ibound
2020/12/28 18:54:47 [DEBUG] [net] putting puback msg on obound
2020/12/28 18:54:47 [DEBUG] [store] memorystore del: message 3026 was deleted
2020/12/28 18:54:47 [DEBUG] [net] done putting puback msg on obound
2020/12/28 18:54:47 [DEBUG] [client] startCommsWorkers c.oboundP msg: &{0xc0002226a0 }
2020/12/28 18:54:47 [DEBUG] [net] obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:47 [DEBUG] [net] outgoing waiting for an outbound message
2020/12/28 18:54:47 [DEBUG] [net] startIncoming Received Message
2020/12/28 18:54:47 [DEBUG] [net] startIncomingComms: got msg on ibound
2020/12/28 18:54:47 [DEBUG] [net] startIncomingComms: received publish, msgId: 0
2020/12/28 18:54:47 [DEBUG] [net] logic waiting for msg on ibound
2020/12/28 18:54:47 [DEBUG] [net] startIncoming Received Message
2020/12/28 18:54:47 [DEBUG] [net] startIncomingComms: got msg on ibound
2020/12/28 18:54:47 [DEBUG] [net] startIncomingComms: received publish, msgId: 3027
2020/12/28 18:54:47 [DEBUG] [net] logic waiting for msg on ibound
2020/12/28 18:54:47 [DEBUG] [net] putting puback msg on obound
2020/12/28 18:54:47 [DEBUG] [store] memorystore del: message 3027 was deleted
2020/12/28 18:54:47 [DEBUG] [net] done putting puback msg on obound
2020/12/28 18:54:47 [DEBUG] [client] startCommsWorkers c.oboundP msg: &{0xc01123cfa0 }
2020/12/28 18:54:47 [DEBUG] [net] obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:47 [DEBUG] [net] outgoing waiting for an outbound message
2020/12/28 18:54:47 [DEBUG] [client] enter Publish
2020/12/28 18:54:47 [DEBUG] [client] sending publish message, topic: stf-692AFE13-0877-5F58-8B5B-949EEACFAE61/9C071FFAZ000J6
2020/12/28 18:54:47 [DEBUG] [client] #####Publish c.obound: #######
2020/12/28 18:54:47 [DEBUG] [client] startCommsWorkers c.obound msg: &{0xc010a42840 0xc010a42800}
2020/12/28 18:54:47 [DEBUG] [net] obound msg to write 827
2020/12/28 18:54:47 [DEBUG] [net] obound wrote msg, id: 827
2020/12/28 18:54:47 [DEBUG] [net] outgoing waiting for an outbound message
2020/12/28 18:54:47 [DEBUG] [net] startIncoming Received Message
2020/12/28 18:54:47 [DEBUG] [net] startIncomingComms: got msg on ibound
2020/12/28 18:54:47 [DEBUG] [store] memorystore del: message 827 was deleted
2020/12/28 18:54:47 [DEBUG] [net] startIncomingComms: received puback, id: 827
2020/12/28 18:54:47 [DEBUG] [net] logic waiting for msg on ibound
2020/12/28 18:54:48 [DEBUG] [pinger] ping check 1.453831872
2020/12/28 18:54:51 [DEBUG] [net] startIncoming Received Message
2020/12/28 18:54:51 [DEBUG] [net] startIncomingComms: got msg on ibound
2020/12/28 18:54:51 [DEBUG] [net] startIncomingComms: received publish, msgId: 3028
2020/12/28 18:54:51 [DEBUG] [net] logic waiting for msg on ibound
2020/12/28 18:54:51 [DEBUG] [net] startIncoming Received Message
2020/12/28 18:54:51 [DEBUG] [net] startIncomingComms: got msg on ibound
2020/12/28 18:54:51 [DEBUG] [net] startIncomingComms: received publish, msgId: 3029
2020/12/28 18:54:51 [DEBUG] [net] logic waiting for msg on ibound
2020/12/28 18:54:51 [DEBUG] [net] startIncoming Received Message
2020/12/28 18:54:51 [DEBUG] [net] startIncomingComms: got msg on ibound
2020/12/28 18:54:51 [DEBUG] [net] startIncomingComms: received publish, msgId: 3030
2020/12/28 18:54:51 [DEBUG] [net] logic waiting for msg on ibound
2020/12/28 18:54:52 [DEBUG] [client] enter Publish
2020/12/28 18:54:52 [DEBUG] [client] sending publish message, topic: stf-692AFE13-0877-5F58-8B5B-949EEACFAE61/5c922e1d
2020/12/28 18:54:52 [DEBUG] [client] #####Publish c.obound: #######
2020/12/28 18:54:52 [DEBUG] [client] startCommsWorkers c.obound msg: &{0xc00fdb2600 0xc00fdb25c0}
2020/12/28 18:54:52 [DEBUG] [net] obound msg to write 828
2020/12/28 18:54:52 [DEBUG] [net] obound wrote msg, id: 828
2020/12/28 18:54:52 [DEBUG] [net] outgoing waiting for an outbound message
2020/12/28 18:54:52 [DEBUG] [net] startIncoming Received Message
2020/12/28 18:54:52 [DEBUG] [net] startIncomingComms: got msg on ibound
2020/12/28 18:54:52 [DEBUG] [store] memorystore del: message 828 was deleted
2020/12/28 18:54:52 [DEBUG] [net] startIncomingComms: received puback, id: 828
2020/12/28 18:54:52 [DEBUG] [net] logic waiting for msg on ibound
2020/12/28 18:54:52 [DEBUG] [net] putting puback msg on obound
2020/12/28 18:54:52 [DEBUG] [store] memorystore del: message 3028 was deleted
2020/12/28 18:54:52 [DEBUG] [net] done putting puback msg on obound
2020/12/28 18:54:52 [DEBUG] [client] startCommsWorkers c.oboundP msg: &{0xc0137636e0 }
2020/12/28 18:54:52 [DEBUG] [net] putting puback msg on obound
2020/12/28 18:54:52 [DEBUG] [net] obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:52 [DEBUG] [store] memorystore del: message 3029 was deleted
2020/12/28 18:54:52 [DEBUG] [net] done putting puback msg on obound
2020/12/28 18:54:52 [DEBUG] [client] startCommsWorkers c.oboundP msg: &{0xc013763740 }
2020/12/28 18:54:52 [DEBUG] [net] outgoing waiting for an outbound message
2020/12/28 18:54:52 [DEBUG] [net] obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:52 [DEBUG] [net] outgoing waiting for an outbound message
2020/12/28 18:54:52 [DEBUG] [net] putting puback msg on obound
2020/12/28 18:54:52 [DEBUG] [store] memorystore del: message 3030 was deleted
2020/12/28 18:54:52 [DEBUG] [net] done putting puback msg on obound
2020/12/28 18:54:52 [DEBUG] [client] startCommsWorkers c.oboundP msg: &{0xc013763760 }
2020/12/28 18:54:52 [DEBUG] [net] obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:52 [DEBUG] [net] outgoing waiting for an outbound message
2020/12/28 18:54:52 [DEBUG] [net] startIncoming Received Message
2020/12/28 18:54:52 [DEBUG] [net] startIncomingComms: got msg on ibound
2020/12/28 18:54:52 [DEBUG] [net] startIncomingComms: received publish, msgId: 3031
2020/12/28 18:54:52 [DEBUG] [net] logic waiting for msg on ibound
2020/12/28 18:54:52 [DEBUG] [net] putting puback msg on obound
2020/12/28 18:54:52 [DEBUG] [store] memorystore del: message 3031 was deleted
2020/12/28 18:54:52 [DEBUG] [net] done putting puback msg on obound
2020/12/28 18:54:52 [DEBUG] [client] startCommsWorkers c.oboundP msg: &{0xc01123d320 }
2020/12/28 18:54:52 [DEBUG] [net] obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:52 [DEBUG] [net] outgoing waiting for an outbound message
2020/12/28 18:54:52 [DEBUG] [net] startIncoming Received Message
2020/12/28 18:54:52 [DEBUG] [net] startIncomingComms: got msg on ibound
2020/12/28 18:54:52 [DEBUG] [net] startIncomingComms: received publish, msgId: 3032
2020/12/28 18:54:52 [DEBUG] [net] logic waiting for msg on ibound
2020/12/28 18:54:52 [DEBUG] [net] putting puback msg on obound
2020/12/28 18:54:52 [DEBUG] [store] memorystore del: message 3032 was deleted
2020/12/28 18:54:52 [DEBUG] [net] done putting puback msg on obound
2020/12/28 18:54:52 [DEBUG] [client] startCommsWorkers c.oboundP msg: &{0xc010b928a0 }
2020/12/28 18:54:52 [DEBUG] [net] obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:52 [DEBUG] [net] outgoing waiting for an outbound message
2020/12/28 18:54:53 [DEBUG] [net] startIncoming Received Message
2020/12/28 18:54:53 [DEBUG] [net] startIncomingComms: got msg on ibound
2020/12/28 18:54:53 [DEBUG] [net] startIncomingComms: received publish, msgId: 3033
2020/12/28 18:54:53 [DEBUG] [net] logic waiting for msg on ibound
2020/12/28 18:54:53 [DEBUG] [net] putting puback msg on obound
2020/12/28 18:54:53 [DEBUG] [store] memorystore del: message 3033 was deleted
2020/12/28 18:54:53 [DEBUG] [net] done putting puback msg on obound
2020/12/28 18:54:53 [DEBUG] [client] startCommsWorkers c.oboundP msg: &{0xc013763960 }
2020/12/28 18:54:53 [DEBUG] [net] obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:53 [DEBUG] [net] outgoing waiting for an outbound message
2020/12/28 18:54:53 [DEBUG] [net] startIncoming Received Message
2020/12/28 18:54:53 [DEBUG] [net] startIncomingComms: got msg on ibound
2020/12/28 18:54:53 [DEBUG] [net] startIncomingComms: received publish, msgId: 3034
2020/12/28 18:54:53 [DEBUG] [net] logic waiting for msg on ibound
2020/12/28 18:54:53 [DEBUG] [net] putting puback msg on obound
2020/12/28 18:54:53 [DEBUG] [store] memorystore del: message 3034 was deleted
2020/12/28 18:54:53 [DEBUG] [net] done putting puback msg on obound
2020/12/28 18:54:53 [DEBUG] [client] startCommsWorkers c.oboundP msg: &{0xc0137639c0 }
2020/12/28 18:54:53 [DEBUG] [net] obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:53 [DEBUG] [net] outgoing waiting for an outbound message
2020/12/28 18:54:53 [DEBUG] [pinger] ping check 0.118052986
2020/12/28 18:54:53 [DEBUG] [net] startIncoming Received Message
2020/12/28 18:54:53 [DEBUG] [net] startIncomingComms: got msg on ibound
2020/12/28 18:54:53 [DEBUG] [net] startIncomingComms: received publish, msgId: 3035
2020/12/28 18:54:53 [DEBUG] [net] logic waiting for msg on ibound
2020/12/28 18:54:53 [DEBUG] [net] putting puback msg on obound
2020/12/28 18:54:53 [DEBUG] [store] memorystore del: message 3035 was deleted
2020/12/28 18:54:53 [DEBUG] [net] done putting puback msg on obound
2020/12/28 18:54:53 [DEBUG] [client] startCommsWorkers c.oboundP msg: &{0xc013763e00 }
2020/12/28 18:54:53 [DEBUG] [net] obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:53 [DEBUG] [net] outgoing waiting for an outbound message
2020/12/28 18:54:54 [DEBUG] [client] enter Publish
2020/12/28 18:54:54 [DEBUG] [client] sending publish message, topic: stf-692AFE13-0877-5F58-8B5B-949EEACFAE61/353013085721500
2020/12/28 18:54:54 [DEBUG] [client] #####Publish c.obound: #######
2020/12/28 18:54:54 [DEBUG] [client] startCommsWorkers c.obound msg: &{0xc00fe2d140 0xc00fe2d100}
2020/12/28 18:54:54 [DEBUG] [net] obound msg to write 829
2020/12/28 18:54:54 [DEBUG] [net] obound wrote msg, id: 829
2020/12/28 18:54:54 [DEBUG] [net] outgoing waiting for an outbound message
2020/12/28 18:54:54 [DEBUG] [net] startIncoming Received Message
2020/12/28 18:54:54 [DEBUG] [net] startIncomingComms: got msg on ibound
2020/12/28 18:54:54 [DEBUG] [store] memorystore del: message 829 was deleted
2020/12/28 18:54:54 [DEBUG] [net] startIncomingComms: received puback, id: 829
2020/12/28 18:54:54 [DEBUG] [net] logic waiting for msg on ibound
2020/12/28 18:54:54 [DEBUG] [net] startIncoming Received Message
2020/12/28 18:54:54 [DEBUG] [net] startIncomingComms: got msg on ibound
2020/12/28 18:54:54 [DEBUG] [net] startIncomingComms: received publish, msgId: 3036
2020/12/28 18:54:54 [DEBUG] [net] logic waiting for msg on ibound
2020/12/28 18:54:54 [DEBUG] [net] putting puback msg on obound
2020/12/28 18:54:54 [DEBUG] [store] memorystore del: message 3036 was deleted
2020/12/28 18:54:54 [DEBUG] [net] done putting puback msg on obound
2020/12/28 18:54:54 [DEBUG] [client] startCommsWorkers c.oboundP msg: &{0xc01123d560 }
2020/12/28 18:54:54 [DEBUG] [net] obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:54 [DEBUG] [net] outgoing waiting for an outbound message
2020/12/28 18:54:54 [DEBUG] [net] startIncoming Received Message
2020/12/28 18:54:54 [DEBUG] [net] startIncomingComms: got msg on ibound
2020/12/28 18:54:54 [DEBUG] [net] startIncomingComms: received publish, msgId: 3037
2020/12/28 18:54:54 [DEBUG] [net] logic waiting for msg on ibound
2020/12/28 18:54:54 [DEBUG] [net] putting puback msg on obound
2020/12/28 18:54:54 [DEBUG] [store] memorystore del: message 3037 was deleted
2020/12/28 18:54:54 [DEBUG] [net] done putting puback msg on obound
2020/12/28 18:54:54 [DEBUG] [client] startCommsWorkers c.oboundP msg: &{0xc00003c320 }
2020/12/28 18:54:54 [DEBUG] [net] obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:54 [DEBUG] [net] outgoing waiting for an outbound message
2020/12/28 18:54:56 [DEBUG] [net] startIncoming Received Message
2020/12/28 18:54:56 [DEBUG] [net] startIncomingComms: got msg on ibound
2020/12/28 18:54:56 [DEBUG] [net] startIncomingComms: received publish, msgId: 3038
2020/12/28 18:54:56 [DEBUG] [net] logic waiting for msg on ibound
2020/12/28 18:54:56 [DEBUG] [net] putting puback msg on obound
2020/12/28 18:54:56 [DEBUG] [store] memorystore del: message 3038 was deleted
2020/12/28 18:54:56 [DEBUG] [net] done putting puback msg on obound
2020/12/28 18:54:56 [DEBUG] [client] startCommsWorkers c.oboundP msg: &{0xc01123d600 }
2020/12/28 18:54:56 [DEBUG] [net] obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:56 [DEBUG] [net] outgoing waiting for an outbound message
2020/12/28 18:54:56 [DEBUG] [net] startIncoming Received Message
2020/12/28 18:54:56 [DEBUG] [net] startIncomingComms: got msg on ibound
2020/12/28 18:54:56 [DEBUG] [net] startIncomingComms: received publish, msgId: 3039
2020/12/28 18:54:56 [DEBUG] [net] logic waiting for msg on ibound
2020/12/28 18:54:56 [DEBUG] [net] putting puback msg on obound
2020/12/28 18:54:56 [DEBUG] [store] memorystore del: message 3039 was deleted
2020/12/28 18:54:56 [DEBUG] [net] done putting puback msg on obound
2020/12/28 18:54:56 [DEBUG] [client] startCommsWorkers c.oboundP msg: &{0xc00567e960 }
2020/12/28 18:54:56 [DEBUG] [net] obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:56 [DEBUG] [net] outgoing waiting for an outbound message
2020/12/28 18:54:56 [DEBUG] [net] startIncoming Received Message
2020/12/28 18:54:56 [DEBUG] [net] startIncomingComms: got msg on ibound
2020/12/28 18:54:56 [DEBUG] [net] startIncomingComms: received publish, msgId: 3040
2020/12/28 18:54:56 [DEBUG] [net] logic waiting for msg on ibound
2020/12/28 18:54:56 [DEBUG] [net] putting puback msg on obound
2020/12/28 18:54:56 [DEBUG] [store] memorystore del: message 3040 was deleted
2020/12/28 18:54:56 [DEBUG] [net] done putting puback msg on obound
2020/12/28 18:54:56 [DEBUG] [client] startCommsWorkers c.oboundP msg: &{0xc00567e980 }
2020/12/28 18:54:56 [DEBUG] [net] obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:56 [DEBUG] [net] outgoing waiting for an outbound message
2020/12/28 18:54:57 [DEBUG] [client] enter Publish
2020/12/28 18:54:57 [DEBUG] [client] sending publish message, topic: stf-692AFE13-0877-5F58-8B5B-949EEACFAE61/9C071FFAZ000J6
2020/12/28 18:54:57 [DEBUG] [client] #####Publish c.obound: #######
2020/12/28 18:54:57 [DEBUG] [client] startCommsWorkers c.obound msg: &{0xc00fe2d3c0 0xc00fe2d380}
2020/12/28 18:54:57 [DEBUG] [net] obound msg to write 830
2020/12/28 18:54:57 [DEBUG] [net] obound wrote msg, id: 830
2020/12/28 18:54:57 [DEBUG] [net] outgoing waiting for an outbound message
2020/12/28 18:54:57 [DEBUG] [net] startIncoming Received Message
2020/12/28 18:54:57 [DEBUG] [net] startIncomingComms: got msg on ibound
2020/12/28 18:54:57 [DEBUG] [store] memorystore del: message 830 was deleted
2020/12/28 18:54:57 [DEBUG] [net] startIncomingComms: received puback, id: 830
2020/12/28 18:54:57 [DEBUG] [net] logic waiting for msg on ibound
2020/12/28 18:54:58 [DEBUG] [net] startIncoming Received Message
2020/12/28 18:54:58 [DEBUG] [net] startIncomingComms: got msg on ibound
2020/12/28 18:54:58 [DEBUG] [net] startIncomingComms: received publish, msgId: 3041
2020/12/28 18:54:58 [DEBUG] [net] logic waiting for msg on ibound
2020/12/28 18:54:58 [DEBUG] [net] putting puback msg on obound
2020/12/28 18:54:58 [DEBUG] [store] memorystore del: message 3041 was deleted
2020/12/28 18:54:58 [DEBUG] [net] done putting puback msg on obound
2020/12/28 18:54:58 [DEBUG] [client] startCommsWorkers c.oboundP msg: &{0xc00003d100 }
2020/12/28 18:54:58 [DEBUG] [net] obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:58 [DEBUG] [net] outgoing waiting for an outbound message
2020/12/28 18:54:58 [DEBUG] [net] startIncoming Received Message
2020/12/28 18:54:58 [DEBUG] [net] startIncomingComms: got msg on ibound
2020/12/28 18:54:58 [DEBUG] [net] startIncomingComms: received publish, msgId: 0
2020/12/28 18:54:58 [DEBUG] [net] logic waiting for msg on ibound
2020/12/28 18:54:58 [DEBUG] [net] startIncoming Received Message
2020/12/28 18:54:58 [DEBUG] [net] startIncomingComms: got msg on ibound
2020/12/28 18:54:58 [DEBUG] [net] startIncomingComms: received publish, msgId: 3042
2020/12/28 18:54:58 [DEBUG] [net] logic waiting for msg on ibound
2020/12/28 18:54:58 [DEBUG] [net] putting puback msg on obound
2020/12/28 18:54:58 [DEBUG] [store] memorystore del: message 3042 was deleted
2020/12/28 18:54:58 [DEBUG] [net] done putting puback msg on obound
2020/12/28 18:54:58 [DEBUG] [client] startCommsWorkers c.oboundP msg: &{0xc010b92c00 }
2020/12/28 18:54:58 [DEBUG] [net] obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:58 [DEBUG] [net] outgoing waiting for an outbound message
2020/12/28 18:54:58 [DEBUG] [pinger] ping check 0.183955869
2020/12/28 18:54:59 [DEBUG] [net] startIncoming Received Message
2020/12/28 18:54:59 [DEBUG] [net] startIncomingComms: got msg on ibound
2020/12/28 18:54:59 [DEBUG] [net] startIncomingComms: received publish, msgId: 3043
2020/12/28 18:54:59 [DEBUG] [net] logic waiting for msg on ibound
2020/12/28 18:54:59 [DEBUG] [net] putting puback msg on obound
2020/12/28 18:54:59 [DEBUG] [store] memorystore del: message 3043 was deleted
2020/12/28 18:54:59 [DEBUG] [net] done putting puback msg on obound
2020/12/28 18:54:59 [DEBUG] [client] startCommsWorkers c.oboundP msg: &{0xc00567f100 }
2020/12/28 18:54:59 [DEBUG] [net] obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:59 [DEBUG] [net] outgoing waiting for an outbound message
2020/12/28 18:54:59 [DEBUG] [net] startIncoming Received Message
2020/12/28 18:54:59 [DEBUG] [net] startIncomingComms: got msg on ibound
2020/12/28 18:54:59 [DEBUG] [net] startIncomingComms: received publish, msgId: 3044
2020/12/28 18:54:59 [DEBUG] [net] logic waiting for msg on ibound
2020/12/28 18:54:59 [DEBUG] [net] putting puback msg on obound
2020/12/28 18:54:59 [DEBUG] [store] memorystore del: message 3044 was deleted
2020/12/28 18:54:59 [DEBUG] [net] done putting puback msg on obound
2020/12/28 18:54:59 [DEBUG] [client] startCommsWorkers c.oboundP msg: &{0xc010b92fc0 }
2020/12/28 18:54:59 [DEBUG] [net] obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:54:59 [DEBUG] [net] outgoing waiting for an outbound message
2020/12/28 18:55:00 [DEBUG] [net] startIncoming Received Message
2020/12/28 18:55:00 [DEBUG] [net] startIncomingComms: got msg on ibound
2020/12/28 18:55:00 [DEBUG] [net] startIncomingComms: received publish, msgId: 3045
2020/12/28 18:55:00 [DEBUG] [net] logic waiting for msg on ibound
2020/12/28 18:55:00 [DEBUG] [net] putting puback msg on obound
2020/12/28 18:55:00 [DEBUG] [store] memorystore del: message 3045 was deleted
2020/12/28 18:55:00 [DEBUG] [net] done putting puback msg on obound
2020/12/28 18:55:00 [DEBUG] [client] startCommsWorkers c.oboundP msg: &{0xc010b931e0 }
2020/12/28 18:55:00 [DEBUG] [net] obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:55:00 [DEBUG] [net] outgoing waiting for an outbound message
2020/12/28 18:55:00 [DEBUG] [net] startIncoming Received Message
2020/12/28 18:55:00 [DEBUG] [net] startIncomingComms: got msg on ibound
2020/12/28 18:55:00 [DEBUG] [net] startIncomingComms: received publish, msgId: 3046
2020/12/28 18:55:00 [DEBUG] [net] logic waiting for msg on ibound
2020/12/28 18:55:00 [DEBUG] [net] putting puback msg on obound
2020/12/28 18:55:00 [DEBUG] [store] memorystore del: message 3046 was deleted
2020/12/28 18:55:00 [DEBUG] [net] done putting puback msg on obound
2020/12/28 18:55:00 [DEBUG] [client] startCommsWorkers c.oboundP msg: &{0xc0004af200 }
2020/12/28 18:55:00 [DEBUG] [net] obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:55:00 [DEBUG] [net] outgoing waiting for an outbound message
2020/12/28 18:55:01 [DEBUG] [net] startIncoming Received Message
2020/12/28 18:55:01 [DEBUG] [net] startIncomingComms: got msg on ibound
2020/12/28 18:55:01 [DEBUG] [net] startIncomingComms: received publish, msgId: 3047
2020/12/28 18:55:01 [DEBUG] [net] logic waiting for msg on ibound
2020/12/28 18:55:01 [DEBUG] [net] putting puback msg on obound
2020/12/28 18:55:01 [DEBUG] [store] memorystore del: message 3047 was deleted
2020/12/28 18:55:01 [DEBUG] [net] done putting puback msg on obound
2020/12/28 18:55:01 [DEBUG] [client] startCommsWorkers c.oboundP msg: &{0xc01123dd80 }
2020/12/28 18:55:01 [DEBUG] [net] obound priority msg to write, type *packets.PubackPacket
2020/12/28 18:55:01 [DEBUG] [net] outgoing waiting for an outbound message
2020/12/28 18:55:01 [DEBUG] [net] startIncoming Received Message
2020/12/28 18:55:01 [DEBUG] [net] startIncomingComms: got msg on ibound
2020/12/28 18:55:01 [DEBUG] [net] startIncomingComms: received publish, msgId: 3048
2020/12/28 18:55:01 [DEBUG] [net] logic waiting for msg on ibound
2020/12/28 18:55:01 [DEBUG] [net] startIncoming Received Message
2020/12/28 18:55:01 [DEBUG] [net] startIncomingComms: got msg on ibound
2020/12/28 18:55:01 [DEBUG] [net] startIncomingComms: received publish, msgId: 3049
2020/12/28 18:55:01 [DEBUG] [net] logic waiting for msg on ibound
2020/12/28 18:55:02 [DEBUG] [net] startIncoming Received Message
2020/12/28 18:55:02 [DEBUG] [net] startIncomingComms: got msg on ibound
2020/12/28 18:55:02 [DEBUG] [net] startIncomingComms: received publish, msgId: 3050
2020/12/28 18:55:02 [DEBUG] [net] logic waiting for msg on ibound
2020/12/28 18:55:02 [DEBUG] [net] startIncoming Received Message
2020/12/28 18:55:02 [DEBUG] [net] startIncomingComms: got msg on ibound
2020/12/28 18:55:02 [DEBUG] [net] startIncomingComms: received publish, msgId: 0
2020/12/28 18:55:02 [DEBUG] [client] enter Publish
2020/12/28 18:55:02 [DEBUG] [client] sending publish message, topic: stf-692AFE13-0877-5F58-8B5B-949EEACFAE61/5c922e1d
2020/12/28 18:55:02 [DEBUG] [client] #####Publish c.obound: #######
2020/12/28 18:55:02 [DEBUG] [client] startCommsWorkers c.obound msg: &{0xc00c95dc00 0xc00c95dbc0}
2020/12/28 18:55:02 [DEBUG] [net] obound msg to write 831
2020/12/28 18:55:02 [DEBUG] [net] obound wrote msg, id: 831
2020/12/28 18:55:02 [DEBUG] [net] outgoing waiting for an outbound message
2020/12/28 18:55:02 [DEBUG] [net] startIncoming Received Message
2020/12/28 18:55:03 [DEBUG] [pinger] ping check 1.872589665
2020/12/28 18:55:08 [DEBUG] [pinger] ping check 6.87293455
2020/12/28 18:55:13 [DEBUG] [pinger] ping check 11.900795076
2020/12/28 18:55:18 [DEBUG] [pinger] ping check 16.873234248
2020/12/28 18:55:23 [DEBUG] [pinger] ping check 21.90367372
2020/12/28 18:55:28 [DEBUG] [pinger] ping check 26.87759304
2020/12/28 18:55:33 [DEBUG] [pinger] ping check 31.871691928
2020/12/28 18:55:38 [DEBUG] [pinger] ping check 36.885652448
2020/12/28 18:55:44 [DEBUG] [pinger] ping check 41.946738907
2020/12/28 18:55:48 [DEBUG] [pinger] ping check 46.87123913
2020/12/28 18:55:53 [DEBUG] [pinger] ping check 51.876050751
2020/12/28 18:55:58 [DEBUG] [pinger] ping check 56.872241076
2020/12/28 18:56:03 [DEBUG] [pinger] ping check 61.871172425
2020/12/28 18:56:08 [DEBUG] [pinger] ping check 66.875206823
2020/12/28 18:56:13 [DEBUG] [pinger] ping check 71.874094389
2020/12/28 18:56:18 [DEBUG] [pinger] ping check 76.871257706
2020/12/28 18:56:23 [DEBUG] [pinger] ping check 81.887289891
2020/12/28 18:56:28 [DEBUG] [pinger] ping check 86.88227673
2020/12/28 18:56:33 [DEBUG] [pinger] ping check 91.872222389
2020/12/28 18:56:38 [DEBUG] [pinger] ping check 96.880015293
2020/12/28 18:56:43 [DEBUG] [pinger] ping check 101.879905674
2020/12/28 18:56:49 [DEBUG] [pinger] ping check 106.950685648
2020/12/28 18:56:53 [DEBUG] [pinger] ping check 111.887278252
2020/12/28 18:56:58 [DEBUG] [pinger] ping check 116.879197592
2020/12/28 18:57:03 [DEBUG] [pinger] ping check 121.890659963
2020/12/28 18:57:08 [DEBUG] [pinger] ping check 126.882503995
2020/12/28 18:57:13 [DEBUG] [pinger] ping check 131.888095769
2020/12/28 18:57:18 [DEBUG] [pinger] ping check 136.894459158
2020/12/28 18:57:23 [DEBUG] [pinger] ping check 141.893740683
2020/12/28 18:57:28 [DEBUG] [pinger] ping check 146.895498901
2020/12/28 18:57:33 [DEBUG] [pinger] ping check 151.896772964
2020/12/28 18:57:38 [DEBUG] [pinger] ping check 156.917567966
2020/12/28 18:57:43 [DEBUG] [pinger] ping check 161.872913588
2020/12/28 18:57:48 [DEBUG] [pinger] ping check 166.894009244
2020/12/28 18:57:53 [DEBUG] [pinger] ping check 171.924919796
2020/12/28 18:57:58 [DEBUG] [pinger] ping check 176.876066261
2020/12/28 18:58:03 [DEBUG] [pinger] ping check 181.871120643
2020/12/28 18:58:08 [DEBUG] [pinger] ping check 186.916778914
2020/12/28 18:58:13 [DEBUG] [pinger] ping check 191.871151304
2020/12/28 18:58:18 [DEBUG] [pinger] ping check 196.894813459
2020/12/28 18:58:23 [DEBUG] [pinger] ping check 201.884660824
2020/12/28 18:58:28 [DEBUG] [pinger] ping check 206.881708149
2020/12/28 18:58:34 [DEBUG] [pinger] ping check 211.946752845
2020/12/28 18:58:38 [DEBUG] [pinger] ping check 216.894292691
2020/12/28 18:58:43 [DEBUG] [pinger] ping check 221.886063422
2020/12/28 18:58:48 [DEBUG] [pinger] ping check 226.872439777
2020/12/28 18:58:53 [DEBUG] [pinger] ping check 231.903365241
2020/12/28 18:58:58 [DEBUG] [pinger] ping check 236.871690075
2020/12/28 18:59:03 [DEBUG] [pinger] ping check 241.872224307
2020/12/28 18:59:08 [DEBUG] [pinger] ping check 246.872293608
2020/12/28 18:59:13 [DEBUG] [pinger] ping check 251.885761097
2020/12/28 18:59:18 [DEBUG] [pinger] ping check 256.872677532
2020/12/28 18:59:23 [DEBUG] [pinger] ping check 261.871915896
2020/12/28 18:59:29 [DEBUG] [pinger] ping check 266.94323031
2020/12/28 18:59:33 [DEBUG] [pinger] ping check 271.871173669
2020/12/28 18:59:38 [DEBUG] [pinger] ping check 276.874400984
2020/12/28 18:59:43 [DEBUG] [pinger] ping check 281.934717686
2020/12/28 18:59:48 [DEBUG] [pinger] ping check 286.885194154
2020/12/28 18:59:53 [DEBUG] [pinger] ping check 291.88239686
2020/12/28 18:59:58 [DEBUG] [pinger] ping check 296.887537738
2020/12/28 19:00:03 [DEBUG] [pinger] ping check 301.877492839
2020/12/28 19:00:08 [DEBUG] [pinger] ping check 306.881997648
2020/12/28 19:00:13 [DEBUG] [pinger] ping check 311.886916863
2020/12/28 19:00:18 [DEBUG] [pinger] ping check 316.881473751
2020/12/28 19:00:23 [DEBUG] [pinger] ping check 321.871081772
2020/12/28 19:00:28 [DEBUG] [pinger] ping check 326.873282093
2020/12/28 19:00:33 [DEBUG] [pinger] ping check 331.873796386
2020/12/28 19:00:38 [DEBUG] [pinger] ping check 336.873702743
2020/12/28 19:00:43 [DEBUG] [pinger] ping check 341.898005436
2020/12/28 19:00:48 [DEBUG] [pinger] ping check 346.890559087
2020/12/28 19:00:53 [DEBUG] [pinger] ping check 351.871989069
2020/12/28 19:00:58 [DEBUG] [pinger] ping check 356.874558575
2020/12/28 19:01:03 [DEBUG] [pinger] ping check 361.874361263
2020/12/28 19:01:08 [DEBUG] [pinger] ping check 366.892902613
2020/12/28 19:01:13 [DEBUG] [pinger] ping check 371.892875777
2020/12/28 19:01:18 [DEBUG] [pinger] ping check 376.895517155
2020/12/28 19:01:23 [DEBUG] [pinger] ping check 381.893908065
2020/12/28 19:01:28 [DEBUG] [pinger] ping check 386.908873572
2020/12/28 19:01:33 [DEBUG] [pinger] ping check 391.878903646
2020/12/28 19:01:38 [DEBUG] [pinger] ping check 396.871251185
2020/12/28 19:01:44 [DEBUG] [pinger] ping check 401.995463532
2020/12/28 19:01:48 [DEBUG] [pinger] ping check 406.942938848
2020/12/28 19:01:53 [DEBUG] [pinger] ping check 411.889605482
2020/12/28 19:01:58 [DEBUG] [pinger] ping check 416.874886907
2020/12/28 19:02:03 [DEBUG] [pinger] ping check 421.890605726
2020/12/28 19:02:08 [DEBUG] [pinger] ping check 426.871226776
2020/12/28 19:02:13 [DEBUG] [pinger] ping check 431.877273847
2020/12/28 19:02:18 2020/12/28 19:02:18 Error reading: EOF
2020/12/28 19:02:18 2020/12/28 19:02:18 Agent Error reading: EOF
2020/12/28 19:02:18 2020/12/28 19:02:18 read finished for 9C071FFAZ000J6
2020/12/28 19:02:18 2020/12/28 19:02:18 scrcpy is dead on device 9C071FFAZ000J6
2020/12/28 19:02:18 2020/12/28 19:02:18 os: process already finished
2020/12/28 19:02:18 2020/12/28 19:02:18 Starting making scrcpy server for device %S 9C071FFAZ000J6
2020/12/28 19:02:18 2020/12/28 19:02:18 9C071FFAZ000J6 process kill err: os: process already finished
2020/12/28 19:02:18 2020/12/28 19:02:18 push server.jar fail: exit status 1
2020/12/28 19:02:18 [DEBUG] [pinger] ping check 436.873068092
2020/12/28 19:02:19 2020/12/28 19:02:19 Starting making scrcpy server for device %S 9C071FFAZ000J6
2020/12/28 19:02:19 2020/12/28 19:02:19 Error reading: read tcp 127.0.0.1:49997->127.0.0.1:50010: use of closed network connection
2020/12/28 19:02:19 2020/12/28 19:02:19 push server.jar fail: exit status 1
2020/12/28 19:02:20 2020/12/28 19:02:20 Error reading: read tcp 127.0.0.1:49997->127.0.0.1:50010: use of closed network connection
2020/12/28 19:02:20 2020/12/28 19:02:20 Starting making scrcpy server for device %S 9C071FFAZ000J6
2020/12/28 19:02:20 2020/12/28 19:02:20 push server.jar fail: exit status 1
2020/12/28 19:02:20 2020/12/28 19:02:20 shut down everything for scrcpy on 9C071FFAZ000J6
2020/12/28 19:02:20 2020/12/28 19:02:20 os: process already finished
2020/12/28 19:02:20 2020/12/28 19:02:20 shut down everything for agent server on 9C071FFAZ000J6
2020/12/28 19:02:20 2020/12/28 19:02:20 Control for 9C071FFAZ000J6 stoped
2020/12/28 19:02:20 2020/12/28 19:02:20 9C071FFAZ000J6 process kill err: os: process already finished
2020/12/28 19:02:21 [DEBUG] [client] enter Unsubscribe
2020/12/28 19:02:21 [DEBUG] [client] sending unsubscribe message, topics: [agent-692AFE13-0877-5F58-8B5B-949EEACFAE61/9C071FFAZ000J6]
2020/12/28 19:02:21 [DEBUG] [client] ####Unsubscribe oboundP receive a message #####
2020/12/28 19:02:21 [DEBUG] [client] exit Unsubscribe
2020/12/28 19:02:21 [DEBUG] [client] startCommsWorkers c.oboundP msg: &{0xc010014d20 0xc00d176a80}
2020/12/28 19:02:21 [DEBUG] [net] obound priority msg to write, type *packets.UnsubscribePacket
2020/12/28 19:02:21 [DEBUG] [net] outgoing waiting for an outbound message
2020/12/28 19:02:21 2020/12/28 19:02:21 Screening finished for 9C071FFAZ000J6
2020/12/28 19:02:21 2020/12/28 19:02:21 finish initiating server for 9C071FFAZ000J6
2020/12/28 19:02:23 [DEBUG] [pinger] ping check 2.5371631629999998
2020/12/28 19:02:28 [DEBUG] [pinger] ping check 7.534591538
2020/12/28 19:02:33 [DEBUG] [pinger] ping check 12.535742837
2020/12/28 19:02:37 2020/12/28 19:02:37 finish initiating server for 9C071FFAZ000J6
2020/12/28 19:02:38 [DEBUG] [pinger] ping check 17.548698441
2020/12/28 19:02:43 [DEBUG] [pinger] ping check 22.560391177
2020/12/28 19:02:48 [DEBUG] [pinger] ping check 27.536675739
2020/12/28 19:02:53 [DEBUG] [pinger] ping check 32.561630977
2020/12/28 19:02:58 [DEBUG] [pinger] ping check 37.536556433
2020/12/28 19:03:03 [DEBUG] [pinger] ping check 42.574990324
2020/12/28 19:03:08 [DEBUG] [pinger] ping check 47.541282015
2020/12/28 19:03:13 [DEBUG] [pinger] ping check 52.5584123
2020/12/28 19:03:18 [DEBUG] [pinger] ping check 57.535337644
2020/12/28 19:03:23 [DEBUG] [pinger] ping check 62.559060043
2020/12/28 19:03:28 [DEBUG] [pinger] ping check 67.561595564
2020/12/28 19:03:33 [DEBUG] [pinger] ping check 72.534744877
2020/12/28 19:03:37 [DEBUG] [client] enter Publish
2020/12/28 19:03:37 [DEBUG] [client] sending publish message, topic: stf-692AFE13-0877-5F58-8B5B-949EEACFAE61/9C071FFAZ000J6
2020/12/28 19:03:37 [DEBUG] [client] #####Publish c.obound: #######
2020/12/28 19:03:37 [DEBUG] [client] startCommsWorkers c.obound msg: &{0xc00db5bb40 0xc00db5bb00}
2020/12/28 19:03:37 [DEBUG] [net] obound msg to write 833
2020/12/28 19:03:37 [DEBUG] [net] obound wrote msg, id: 833
2020/12/28 19:03:37 [DEBUG] [net] outgoing waiting for an outbound message
2020/12/28 19:03:38 [DEBUG] [pinger] ping check 1.385413411
2020/12/28 19:03:43 [DEBUG] [pinger] ping check 6.433137042
2020/12/28 19:03:48 [DEBUG] [pinger] ping check 11.381266375
2020/12/28 19:03:53 [DEBUG] [pinger] ping check 16.41252487
2020/12/28 19:03:58 [DEBUG] [pinger] ping check 21.378576052
2020/12/28 19:04:03 [DEBUG] [pinger] ping check 26.378504355
2020/12/28 19:04:08 [DEBUG] [pinger] ping check 31.381645796
2020/12/28 19:04:13 [DEBUG] [pinger] ping check 36.395564331
2020/12/28 19:04:18 [DEBUG] [pinger] ping check 41.381531796
2020/12/28 19:04:23 [DEBUG] [pinger] ping check 46.402866521
2020/12/28 19:04:28 [DEBUG] [pinger] ping check 51.41327018
2020/12/28 19:04:33 [DEBUG] [pinger] ping check 56.378523871
2020/12/28 19:04:38 [DEBUG] [pinger] ping check 61.381385266
2020/12/28 19:04:43 [DEBUG] [pinger] ping check 66.386516631
2020/12/28 19:04:48 [DEBUG] [pinger] ping check 71.421782476
2020/12/28 19:04:54 [DEBUG] [pinger] ping check 76.466843257
2020/12/28 19:04:58 [DEBUG] [pinger] ping check 81.378573708
2020/12/28 19:05:03 [DEBUG] [pinger] ping check 86.386321059
2020/12/28 19:05:03 [DEBUG] [pinger] keepalive sending ping
2020/12/28 19:05:08 [DEBUG] [pinger] ping check 5.02801415
2020/12/28 19:05:08 2020/12/28 19:05:08 ping check Intercept
2020/12/28 19:05:14 2020/12/28 19:05:14 ping check Intercept
2020/12/28 19:05:14 [DEBUG] [pinger] ping check 10.07152941
2020/12/28 19:05:18 2020/12/28 19:05:18 ping check Intercept
2020/12/28 19:05:18 [DEBUG] [pinger] ping check 15.062565754
2020/12/28 19:05:23 2020/12/28 19:05:23 ping check Intercept
2020/12/28 19:05:23 [DEBUG] [pinger] ping check 19.99413201
2020/12/28 19:05:28 2020/12/28 19:05:28 ping check Intercept
2020/12/28 19:05:28 [DEBUG] [pinger] ping check 25.019997198
2020/12/28 19:05:34 2020/12/28 19:05:34 ping check Intercept
2020/12/28 19:05:34 [DEBUG] [pinger] ping check 30.067929456
2020/12/28 19:05:38 [DEBUG] [pinger] ping check 34.992124266
2020/12/28 19:05:38 2020/12/28 19:05:38 ping check Intercept
2020/12/28 19:05:43 2020/12/28 19:05:43 ping check Intercept
2020/12/28 19:05:43 [DEBUG] [pinger] ping check 40.009211112
2020/12/28 19:05:49 2020/12/28 19:05:49 ping check Intercept
2020/12/28 19:05:49 [DEBUG] [pinger] ping check 45.068973113
2020/12/28 19:05:53 2020/12/28 19:05:53 ping check Intercept
2020/12/28 19:05:53 [DEBUG] [pinger] ping check 50.019180143
2020/12/28 19:05:58 [DEBUG] [pinger] ping check 54.993858575
2020/12/28 19:05:58 2020/12/28 19:05:58 ping check Intercept
2020/12/28 19:06:03 2020/12/28 19:06:03 ping check Intercept
2020/12/28 19:06:03 [DEBUG] [pinger] ping check 60.028736356
2020/12/28 19:06:03 [CRIT] [pinger] pingresp not received, disconnecting
2020/12/28 19:06:03 [DEBUG] [client] internalConnLost called
2020/12/28 19:06:03 [DEBUG] [client] stopCommsWorkers called
2020/12/28 19:06:03 [DEBUG] [client] startCommsWorkers output redirector finnished
2020/12/28 19:06:03 [DEBUG] [client] ### startCommsWorkers #####
2020/12/28 19:06:03 [DEBUG] [net] outgoing waiting for an outbound message
2020/12/28 19:06:03 [DEBUG] [net] outgoing waiting for an outbound message
2020/12/28 19:06:03 [DEBUG] [pinger] #### keepalive c.workers.Done ####
2020/12/28 19:06:03 [DEBUG] [client] internalConnLost waiting on workers
2020/12/28 19:06:03 [DEBUG] [client] stopCommsWorkers waiting for workers
@MattBrittan MattBrittan commented on 31 Dec 2020
Thanks - unfortunately I'm not going to have time to look at this in detail before heading away. It looks like your issue is here:

2020/12/28 18:55:02 [DEBUG] [net] logic waiting for msg on ibound
2020/12/28 18:55:02 [DEBUG] [net] startIncoming Received Message
2020/12/28 18:55:02 [DEBUG] [net] startIncomingComms: got msg on ibound
2020/12/28 18:55:02 [DEBUG] [net] startIncomingComms: received publish, msgId: 0
2020/12/28 18:55:02 [DEBUG] [client] enter Publish
2020/12/28 18:55:02 [DEBUG] [client] sending publish message, topic: stf-692AFE13-0877-5F58-8B5B-949EEACFAE61/5c922e1d
2020/12/28 18:55:02 [DEBUG] [client] #####Publish c.obound: #######
The fact that logic waiting for msg on ibound is not logged again indicates that output <- incomingComms{incomingPub: m} is blocking. This would generally happen when matchAndDispatch is blocked (i.e. by the handler). I would suggest un-comenting the logging in matchAndDispatch and identifying where it is blocking.

I am guessing that you are triggering a Publish based on an incoming message. This should be fine if the handler is in a go routine but will cause a deadlock if not (your log is what I would expect to see in that case),

cant give you a demo of this.
Are you able to share source? (I'm happy to check a private repo as long as its not too convoluted).

@MattBrittan MattBrittan commented on 29 Jan
Sorry for not reviewing this again sooner. I believe that my previous analysis stands (a handler in your code is probably blocking). I have updated the documentation (in @master) to clarify this. Please try calling SetOrderMatters(false) on your ClientOptions - doing this will mean that the handlers will be called in a goroutine avoiding this kind of issue. Note that just having SetOrderMatters(true) does not guarantee in order delivery of messages (your broker would also need to be configured for this) so in most cases SetOrderMatters(false) is the best option.

@Suparerk8866 Suparerk8866 mentioned this issue 13 seconds ago
M Suparerk8866/Suparerk8866#2
Open

Leave a comment
โปรดจำไว้ว่าการมีส่วนร่วมในการเก็บข้อมูลนี้ควรเป็นไปตามของ แนวทางที่เอื้อ และ จรรยาบรรณ
ผู้รับมอบหมาย
ไม่มีใครมอบหมาย
ป้ายกำกับ
ยังไม่มี
โครงการ
ยังไม่มี
เหตุการณ์สำคัญ
ไม่มีเหตุการณ์สำคัญ
คำขอดึงที่เชื่อมโยง
การรวมคำขอดึงข้อมูลสำเร็จอาจปิดปัญหานี้ได้

ยังไม่มี
การแจ้งเตือน
ปรับแต่ง
คุณไม่ได้รับการแจ้งเตือนจากชุดข้อความนี้
ผู้เข้าร่วม 3 คน
@bartmeuris
@yunfuyiren
@MattBrittan
© 2021 GitHub, Inc.
เงื่อนไข
ความเป็นส่วนตัว
ความปลอดภัย
สถานะ
เอกสาร
ติดต่อ GitHub
ราคา
API
การฝึกอบรม
บล็อก
เกี่ยวกับ

@yunfuyiren yunfuyiren แก้ไขon 24 Dec 2020
สวัสดีพวก, ฉันใช้ sdk ไคลเอนต์นี้ตามเวอร์ชัน paho 1.3.0 เวอร์ชันโบรกเกอร์คือ mosquitto 2.0.0

นี่คือรหัสลูกค้าของฉัน

mosquittoClient := &MosquittoClient{
client: nil,
Topic: Topic,
QoS: 0,
}
userName, passWord, _ := getMqttUserNameAndPassword()
opts := mqtt.NewClientOptions().SetClientID(id).AddBroker(PROTOCAL + "://" + MQTTHOST) //.SetTLSConfig(tlsconfig)
opts.SetKeepAlive(60 * time.Second)
opts.SetWill(Topic, "the pub device has dropped off "+id, 1, true)
opts.SetAutoReconnect(true)
opts.SetCleanSession(true)
opts.SetOnConnectHandler(func(client mqtt.Client) {
log.Info("client has been connect success ")
client.Subscribe(channel, mosquittoClient.QoS, mosquittoClient.handlerFun)
log.Info("client reconnect channel: ", channel)
})
opts.SetConnectionLostHandler(func(client mqtt.Client, err error) {
log.Error("SetConnectionLostHandler has been triggered : ", err.Error())
})
opts.SetUsername(userName)
opts.SetPassword(passWord)
opts.SetDefaultPublishHandler(func(client mqtt.Client, message mqtt.Message) {
log.Info("Topic: %s\n", message.Topic())
log.Info("MSG: %s\n", message.Payload())
})
c := mqtt.NewClient(opts)
mosquittoClient.client = c
if token := c.Connect(); token.Wait() && token.Error() != nil {
//tea add alert
log.Error("mqtt connect failed: ", token.Error().Error())
go func(client mqtt.Client) {
for {
time.Sleep(10 * time.Second)
if token = client.Connect(); token.Wait() && token.Error() != nil {
continue
} else {
log.Info("Initial Reconnect to MQTT successed ")
break
}
}
}(c)
}
return mosquittoClient
แต่หลังจากนั้นไม่นานการเชื่อมต่อของ mqtt จะขาดหายไปโดยไม่มีบันทึกของฟังก์ชัน 'SetConnectionLostHandler' ฉันตรวจสอบบันทึกการแก้ไขข้อบกพร่อง
บันทึกคือ:
2020/12/20 21:08:26 [CRIT] [pinger] ไม่ได้รับ
pingresp กำลังตัดการเชื่อมต่อ2020/12/20 21:08:26 [DEBUG] [ไคลเอนต์] internalConnLost เรียกว่า
2020/12/20 21:08 : 26 [แก้ปัญหา] [ไคลเอนต์] stopCommsWorkers เรียกว่า
2020/12/20 21:08:26 [DEBUG] [ไคลเอนต์] ตัวเปลี่ยนเส้นทางเอาต์พุต
startCommsWorkers สิ้นสุด 2020/12/20 21:08:26 [DEBUG] [net] ขาออกกำลังรอ ข้อความขาออก
2020/12/20 21:08:26 [DEBUG] [net] ขา
ออกกำลังรอข้อความขาออก2020/12/20 21:08:26 [แก้ปัญหา] [ลูกค้า] internalConnLost รอคนงาน
2020/12/20 21:08:26 [แก้ปัญหา] [ลูกค้า] stopCommsWorkers กำลังรอคนงาน

ร่างกายใดช่วยฉันได้บ้างว่าการหยุดชะงักเกิดขึ้นได้อย่างไรและจะแก้ไขได้อย่างไร

ร่างกายใดช่วยฉันได้บ้างว่าการหยุดชะงักเกิดขึ้นได้อย่างไรและจะแก้ไขได้อย่างไร @MattBrittanทำตามคำแนะนำของคุณใน # 453 ฉันแจ้งปัญหาใหม่และขอความช่วยเหลือจากคุณ

@MattBrittan
Copy link
Contributor

Closing this issue due to inactivity (it appears likely that the issue is in the handlers but there is insufficient info to confirm this). No idea what the comment from @Suparerk8866 is...

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

4 participants