Re: [paho-dev] Varying Delay for MQTT Messages

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index] [List Home]

Re: [paho-dev] Varying Delay for MQTT Messages

From: Frank Pagliughi <fpagliughi@xxxxxxxxxxxxxx>
Date: Fri, 30 Jan 2015 17:23:00 -0500
Delivered-to: paho-dev@xxxxxxxxxxx
List-archive: <https://dev.eclipse.org/mailman/private/paho-dev>
List-help: <mailto:paho-dev-request@eclipse.org?subject=help>
List-subscribe: <https://dev.eclipse.org/mailman/listinfo/paho-dev>, <mailto:paho-dev-request@eclipse.org?subject=subscribe>
List-unsubscribe: <https://dev.eclipse.org/mailman/options/paho-dev>, <mailto:paho-dev-request@eclipse.org?subject=unsubscribe>
User-agent: Mozilla/5.0 (X11; Linux x86_64; rv:31.0) Gecko/20100101 Thunderbird/31.3.0

Hello Ian,

Sorry for the delay on this. Earlier this week a very large pile of snow developed between where I was and where my laptop was.

I made a slight modification to the MQTTAsync_publish sample app so that when a transfer is completed another message is sent immediately, but I was seeing about a second between each message.

The 'running' variable is now an int counting down the number of messages to send, five in this case. The normal output would be:

$ build/output/samples/MQTTAsync_publish
Waiting for publication of 'Hello World!'
on topic 'MQTT Examples' for client with ClientID: ExampleClientPub
Successful connection
Sent message with token value 1
Message with token value 1 delivery confirmed
Sent message with token value 2
Message with token value 2 delivery confirmed
Sent message with token value 3
Message with token value 3 delivery confirmed
Sent message with token value 4
Message with token value 4 delivery confirmed
Sent message with token value 5
Message with token value 5 delivery confirmed

Attached is the source and log. According to the log, it seems that the delay I noticed turned out to be exactly 1sec in a persistence "put" call despite MQTTCLIENT_PERSISTENCE_NONE being specified? This is ~Line 411 in the log and repeats for each message sent.

20150130 170213.898 (3380758272)    (3)> MQTTProtocol_startPublishCommon:124
20150130 170213.898 (3380758272)     (4)> MQTTPacket_send_publish:677
20150130 170213.898 (3380758272)      (5)> MQTTPacket_sends:226
20150130 170213.898 (3380758272)       (6)> MQTTPacket_encode:268
20150130 170213.898 (3380758272)       (6)< MQTTPacket_encode:278 (1)
20150130 170213.898 (3380758272)       (6)> MQTTPersistence_put:347
20150130 170213.898 (3380758272)       (6)< MQTTPersistence_put:381 (0)    <------ Here -----
20150130 170214.898 (3380758272)       (6)> Socket_putdatas:443
20150130 170214.898 (3380758272)        (7)> Socket_writev:399
20150130 170214.898 (3380758272)        (7)< Socket_writev:420 (31)
20150130 170214.898 (3380758272)       (6)< Socket_putdatas:485 (0)
20150130 170214.898 (3380758272)      (5)< MQTTPacket_sends:253 (0)
20150130 170214.898 3 ExampleClientPub -> PUBLISH msgid: 1 qos: 1 retained: 0 (0) payload: Hello World!

This was run on a ThinkPad i7 laptop running Linux Mint13, x86_64.

Thanks,
Frank

On 01/28/2015 08:29 AM, Ian Craggs wrote:

Hi Chris,

I was hoping for a full trace. This seems to be just a protocol level trace?

Ian

On 01/27/2015 03:07 PM, Chris Summer wrote:
Hi Ian,

0) I am using the MQTTAsyncAPI with callbacks. I am processing the incoming messages within the MessageArrived Callback Function. I did an implementation using the MQTTClient, then there is no such effect.

1) Is turned off

2) Find tracefile in the attachement

Thanks a lot!
Chris
Date: Mon, 26 Jan 2015 14:00:35 -0500
From: fpagliughi@xxxxxxxxxxxxxx
To: paho-dev@xxxxxxxxxxx
Subject: Re: [paho-dev] Varying Delay for MQTT Messages

Hi Ian,

I saw a strange delay of about 1-sec in the latest Asynhronous C library. I had modified the publisher example app to send several messages; sending the next as soon as one is acknowledged (QoS=1). I ran it all on the same machine over localhost, talking to mosquitto. The timing seemed odd, but I haven't had time to investigate further yet.

I will see I can recreate the test app and send it to you ASAP.

Frank

On 01/26/2015 08:12 AM, Ian Craggs wrote:
Hi Chris,

are you using the MQTTClient or MQTTAsync API? If MQTTClient, are you setting callbacks? I think it's most likely that the timing differences are an artifact of the threading model. With MQTTClient, if you use the receive call rather than the messageArrived callback, no background threads are started.

1) make sure you have turned off message persistence when creating the client object (MQTTCLIENT_PERSISTENCE_NONE). This shouldn't be used for QoS 0, but might have an effect.

2) You can take a trace by setting the environment variable MQTT_C_CLIENT_TRACE=(ON or filename), and then I can check to see what is happening.

3) Other client options for C/C++ are the Paho embedded clients and libmosquitto in the Mosquitto project, which follows the same API model as the Python API because they are both written by Roger Light. I'd like to see if we can understand and solve your problem first though -- so please take a trace.

Thanks

Ian

On 01/26/2015 10:23 AM, Chris Summer wrote:
Hi all,

I am experiencing some behavior I cannot explain.

Here is what I do.

I am using the paho-c library and as a reference the paho python library. My Broker is mosquitto.

The goal of my experiments is to measure the application layer roundtrip time. Therefore I have the following setup

Application <----> Broker <---> Reflector

What I do is:

* I take the time in the application, put it into a packet and send it to the broker. (QoS 0)
* The reflector is subscribed to theses messages, receives them, packs them into a new packet and sends the back to the broker using a different topic.
* Finally I receive the message back at the application, take the current time and calculate the time difference between the current time and the time contained in the packet.

I have this implementation, both in C and in Python. All processes are running on the same machine.

No here are the observations that keep me busy.

If I watch the application delay for the c implementation I get something like
5, 1005, 106, 5, 1005, 104, 6 ...

For the python implementation it is like:
5, 5, 5, 6, 4, ....

You see the difference, unfortunately I need an implementation in C thanks to the target platform. I checked my code several times, there is nothing I could pinpoint to cause the delay.

To me, it resembles effects that I have seen in other projects when using TCP. Could it be, that somewhere in the library code there is some issue with the socket handling?

Any other ideas? Did I miss a configuration flag or something?

Cheers,

Chris
_______________________________________________
paho-dev mailing list
paho-dev@xxxxxxxxxxx
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/paho-dev
-- 
Ian Craggs                          
icraggs@xxxxxxxxxx                 IBM United Kingdom
Paho Project Lead; Committer on Mosquitto
_______________________________________________
paho-dev mailing list
paho-dev@xxxxxxxxxxx
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/paho-dev
_______________________________________________ paho-dev mailing list paho-dev@xxxxxxxxxxx To change your delivery options, retrieve your password, or unsubscribe from this list, visit https://dev.eclipse.org/mailman/listinfo/paho-dev
_______________________________________________
paho-dev mailing list
paho-dev@xxxxxxxxxxx
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/paho-dev
-- 
Ian Craggs                          
icraggs@xxxxxxxxxx                 IBM United Kingdom
Paho Project Lead; Committer on Mosquitto
_______________________________________________
paho-dev mailing list
paho-dev@xxxxxxxxxxx
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/paho-dev

/*******************************************************************************
 * Copyright (c) 2012, 2013 IBM Corp.
 *
 * All rights reserved. This program and the accompanying materials
 * are made available under the terms of the Eclipse Public License v1.0
 * and Eclipse Distribution License v1.0 which accompany this distribution. 
 *
 * The Eclipse Public License is available at 
 *   http://www.eclipse.org/legal/epl-v10.html
 * and the Eclipse Distribution License is available at 
 *   http://www.eclipse.org/org/documents/edl-v10.php.
 *
 * Contributors:
 *    Ian Craggs - initial contribution
 *******************************************************************************/

#include "stdio.h"
#include "stdlib.h"
#include "string.h"
#include "MQTTAsync.h"

#if !defined(WIN32)
#include <unistd.h>
#endif

//#define ADDRESS     "tcp://m2m.eclipse.org:1883"
#define ADDRESS     "tcp://localhost:1883"
#define CLIENTID    "ExampleClientPub"
#define TOPIC       "MQTT Examples"
#define PAYLOAD     "Hello World!"
#define QOS         1
#define TIMEOUT     10000L

volatile MQTTAsync_token deliveredtoken;

volatile int running = 5;
void sendMessage(MQTTAsync client);

void connlost(void *context, char *cause)
{
	MQTTAsync client = (MQTTAsync)context;
	MQTTAsync_connectOptions conn_opts = MQTTAsync_connectOptions_initializer;
	int rc;

	printf("\nConnection lost\n");
	printf("     cause: %s\n", cause);

	printf("Reconnecting\n");
	conn_opts.keepAliveInterval = 20;
	conn_opts.cleansession = 1;
	if ((rc = MQTTAsync_connect(client, &conn_opts)) != MQTTASYNC_SUCCESS)
	{
		printf("Failed to start connect, return code %d\n", rc);
 		running = 0;
	}
}

int msgarrvd(void *context, char *topicName, int topicLen, MQTTAsync_message *message)
{
    int i;
    char* payloadptr;

    printf("Message arrived\n");
    printf("     topic: %s\n", topicName);
    printf("   message: ");

    payloadptr = message->payload;
    for(i=0; i<message->payloadlen; i++)
    {
        putchar(*payloadptr++);
    }
    putchar('\n');
    MQTTAsync_freeMessage(&message);
    MQTTAsync_free(topicName);
    return 1;
}

void onDisconnect(void* context, MQTTAsync_successData* response)
{
	printf("Successful disconnection\n");
	running = 0;
}


void onSend(void* context, MQTTAsync_successData* response)
{
	MQTTAsync client = (MQTTAsync)context;
	MQTTAsync_disconnectOptions opts = MQTTAsync_disconnectOptions_initializer;
	int rc;

	printf("Message with token value %d delivery confirmed\n", response->token);

	if (--running >= 1) {
		sendMessage(client);
	}
	else {
		opts.onSuccess = onDisconnect;
		opts.context = client;

		if ((rc = MQTTAsync_disconnect(client, &opts)) != MQTTASYNC_SUCCESS)
		{
			printf("Failed to start sendMessage, return code %d\n", rc);
			exit(-1);	
		}
	}
}


void onConnectFailure(void* context, MQTTAsync_failureData* response)
{
	printf("Connect failed, rc %d\n", response ? response->code : 0);
	running = 0;
}

void sendMessage(MQTTAsync client)
{
	int rc;
	MQTTAsync_responseOptions opts = MQTTAsync_responseOptions_initializer;
	MQTTAsync_message pubmsg = MQTTAsync_message_initializer;

	opts.onSuccess = onSend;
	opts.context = client;

	pubmsg.payload = PAYLOAD;
	pubmsg.payloadlen = strlen(PAYLOAD);
	pubmsg.qos = QOS;
	pubmsg.retained = 0;
	deliveredtoken = 0;

	if ((rc = MQTTAsync_sendMessage(client, TOPIC, &pubmsg, &opts)) != MQTTASYNC_SUCCESS)
	{
		printf("Failed to start sendMessage, return code %d\n", rc);
 		exit(1);	
	}
	else {
		printf("Sent message with token value %d\n", (int) opts.token);
	}
}


void onConnect(void* context, MQTTAsync_successData* response)
{
	MQTTAsync client = (MQTTAsync)context;
	printf("Successful connection\n");
	sendMessage(client);
}

int main(int argc, char* argv[])
{
	MQTTAsync client;
	MQTTAsync_connectOptions conn_opts = MQTTAsync_connectOptions_initializer;
	MQTTAsync_message pubmsg = MQTTAsync_message_initializer;
	MQTTAsync_token token;
	int rc;

	MQTTAsync_create(&client, ADDRESS, CLIENTID, MQTTCLIENT_PERSISTENCE_NONE, NULL);

	MQTTAsync_setCallbacks(client, NULL, connlost, msgarrvd, NULL);

	conn_opts.keepAliveInterval = 20;
	conn_opts.cleansession = 1;
	conn_opts.onSuccess = onConnect;
	conn_opts.onFailure = onConnectFailure;
	conn_opts.context = client;
	if ((rc = MQTTAsync_connect(client, &conn_opts)) != MQTTASYNC_SUCCESS)
	{
		printf("Failed to start connect, return code %d\n", rc);
		exit(-1);	
	}

	printf("Waiting for publication of '%s'\n"
         "on topic '%s' for client with ClientID: %s\n",
         PAYLOAD, TOPIC, CLIENTID);

	while (running) {
		#if defined(WIN32)
			Sleep(100);
		#else
			usleep(10000L);
		#endif
	}

	MQTTAsync_destroy(&client);
 	return rc;
}

=========================================================
                   Trace Output
Product name: Paho Asynchronous MQTT C Client Library
Version: ##MQTTCLIENT_VERSION_TAG##
Build level: ##MQTTCLIENT_BUILD_TAG##
/proc/version: Linux version 3.2.0-70-generic (buildd@tipua) (gcc version 4.6.3 (Ubuntu/Linaro 4.6.3-1ubuntu5) ) #105-Ubuntu SMP Wed Sep 24 19:49:16 UTC 2014

=========================================================
19691231 190000.000 (3391796992)  (1)> Socket_outInitialize:120
19691231 190000.000 (3391796992)   (2)> SocketBuffer_initialize:85
19691231 190000.000 (3391796992)   (2)< SocketBuffer_initialize:89
19691231 190000.000 (3391796992)  (1)< Socket_outInitialize:133
19691231 190000.000 (3391796992)  (1)> MQTTStrncpy:736
19691231 190000.000 (3391796992)  (1)< MQTTStrncpy:746
19691231 190000.000 (3391796992)  (1)> MQTTStrncpy:736
19691231 190000.000 (3391796992)  (1)< MQTTStrncpy:746
19691231 190000.000 (3391796992)  (1)> MQTTPersistence_create:48
19691231 190000.000 (3391796992)  (1)< MQTTPersistence_create:94 (0)
19691231 190000.000 (3391796992)  (1)> MQTTPersistence_initialize:109
19691231 190000.000 (3391796992)  (1)< MQTTPersistence_initialize:117 (0)
19691231 190000.000 (3391796992)  (1)> MQTTAsync_restoreCommands:695
19691231 190000.000 0 commands restored for client ExampleClientPub
19691231 190000.000 (3391796992)  (1)< MQTTAsync_restoreCommands:727 (0)
19691231 190000.000 (3391796992)  (1)> MQTTPersistence_restoreMessageQueue:609
19691231 190000.000 0 queued messages restored for client ExampleClientPub
19691231 190000.000 (3391796992)  (1)< MQTTPersistence_restoreMessageQueue:640 (0)
19691231 190000.000 (3391796992) (0)< MQTTAsync_create:433 (0)
20150130 170211.891 (3391796992) (0)> MQTTAsync_setCallbacks:1742
20150130 170211.891 (3391796992) (0)< MQTTAsync_setCallbacks:1756 (0)
20150130 170211.891 (3391796992) (0)> MQTTAsync_connect:1920
20150130 170211.891 (3391796992)  (1)> Thread_start:65
20150130 170211.891 (3391796992)  (1)< Thread_start:75
20150130 170211.891 (3391796992)  (1)> Thread_start:65
20150130 170211.891 (3380758272) (0)> MQTTAsync_sendThread:1257
20150130 170211.891 (3391796992)  (1)< Thread_start:75
20150130 170211.891 (3391796992)  (1)> MQTTAsync_addCommand:737
20150130 170211.891 (3380758272)  (1)> Thread_wait_cond:402
20150130 170211.891 (3391796992)  (1)< MQTTAsync_addCommand:768 (0)
20150130 170211.891 (3391796992) (0)< MQTTAsync_connect:2072 (0)
Waiting for publication of 'Hello World!'
on topic 'MQTT Examples' for client with ClientID: ExampleClientPub
20150130 170211.891 (3372365568) (0)> MQTTAsync_receiveThread:1459
20150130 170211.891 (3372365568)  (1)> MQTTAsync_cycle:2563
20150130 170211.891 (3372365568)   (2)> Socket_getReadySocket:216
20150130 170211.891 (3372365568)   (2)< Socket_getReadySocket:282 (0)
20150130 170211.891 (3372365568)   (2)> MQTTAsync_sleep:305
20150130 170211.891 (3372365568)   (2)< MQTTAsync_sleep:311
20150130 170211.891 (3372365568)   (2)> MQTTAsync_retry:2430
20150130 170211.891 (3372365568)    (3)> MQTTProtocol_keepalive:512
20150130 170211.992 (3372365568)    (3)< MQTTProtocol_keepalive:545
20150130 170211.992 (3372365568)    (3)> MQTTProtocol_retry:629
20150130 170211.992 (3372365568)    (3)< MQTTProtocol_retry:648
20150130 170211.992 (3372365568)   (2)< MQTTAsync_retry:2440
20150130 170211.992 (3372365568)  (1)< MQTTAsync_cycle:2699 (-1)
20150130 170211.992 (3372365568)  (1)> MQTTAsync_cycle:2563
20150130 170211.992 (3372365568)   (2)> Socket_getReadySocket:216
20150130 170211.992 (3372365568)   (2)< Socket_getReadySocket:282 (0)
20150130 170211.992 (3372365568)   (2)> MQTTAsync_sleep:305
20150130 170211.992 (3372365568)   (2)< MQTTAsync_sleep:311
20150130 170211.992 (3372365568)   (2)> MQTTAsync_retry:2430
20150130 170211.992 (3372365568)    (3)> MQTTProtocol_retry:629
20150130 170211.992 (3372365568)    (3)< MQTTProtocol_retry:648
20150130 170211.992 (3372365568)   (2)< MQTTAsync_retry:2440
20150130 170211.992 (3372365568)  (1)< MQTTAsync_cycle:2699 (-1)
20150130 170211.992 (3372365568)  (1)> MQTTAsync_cycle:2563
20150130 170211.992 (3372365568)   (2)> Socket_getReadySocket:216
20150130 170211.992 (3372365568)   (2)< Socket_getReadySocket:282 (0)
20150130 170211.992 (3372365568)   (2)> MQTTAsync_sleep:305
20150130 170211.992 (3372365568)   (2)< MQTTAsync_sleep:311
20150130 170212.193 (3372365568)   (2)> MQTTAsync_retry:2430
20150130 170212.193 (3372365568)    (3)> MQTTProtocol_retry:629
20150130 170212.193 (3372365568)    (3)< MQTTProtocol_retry:648
20150130 170212.193 (3372365568)   (2)< MQTTAsync_retry:2440
20150130 170212.193 (3372365568)  (1)< MQTTAsync_cycle:2699 (-1)
20150130 170212.193 (3372365568)  (1)> MQTTAsync_cycle:2563
20150130 170212.193 (3372365568)   (2)> Socket_getReadySocket:216
20150130 170212.193 (3372365568)   (2)< Socket_getReadySocket:282 (0)
20150130 170212.193 (3372365568)   (2)> MQTTAsync_sleep:305
20150130 170212.193 (3372365568)   (2)< MQTTAsync_sleep:311
20150130 170212.193 (3372365568)   (2)> MQTTAsync_retry:2430
20150130 170212.193 (3372365568)    (3)> MQTTProtocol_retry:629
20150130 170212.193 (3372365568)    (3)< MQTTProtocol_retry:648
20150130 170212.193 (3372365568)   (2)< MQTTAsync_retry:2440
20150130 170212.193 (3372365568)  (1)< MQTTAsync_cycle:2699 (-1)
20150130 170212.193 (3372365568)  (1)> MQTTAsync_cycle:2563
20150130 170212.193 (3372365568)   (2)> Socket_getReadySocket:216
20150130 170212.193 (3372365568)   (2)< Socket_getReadySocket:282 (0)
20150130 170212.193 (3372365568)   (2)> MQTTAsync_sleep:305
20150130 170212.193 (3372365568)   (2)< MQTTAsync_sleep:311
20150130 170212.394 (3372365568)   (2)> MQTTAsync_retry:2430
20150130 170212.394 (3372365568)    (3)> MQTTProtocol_retry:629
20150130 170212.394 (3372365568)    (3)< MQTTProtocol_retry:648
20150130 170212.394 (3372365568)   (2)< MQTTAsync_retry:2440
20150130 170212.394 (3372365568)  (1)< MQTTAsync_cycle:2699 (-1)
20150130 170212.394 (3372365568)  (1)> MQTTAsync_cycle:2563
20150130 170212.394 (3372365568)   (2)> Socket_getReadySocket:216
20150130 170212.394 (3372365568)   (2)< Socket_getReadySocket:282 (0)
20150130 170212.394 (3372365568)   (2)> MQTTAsync_sleep:305
20150130 170212.394 (3372365568)   (2)< MQTTAsync_sleep:311
20150130 170212.394 (3372365568)   (2)> MQTTAsync_retry:2430
20150130 170212.394 (3372365568)    (3)> MQTTProtocol_retry:629
20150130 170212.394 (3372365568)    (3)< MQTTProtocol_retry:648
20150130 170212.394 (3372365568)   (2)< MQTTAsync_retry:2440
20150130 170212.394 (3372365568)  (1)< MQTTAsync_cycle:2699 (-1)
20150130 170212.394 (3372365568)  (1)> MQTTAsync_cycle:2563
20150130 170212.394 (3372365568)   (2)> Socket_getReadySocket:216
20150130 170212.394 (3372365568)   (2)< Socket_getReadySocket:282 (0)
20150130 170212.394 (3372365568)   (2)> MQTTAsync_sleep:305
20150130 170212.394 (3372365568)   (2)< MQTTAsync_sleep:311
20150130 170212.594 (3372365568)   (2)> MQTTAsync_retry:2430
20150130 170212.594 (3372365568)    (3)> MQTTProtocol_retry:629
20150130 170212.594 (3372365568)    (3)< MQTTProtocol_retry:648
20150130 170212.594 (3372365568)   (2)< MQTTAsync_retry:2440
20150130 170212.594 (3372365568)  (1)< MQTTAsync_cycle:2699 (-1)
20150130 170212.594 (3372365568)  (1)> MQTTAsync_cycle:2563
20150130 170212.594 (3372365568)   (2)> Socket_getReadySocket:216
20150130 170212.594 (3372365568)   (2)< Socket_getReadySocket:282 (0)
20150130 170212.594 (3372365568)   (2)> MQTTAsync_sleep:305
20150130 170212.594 (3372365568)   (2)< MQTTAsync_sleep:311
20150130 170212.594 (3372365568)   (2)> MQTTAsync_retry:2430
20150130 170212.594 (3372365568)    (3)> MQTTProtocol_retry:629
20150130 170212.594 (3372365568)    (3)< MQTTProtocol_retry:648
20150130 170212.594 (3372365568)   (2)< MQTTAsync_retry:2440
20150130 170212.594 (3372365568)  (1)< MQTTAsync_cycle:2699 (-1)
20150130 170212.594 (3372365568)  (1)> MQTTAsync_cycle:2563
20150130 170212.594 (3372365568)   (2)> Socket_getReadySocket:216
20150130 170212.594 (3372365568)   (2)< Socket_getReadySocket:282 (0)
20150130 170212.594 (3372365568)   (2)> MQTTAsync_sleep:305
20150130 170212.594 (3372365568)   (2)< MQTTAsync_sleep:311
20150130 170212.795 (3372365568)   (2)> MQTTAsync_retry:2430
20150130 170212.795 (3372365568)    (3)> MQTTProtocol_retry:629
20150130 170212.795 (3372365568)    (3)< MQTTProtocol_retry:648
20150130 170212.795 (3372365568)   (2)< MQTTAsync_retry:2440
20150130 170212.795 (3372365568)  (1)< MQTTAsync_cycle:2699 (-1)
20150130 170212.795 (3372365568)  (1)> MQTTAsync_cycle:2563
20150130 170212.795 (3372365568)   (2)> Socket_getReadySocket:216
20150130 170212.795 (3372365568)   (2)< Socket_getReadySocket:282 (0)
20150130 170212.795 (3372365568)   (2)> MQTTAsync_sleep:305
20150130 170212.795 (3380758272)  (1)< Thread_wait_cond:416 (110)
20150130 170212.795 (3380758272)  (1)> Thread_wait_cond:402
20150130 170212.795 (3372365568)   (2)< MQTTAsync_sleep:311
20150130 170212.795 (3372365568)   (2)> MQTTAsync_retry:2430
20150130 170212.795 (3372365568)    (3)> MQTTProtocol_retry:629
20150130 170212.795 (3372365568)    (3)< MQTTProtocol_retry:648
20150130 170212.795 (3372365568)   (2)< MQTTAsync_retry:2440
20150130 170212.795 (3372365568)  (1)< MQTTAsync_cycle:2699 (-1)
20150130 170212.795 (3372365568)  (1)> MQTTAsync_cycle:2563
20150130 170212.795 (3372365568)   (2)> Socket_getReadySocket:216
20150130 170212.795 (3372365568)   (2)< Socket_getReadySocket:282 (0)
20150130 170212.895 (3372365568)   (2)> MQTTAsync_sleep:305
20150130 170212.895 (3372365568)   (2)< MQTTAsync_sleep:311
20150130 170212.895 (3372365568)   (2)> MQTTAsync_retry:2430
20150130 170212.895 (3372365568)    (3)> MQTTProtocol_retry:629
20150130 170212.895 (3372365568)    (3)< MQTTProtocol_retry:648
20150130 170212.895 (3372365568)   (2)< MQTTAsync_retry:2440
20150130 170212.895 (3372365568)  (1)< MQTTAsync_cycle:2699 (-1)
20150130 170212.895 (3372365568)  (1)> MQTTAsync_cycle:2563
20150130 170212.895 (3372365568)   (2)> Socket_getReadySocket:216
20150130 170212.895 (3372365568)   (2)< Socket_getReadySocket:282 (0)
20150130 170212.895 (3372365568)   (2)> MQTTAsync_sleep:305
20150130 170212.895 (3372365568)   (2)< MQTTAsync_sleep:311
20150130 170212.895 (3372365568)   (2)> MQTTAsync_retry:2430
20150130 170212.895 (3372365568)    (3)> MQTTProtocol_retry:629
20150130 170212.895 (3372365568)    (3)< MQTTProtocol_retry:648
20150130 170212.895 (3372365568)   (2)< MQTTAsync_retry:2440
20150130 170212.895 (3372365568)  (1)< MQTTAsync_cycle:2699 (-1)
20150130 170212.895 (3372365568)  (1)> MQTTAsync_cycle:2563
20150130 170212.895 (3372365568)   (2)> Socket_getReadySocket:216
20150130 170212.895 (3372365568)   (2)< Socket_getReadySocket:282 (0)
20150130 170213.096 (3372365568)   (2)> MQTTAsync_sleep:305
20150130 170213.096 (3372365568)   (2)< MQTTAsync_sleep:311
20150130 170213.096 (3372365568)   (2)> MQTTAsync_retry:2430
20150130 170213.096 (3372365568)    (3)> MQTTProtocol_retry:629
20150130 170213.096 (3372365568)    (3)< MQTTProtocol_retry:648
20150130 170213.096 (3372365568)   (2)< MQTTAsync_retry:2440
20150130 170213.096 (3372365568)  (1)< MQTTAsync_cycle:2699 (-1)
20150130 170213.096 (3372365568)  (1)> MQTTAsync_cycle:2563
20150130 170213.096 (3372365568)   (2)> Socket_getReadySocket:216
20150130 170213.096 (3372365568)   (2)< Socket_getReadySocket:282 (0)
20150130 170213.096 (3372365568)   (2)> MQTTAsync_sleep:305
20150130 170213.096 (3372365568)   (2)< MQTTAsync_sleep:311
20150130 170213.096 (3372365568)   (2)> MQTTAsync_retry:2430
20150130 170213.096 (3372365568)    (3)> MQTTProtocol_retry:629
20150130 170213.096 (3372365568)    (3)< MQTTProtocol_retry:648
20150130 170213.096 (3372365568)   (2)< MQTTAsync_retry:2440
20150130 170213.096 (3372365568)  (1)< MQTTAsync_cycle:2699 (-1)
20150130 170213.096 (3372365568)  (1)> MQTTAsync_cycle:2563
20150130 170213.096 (3372365568)   (2)> Socket_getReadySocket:216
20150130 170213.096 (3372365568)   (2)< Socket_getReadySocket:282 (0)
20150130 170213.296 (3372365568)   (2)> MQTTAsync_sleep:305
20150130 170213.296 (3372365568)   (2)< MQTTAsync_sleep:311
20150130 170213.296 (3372365568)   (2)> MQTTAsync_retry:2430
20150130 170213.296 (3372365568)    (3)> MQTTProtocol_retry:629
20150130 170213.296 (3372365568)    (3)< MQTTProtocol_retry:648
20150130 170213.296 (3372365568)   (2)< MQTTAsync_retry:2440
20150130 170213.296 (3372365568)  (1)< MQTTAsync_cycle:2699 (-1)
20150130 170213.296 (3372365568)  (1)> MQTTAsync_cycle:2563
20150130 170213.296 (3372365568)   (2)> Socket_getReadySocket:216
20150130 170213.296 (3372365568)   (2)< Socket_getReadySocket:282 (0)
20150130 170213.296 (3372365568)   (2)> MQTTAsync_sleep:305
20150130 170213.296 (3372365568)   (2)< MQTTAsync_sleep:311
20150130 170213.296 (3372365568)   (2)> MQTTAsync_retry:2430
20150130 170213.296 (3372365568)    (3)> MQTTProtocol_retry:629
20150130 170213.296 (3372365568)    (3)< MQTTProtocol_retry:648
20150130 170213.296 (3372365568)   (2)< MQTTAsync_retry:2440
20150130 170213.296 (3372365568)  (1)< MQTTAsync_cycle:2699 (-1)
20150130 170213.296 (3372365568)  (1)> MQTTAsync_cycle:2563
20150130 170213.296 (3372365568)   (2)> Socket_getReadySocket:216
20150130 170213.296 (3372365568)   (2)< Socket_getReadySocket:282 (0)
20150130 170213.496 (3372365568)   (2)> MQTTAsync_sleep:305
20150130 170213.496 (3372365568)   (2)< MQTTAsync_sleep:311
20150130 170213.496 (3372365568)   (2)> MQTTAsync_retry:2430
20150130 170213.496 (3372365568)    (3)> MQTTProtocol_retry:629
20150130 170213.496 (3372365568)    (3)< MQTTProtocol_retry:648
20150130 170213.496 (3372365568)   (2)< MQTTAsync_retry:2440
20150130 170213.496 (3372365568)  (1)< MQTTAsync_cycle:2699 (-1)
20150130 170213.496 (3372365568)  (1)> MQTTAsync_cycle:2563
20150130 170213.496 (3372365568)   (2)> Socket_getReadySocket:216
20150130 170213.496 (3372365568)   (2)< Socket_getReadySocket:282 (0)
20150130 170213.496 (3372365568)   (2)> MQTTAsync_sleep:305
20150130 170213.496 (3372365568)   (2)< MQTTAsync_sleep:311
20150130 170213.496 (3372365568)   (2)> MQTTAsync_retry:2430
20150130 170213.496 (3372365568)    (3)> MQTTProtocol_retry:629
20150130 170213.496 (3372365568)    (3)< MQTTProtocol_retry:648
20150130 170213.496 (3372365568)   (2)< MQTTAsync_retry:2440
20150130 170213.496 (3372365568)  (1)< MQTTAsync_cycle:2699 (-1)
20150130 170213.496 (3372365568)  (1)> MQTTAsync_cycle:2563
20150130 170213.496 (3372365568)   (2)> Socket_getReadySocket:216
20150130 170213.496 (3372365568)   (2)< Socket_getReadySocket:282 (0)
20150130 170213.697 (3372365568)   (2)> MQTTAsync_sleep:305
20150130 170213.697 (3372365568)   (2)< MQTTAsync_sleep:311
20150130 170213.697 (3372365568)   (2)> MQTTAsync_retry:2430
20150130 170213.697 (3372365568)    (3)> MQTTProtocol_retry:629
20150130 170213.697 (3372365568)    (3)< MQTTProtocol_retry:648
20150130 170213.697 (3372365568)   (2)< MQTTAsync_retry:2440
20150130 170213.697 (3372365568)  (1)< MQTTAsync_cycle:2699 (-1)
20150130 170213.697 (3372365568)  (1)> MQTTAsync_cycle:2563
20150130 170213.697 (3372365568)   (2)> Socket_getReadySocket:216
20150130 170213.697 (3372365568)   (2)< Socket_getReadySocket:282 (0)
20150130 170213.697 (3372365568)   (2)> MQTTAsync_sleep:305
20150130 170213.697 (3380758272)  (1)< Thread_wait_cond:416 (110)
20150130 170213.697 (3380758272)  (1)> MQTTAsync_checkTimeouts:1179
20150130 170213.697 (3380758272)  (1)< MQTTAsync_checkTimeouts:1251
20150130 170213.697 (3380758272)  (1)> MQTTAsync_processCommand:937
20150130 170213.697 Connecting to serverURI localhost:1883 with MQTT version 4
20150130 170213.697 (3380758272)   (2)> MQTTProtocol_connect:93
20150130 170213.697 (3380758272)    (3)> MQTTProtocol_addressPort:50
20150130 170213.697 (3380758272)     (4)> MQTTStrncpy:736
20150130 170213.697 the src string is truncated
20150130 170213.892 (3380758272)     (4)< MQTTStrncpy:746
20150130 170213.892 (3380758272)    (3)< MQTTProtocol_addressPort:71
20150130 170213.892 (3380758272)    (3)> Socket_new:601
20150130 170213.892 New socket 3 for localhost, port 1883
20150130 170213.892 (3380758272)     (4)> Socket_addSocket:162
20150130 170213.892 (3380758272)      (5)> Socket_setnonblocking:72
20150130 170213.892 (3380758272)      (5)< Socket_setnonblocking:77 (0)
20150130 170213.892 (3380758272)     (4)< Socket_addSocket:175 (0)
20150130 170213.892 (3380758272)     (4)> Socket_error:94
20150130 170213.892 (3380758272)     (4)< Socket_error:103 (115)
20150130 170213.892 Connect pending
20150130 170213.892 (3380758272)    (3)< Socket_new:688 (115)
20150130 170213.892 (3380758272)   (2)< MQTTProtocol_connect:128 (115)
20150130 170213.892 (3380758272)  (1)< MQTTAsync_processCommand:1169
20150130 170213.892 (3380758272)  (1)> Thread_wait_cond:402
20150130 170213.892 (3372365568)   (2)< MQTTAsync_sleep:311
20150130 170213.892 (3372365568)   (2)> MQTTAsync_retry:2430
20150130 170213.892 (3372365568)    (3)> MQTTProtocol_retry:629
20150130 170213.892 (3372365568)    (3)< MQTTProtocol_retry:648
20150130 170213.892 (3372365568)   (2)< MQTTAsync_retry:2440
20150130 170213.897 (3372365568)  (1)< MQTTAsync_cycle:2699 (-1)
20150130 170213.897 (3372365568)  (1)> MQTTAsync_cycle:2563
20150130 170213.897 (3372365568)   (2)> Socket_getReadySocket:216
20150130 170213.897 (3372365568)    (3)> Socket_continueWrites:777
20150130 170213.897 (3372365568)    (3)< Socket_continueWrites:799 (0)
20150130 170213.897 (3372365568)    (3)> isReady:192
20150130 170213.897 (3372365568)    (3)< isReady:197 (1)
20150130 170213.897 (3372365568)   (2)< Socket_getReadySocket:282 (3)
20150130 170213.897 (3372365568)   (2)> MQTTAsync_connecting:2448
20150130 170213.897 (3372365568)    (3)> MQTTPacket_send_connect:50
20150130 170213.897 (3372365568)     (4)> MQTTPacket_send:180
20150130 170213.897 (3372365568)      (5)> MQTTPacket_encode:268
20150130 170213.897 (3372365568)      (5)< MQTTPacket_encode:278 (1)
20150130 170213.897 (3372365568)      (5)> Socket_putdatas:443
20150130 170213.897 (3372365568)       (6)> Socket_writev:399
20150130 170213.897 (3372365568)       (6)< Socket_writev:420 (30)
20150130 170213.897 (3372365568)      (5)< Socket_putdatas:485 (0)
20150130 170213.897 (3372365568)     (4)< MQTTPacket_send:207 (0)
20150130 170213.897 3 ExampleClientPub -> CONNECT cleansession: 1 (0)
20150130 170213.897 (3372365568)    (3)< MQTTPacket_send_connect:108 (0)
20150130 170213.897 (3372365568)   (2)< MQTTAsync_connecting:2551 (0)
20150130 170213.897 (3372365568)   (2)> MQTTAsync_retry:2430
20150130 170213.897 (3372365568)    (3)> MQTTProtocol_retry:629
20150130 170213.897 (3372365568)    (3)< MQTTProtocol_retry:648
20150130 170213.897 (3372365568)   (2)< MQTTAsync_retry:2440
20150130 170213.897 (3372365568)  (1)< MQTTAsync_cycle:2699 (0)
20150130 170213.897 (3372365568)  (1)> MQTTAsync_cycle:2563
20150130 170213.897 (3372365568)   (2)> Socket_getReadySocket:216
20150130 170213.897 (3372365568)    (3)> Socket_continueWrites:777
20150130 170213.897 (3372365568)    (3)< Socket_continueWrites:799 (0)
20150130 170213.897 (3372365568)    (3)> isReady:192
20150130 170213.897 (3372365568)    (3)< isReady:197 (1)
20150130 170213.897 (3372365568)   (2)< Socket_getReadySocket:282 (3)
20150130 170213.897 (3372365568)   (2)> MQTTPacket_Factory:104
20150130 170213.897 (3372365568)    (3)> Socket_getch:297
20150130 170213.897 (3372365568)     (4)> SocketBuffer_getQueuedChar:189
20150130 170213.897 (3372365568)     (4)< SocketBuffer_getQueuedChar:208 (-22)
20150130 170213.897 (3372365568)     (4)> SocketBuffer_queueChar:268
20150130 170213.897 (3372365568)     (4)< SocketBuffer_queueChar:292
20150130 170213.897 (3372365568)    (3)< Socket_getch:318 (0)
20150130 170213.898 (3372365568)    (3)> MQTTPacket_decode:297
20150130 170213.898 (3372365568)     (4)> Socket_getch:297
20150130 170213.898 (3372365568)      (5)> SocketBuffer_getQueuedChar:189
20150130 170213.898 (3372365568)      (5)< SocketBuffer_getQueuedChar:208 (-22)
20150130 170213.898 (3372365568)      (5)> SocketBuffer_queueChar:268
20150130 170213.898 (3372365568)      (5)< SocketBuffer_queueChar:292
20150130 170213.898 (3372365568)     (4)< Socket_getch:318 (0)
20150130 170213.898 (3372365568)    (3)< MQTTPacket_decode:317 (0)
20150130 170213.898 (3372365568)    (3)> Socket_getdata:336
20150130 170213.898 (3372365568)     (4)> SocketBuffer_getQueuedData:149
20150130 170213.898 (3372365568)     (4)< SocketBuffer_getQueuedData:174
20150130 170213.898 (3372365568)     (4)> SocketBuffer_complete:244
20150130 170213.898 (3372365568)     (4)< SocketBuffer_complete:253
20150130 170213.898 (3372365568)    (3)< Socket_getdata:370
20150130 170213.898 (3372365568)    (3)> MQTTPacket_connack:125
20150130 170213.898 (3372365568)    (3)< MQTTPacket_connack:129
20150130 170213.898 (3372365568)   (2)< MQTTPacket_Factory:162 (0)
20150130 170213.898 (3372365568)   (2)> MQTTAsync_retry:2430
20150130 170213.898 (3372365568)    (3)> MQTTProtocol_retry:629
20150130 170213.898 (3372365568)    (3)< MQTTProtocol_retry:648
20150130 170213.898 (3372365568)   (2)< MQTTAsync_retry:2440
20150130 170213.898 (3372365568)  (1)< MQTTAsync_cycle:2699 (0)
20150130 170213.898 (3372365568)  (1)> MQTTAsync_completeConnection:1421
20150130 170213.898 3 ExampleClientPub <- CONNACK rc: 0
20150130 170213.898 (3372365568)   (2)> MQTTAsync_cleanSession:1815
20150130 170213.898 (3372365568)    (3)> MQTTPersistence_clear:156
20150130 170213.898 (3372365568)    (3)< MQTTPersistence_clear:160 (0)
20150130 170213.898 (3372365568)    (3)> MQTTProtocol_emptyMessageList:699
20150130 170213.898 (3372365568)    (3)< MQTTProtocol_emptyMessageList:706
20150130 170213.898 (3372365568)    (3)> MQTTProtocol_emptyMessageList:699
20150130 170213.898 (3372365568)    (3)< MQTTProtocol_emptyMessageList:706
20150130 170213.898 (3372365568)    (3)> MQTTAsync_emptyMessageQueue:1296
20150130 170213.898 (3372365568)    (3)< MQTTAsync_emptyMessageQueue:1310
20150130 170213.898 (3372365568)    (3)> MQTTAsync_removeResponsesAndCommands:1320
20150130 170213.898 0 responses removed for client ExampleClientPub
20150130 170213.898 0 commands removed for client ExampleClientPub
20150130 170213.898 (3372365568)    (3)< MQTTAsync_removeResponsesAndCommands:1352
20150130 170213.898 (3372365568)   (2)< MQTTAsync_cleanSession:1831 (0)
20150130 170213.898 (3372365568)  (1)< MQTTAsync_completeConnection:1450 (0)
20150130 170213.898 Calling connect success for client ExampleClientPub
Successful connection
20150130 170213.898 (3372365568)  (1)> MQTTAsync_sendMessage:2405
20150130 170213.898 (3372365568)   (2)> MQTTAsync_send:2357
20150130 170213.898 (3372365568)    (3)> UTF8_validateString:155
20150130 170213.898 (3372365568)     (4)> UTF8_validate:129
20150130 170213.898 (3372365568)      (5)> UTF8_char_validate:79
20150130 170213.898 (3372365568)      (5)< UTF8_char_validate:113
20150130 170213.898 (3372365568)      (5)> UTF8_char_validate:79
20150130 170213.898 (3372365568)      (5)< UTF8_char_validate:113
20150130 170213.898 (3372365568)      (5)> UTF8_char_validate:79
20150130 170213.898 (3372365568)      (5)< UTF8_char_validate:113
20150130 170213.898 (3372365568)      (5)> UTF8_char_validate:79
20150130 170213.898 (3372365568)      (5)< UTF8_char_validate:113
20150130 170213.898 (3372365568)      (5)> UTF8_char_validate:79
20150130 170213.898 (3372365568)      (5)< UTF8_char_validate:113
20150130 170213.898 (3372365568)      (5)> UTF8_char_validate:79
20150130 170213.898 (3372365568)      (5)< UTF8_char_validate:113
20150130 170213.898 (3372365568)      (5)> UTF8_char_validate:79
20150130 170213.898 (3372365568)      (5)< UTF8_char_validate:113
20150130 170213.898 (3372365568)      (5)> UTF8_char_validate:79
20150130 170213.898 (3372365568)      (5)< UTF8_char_validate:113
20150130 170213.898 (3372365568)      (5)> UTF8_char_validate:79
20150130 170213.898 (3372365568)      (5)< UTF8_char_validate:113
20150130 170213.898 (3372365568)      (5)> UTF8_char_validate:79
20150130 170213.898 (3372365568)      (5)< UTF8_char_validate:113
20150130 170213.898 (3372365568)      (5)> UTF8_char_validate:79
20150130 170213.898 (3372365568)      (5)< UTF8_char_validate:113
20150130 170213.898 (3372365568)      (5)> UTF8_char_validate:79
20150130 170213.898 (3372365568)      (5)< UTF8_char_validate:113
20150130 170213.898 (3372365568)      (5)> UTF8_char_validate:79
20150130 170213.898 (3372365568)      (5)< UTF8_char_validate:113
20150130 170213.898 (3372365568)     (4)< UTF8_validate:141 (1)
20150130 170213.898 (3372365568)    (3)< UTF8_validateString:157 (1)
20150130 170213.898 (3372365568)    (3)> MQTTAsync_assignMsgId:2173
20150130 170213.898 (3372365568)    (3)< MQTTAsync_assignMsgId:2197 (1)
20150130 170213.898 (3372365568)    (3)> MQTTStrncpy:736
20150130 170213.898 (3372365568)    (3)< MQTTStrncpy:746
20150130 170213.898 (3372365568)    (3)> MQTTAsync_addCommand:737
20150130 170213.898 (3372365568)    (3)< MQTTAsync_addCommand:768 (0)
20150130 170213.898 (3380758272)  (1)< Thread_wait_cond:416 (0)
20150130 170213.898 (3380758272)  (1)> Thread_wait_cond:402
20150130 170213.898 (3372365568)   (2)< MQTTAsync_send:2394 (0)
20150130 170213.898 (3372365568)  (1)< MQTTAsync_sendMessage:2420 (0)
Sent message with token value 1
20150130 170213.898 (3372365568)  (1)> MQTTAsync_cycle:2563
20150130 170213.898 (3372365568)   (2)> Socket_getReadySocket:216
20150130 170213.898 (3380758272)  (1)< Thread_wait_cond:416 (110)
20150130 170213.898 (3380758272)  (1)> MQTTAsync_checkTimeouts:1179
20150130 170213.898 (3380758272)  (1)< MQTTAsync_checkTimeouts:1251
20150130 170213.898 (3380758272)  (1)> MQTTAsync_processCommand:937
20150130 170213.898 (3380758272)   (2)> MQTTProtocol_startPublish:147
20150130 170213.898 (3380758272)    (3)> MQTTProtocol_createMessage:175
20150130 170213.898 (3380758272)     (4)> MQTTProtocol_storePublication:210
20150130 170213.898 (3380758272)     (4)< MQTTProtocol_storePublication:230
20150130 170213.898 (3380758272)    (3)< MQTTProtocol_createMessage:195
20150130 170213.898 (3380758272)    (3)> MQTTProtocol_startPublishCommon:124
20150130 170213.898 (3380758272)     (4)> MQTTPacket_send_publish:677
20150130 170213.898 (3380758272)      (5)> MQTTPacket_sends:226
20150130 170213.898 (3380758272)       (6)> MQTTPacket_encode:268
20150130 170213.898 (3380758272)       (6)< MQTTPacket_encode:278 (1)
20150130 170213.898 (3380758272)       (6)> MQTTPersistence_put:347
20150130 170213.898 (3380758272)       (6)< MQTTPersistence_put:381 (0)
20150130 170214.898 (3380758272)       (6)> Socket_putdatas:443
20150130 170214.898 (3380758272)        (7)> Socket_writev:399
20150130 170214.898 (3380758272)        (7)< Socket_writev:420 (31)
20150130 170214.898 (3380758272)       (6)< Socket_putdatas:485 (0)
20150130 170214.898 (3380758272)      (5)< MQTTPacket_sends:253 (0)
20150130 170214.898 3 ExampleClientPub -> PUBLISH msgid: 1 qos: 1 retained: 0 (0) payload: Hello World!
20150130 170214.898 (3380758272)     (4)< MQTTPacket_send_publish:716 (0)
20150130 170214.898 (3380758272)    (3)< MQTTProtocol_startPublishCommon:128 (0)
20150130 170214.898 (3380758272)   (2)< MQTTProtocol_startPublish:158 (0)
20150130 170214.898 (3380758272)  (1)< MQTTAsync_processCommand:1169
20150130 170214.898 (3380758272)  (1)> Thread_wait_cond:402
20150130 170214.898 (3372365568)    (3)> Socket_continueWrites:777
20150130 170214.898 (3372365568)    (3)< Socket_continueWrites:799 (0)
20150130 170214.898 (3372365568)    (3)> isReady:192
20150130 170214.898 (3372365568)    (3)< isReady:197 (1)
20150130 170214.898 (3372365568)   (2)< Socket_getReadySocket:282 (3)
20150130 170214.898 (3372365568)   (2)> MQTTPacket_Factory:104
20150130 170214.898 (3372365568)    (3)> Socket_getch:297
20150130 170214.898 (3372365568)     (4)> SocketBuffer_getQueuedChar:189
20150130 170214.898 (3372365568)     (4)< SocketBuffer_getQueuedChar:208 (-22)
20150130 170214.899 (3372365568)     (4)> SocketBuffer_queueChar:268
20150130 170214.899 (3372365568)     (4)< SocketBuffer_queueChar:292
20150130 170214.899 (3372365568)    (3)< Socket_getch:318 (0)
20150130 170214.899 (3372365568)    (3)> MQTTPacket_decode:297
20150130 170214.899 (3372365568)     (4)> Socket_getch:297
20150130 170214.899 (3372365568)      (5)> SocketBuffer_getQueuedChar:189
20150130 170214.899 (3372365568)      (5)< SocketBuffer_getQueuedChar:208 (-22)
20150130 170214.899 (3372365568)      (5)> SocketBuffer_queueChar:268
20150130 170214.899 (3372365568)      (5)< SocketBuffer_queueChar:292
20150130 170214.899 (3372365568)     (4)< Socket_getch:318 (0)
20150130 170214.899 (3372365568)    (3)< MQTTPacket_decode:317 (0)
20150130 170214.899 (3372365568)    (3)> Socket_getdata:336
20150130 170214.899 (3372365568)     (4)> SocketBuffer_getQueuedData:149
20150130 170214.899 (3372365568)     (4)< SocketBuffer_getQueuedData:174
20150130 170214.899 (3372365568)     (4)> SocketBuffer_complete:244
20150130 170214.899 (3372365568)     (4)< SocketBuffer_complete:253
20150130 170214.899 (3372365568)    (3)< Socket_getdata:370
20150130 170214.899 (3372365568)    (3)> MQTTPacket_ack:653
20150130 170214.899 (3372365568)    (3)< MQTTPacket_ack:656
20150130 170214.899 (3372365568)   (2)< MQTTPacket_Factory:162 (0)
20150130 170214.899 (3372365568)   (2)> MQTTProtocol_handlePubacks:318
20150130 170214.899 3 ExampleClientPub <- PUBACK msgid: 1
20150130 170214.899 PUBACK received from client ExampleClientPub for message id 1 - removing publication
20150130 170214.899 (3372365568)    (3)> MQTTPersistence_remove:399
20150130 170214.899 (3372365568)    (3)< MQTTPersistence_remove:418 (0)
20150130 170214.899 (3372365568)    (3)> MQTTProtocol_removePublication:240
20150130 170214.899 (3372365568)    (3)< MQTTProtocol_removePublication:247
20150130 170214.899 (3372365568)   (2)< MQTTProtocol_handlePubacks:341 (0)
20150130 170214.899 Calling publish success for client ExampleClientPub
Message with token value 1 delivery confirmed
20150130 170214.899 (3372365568)   (2)> MQTTAsync_sendMessage:2405
20150130 170214.899 (3372365568)    (3)> MQTTAsync_send:2357
20150130 170214.899 (3372365568)     (4)> UTF8_validateString:155
20150130 170214.899 (3372365568)      (5)> UTF8_validate:129
20150130 170214.899 (3372365568)       (6)> UTF8_char_validate:79
20150130 170214.899 (3372365568)       (6)< UTF8_char_validate:113
20150130 170214.899 (3372365568)       (6)> UTF8_char_validate:79
20150130 170214.899 (3372365568)       (6)< UTF8_char_validate:113
20150130 170214.899 (3372365568)       (6)> UTF8_char_validate:79
20150130 170214.899 (3372365568)       (6)< UTF8_char_validate:113
20150130 170214.899 (3372365568)       (6)> UTF8_char_validate:79
20150130 170214.899 (3372365568)       (6)< UTF8_char_validate:113
20150130 170214.899 (3372365568)       (6)> UTF8_char_validate:79
20150130 170214.899 (3372365568)       (6)< UTF8_char_validate:113
20150130 170214.899 (3372365568)       (6)> UTF8_char_validate:79
20150130 170214.899 (3372365568)       (6)< UTF8_char_validate:113
20150130 170214.899 (3372365568)       (6)> UTF8_char_validate:79
20150130 170214.899 (3372365568)       (6)< UTF8_char_validate:113
20150130 170214.899 (3372365568)       (6)> UTF8_char_validate:79
20150130 170214.899 (3372365568)       (6)< UTF8_char_validate:113
20150130 170214.899 (3372365568)       (6)> UTF8_char_validate:79
20150130 170214.899 (3372365568)       (6)< UTF8_char_validate:113
20150130 170214.899 (3372365568)       (6)> UTF8_char_validate:79
20150130 170214.899 (3372365568)       (6)< UTF8_char_validate:113
20150130 170214.899 (3372365568)       (6)> UTF8_char_validate:79
20150130 170214.899 (3372365568)       (6)< UTF8_char_validate:113
20150130 170214.899 (3372365568)       (6)> UTF8_char_validate:79
20150130 170214.899 (3372365568)       (6)< UTF8_char_validate:113
20150130 170214.899 (3372365568)       (6)> UTF8_char_validate:79
20150130 170214.899 (3372365568)       (6)< UTF8_char_validate:113
20150130 170214.899 (3372365568)      (5)< UTF8_validate:141 (1)
20150130 170214.900 (3372365568)     (4)< UTF8_validateString:157 (1)
20150130 170214.900 (3372365568)     (4)> MQTTAsync_assignMsgId:2173
20150130 170214.900 (3372365568)     (4)< MQTTAsync_assignMsgId:2197 (2)
20150130 170214.900 (3372365568)     (4)> MQTTStrncpy:736
20150130 170214.900 (3372365568)     (4)< MQTTStrncpy:746
20150130 170214.900 (3372365568)     (4)> MQTTAsync_addCommand:737
20150130 170214.900 (3372365568)     (4)< MQTTAsync_addCommand:768 (0)
20150130 170214.900 (3372365568)    (3)< MQTTAsync_send:2394 (0)
20150130 170214.900 (3372365568)   (2)< MQTTAsync_sendMessage:2420 (0)
Sent message with token value 2
20150130 170214.900 (3372365568)   (2)> MQTTAsync_retry:2430
20150130 170214.900 (3372365568)    (3)> MQTTProtocol_retry:629
20150130 170214.900 (3372365568)    (3)< MQTTProtocol_retry:648
20150130 170214.900 (3372365568)   (2)< MQTTAsync_retry:2440
20150130 170214.900 (3372365568)  (1)< MQTTAsync_cycle:2699 (0)
20150130 170214.900 (3372365568)  (1)> MQTTAsync_cycle:2563
20150130 170214.900 (3372365568)   (2)> Socket_getReadySocket:216
20150130 170214.900 (3380758272)  (1)< Thread_wait_cond:416 (0)
20150130 170214.900 (3380758272)  (1)> Thread_wait_cond:402
20150130 170214.900 (3380758272)  (1)< Thread_wait_cond:416 (110)
20150130 170214.900 (3380758272)  (1)> MQTTAsync_checkTimeouts:1179
20150130 170215.900 (3380758272)  (1)< MQTTAsync_checkTimeouts:1251
20150130 170215.900 (3380758272)  (1)> MQTTAsync_processCommand:937
20150130 170215.900 (3380758272)   (2)> MQTTProtocol_startPublish:147
20150130 170215.900 (3380758272)    (3)> MQTTProtocol_createMessage:175
20150130 170215.900 (3380758272)     (4)> MQTTProtocol_storePublication:210
20150130 170215.900 (3380758272)     (4)< MQTTProtocol_storePublication:230
20150130 170215.900 (3380758272)    (3)< MQTTProtocol_createMessage:195
20150130 170215.900 (3380758272)    (3)> MQTTProtocol_startPublishCommon:124
20150130 170215.900 (3380758272)     (4)> MQTTPacket_send_publish:677
20150130 170215.900 (3380758272)      (5)> MQTTPacket_sends:226
20150130 170215.900 (3380758272)       (6)> MQTTPacket_encode:268
20150130 170215.900 (3380758272)       (6)< MQTTPacket_encode:278 (1)
20150130 170215.900 (3380758272)       (6)> MQTTPersistence_put:347
20150130 170215.900 (3380758272)       (6)< MQTTPersistence_put:381 (0)
20150130 170215.900 (3380758272)       (6)> Socket_putdatas:443
20150130 170215.900 (3380758272)        (7)> Socket_writev:399
20150130 170215.900 (3380758272)        (7)< Socket_writev:420 (31)
20150130 170215.900 (3380758272)       (6)< Socket_putdatas:485 (0)
20150130 170215.900 (3380758272)      (5)< MQTTPacket_sends:253 (0)
20150130 170215.900 3 ExampleClientPub -> PUBLISH msgid: 2 qos: 1 retained: 0 (0) payload: Hello World!
20150130 170215.900 (3380758272)     (4)< MQTTPacket_send_publish:716 (0)
20150130 170215.900 (3380758272)    (3)< MQTTProtocol_startPublishCommon:128 (0)
20150130 170215.900 (3380758272)   (2)< MQTTProtocol_startPublish:158 (0)
20150130 170215.900 (3380758272)  (1)< MQTTAsync_processCommand:1169
20150130 170215.900 (3380758272)  (1)> Thread_wait_cond:402
20150130 170215.900 (3372365568)    (3)> Socket_continueWrites:777
20150130 170215.900 (3372365568)    (3)< Socket_continueWrites:799 (0)
20150130 170215.900 (3372365568)    (3)> isReady:192
20150130 170215.900 (3372365568)    (3)< isReady:197 (1)
20150130 170215.900 (3372365568)   (2)< Socket_getReadySocket:282 (3)
20150130 170215.900 (3372365568)   (2)> MQTTPacket_Factory:104
20150130 170215.900 (3372365568)    (3)> Socket_getch:297
20150130 170215.900 (3372365568)     (4)> SocketBuffer_getQueuedChar:189
20150130 170215.900 (3372365568)     (4)< SocketBuffer_getQueuedChar:208 (-22)
20150130 170215.900 (3372365568)     (4)> SocketBuffer_queueChar:268
20150130 170215.900 (3372365568)     (4)< SocketBuffer_queueChar:292
20150130 170215.900 (3372365568)    (3)< Socket_getch:318 (0)
20150130 170215.900 (3372365568)    (3)> MQTTPacket_decode:297
20150130 170215.900 (3372365568)     (4)> Socket_getch:297
20150130 170215.900 (3372365568)      (5)> SocketBuffer_getQueuedChar:189
20150130 170215.900 (3372365568)      (5)< SocketBuffer_getQueuedChar:208 (-22)
20150130 170215.900 (3372365568)      (5)> SocketBuffer_queueChar:268
20150130 170215.900 (3372365568)      (5)< SocketBuffer_queueChar:292
20150130 170215.900 (3372365568)     (4)< Socket_getch:318 (0)
20150130 170215.900 (3372365568)    (3)< MQTTPacket_decode:317 (0)
20150130 170215.900 (3372365568)    (3)> Socket_getdata:336
20150130 170215.900 (3372365568)     (4)> SocketBuffer_getQueuedData:149
20150130 170215.900 (3372365568)     (4)< SocketBuffer_getQueuedData:174
20150130 170215.900 (3372365568)     (4)> SocketBuffer_complete:244
20150130 170215.900 (3372365568)     (4)< SocketBuffer_complete:253
20150130 170215.900 (3372365568)    (3)< Socket_getdata:370
20150130 170215.900 (3372365568)    (3)> MQTTPacket_ack:653
20150130 170215.900 (3372365568)    (3)< MQTTPacket_ack:656
20150130 170215.900 (3372365568)   (2)< MQTTPacket_Factory:162 (0)
20150130 170215.900 (3372365568)   (2)> MQTTProtocol_handlePubacks:318
20150130 170215.900 3 ExampleClientPub <- PUBACK msgid: 2
20150130 170215.900 PUBACK received from client ExampleClientPub for message id 2 - removing publication
20150130 170215.900 (3372365568)    (3)> MQTTPersistence_remove:399
20150130 170215.900 (3372365568)    (3)< MQTTPersistence_remove:418 (0)
20150130 170215.900 (3372365568)    (3)> MQTTProtocol_removePublication:240
20150130 170215.900 (3372365568)    (3)< MQTTProtocol_removePublication:247
20150130 170215.900 (3372365568)   (2)< MQTTProtocol_handlePubacks:341 (0)
20150130 170215.900 Calling publish success for client ExampleClientPub
Message with token value 2 delivery confirmed
20150130 170215.900 (3372365568)   (2)> MQTTAsync_sendMessage:2405
20150130 170215.900 (3372365568)    (3)> MQTTAsync_send:2357
20150130 170215.900 (3372365568)     (4)> UTF8_validateString:155
20150130 170215.900 (3372365568)      (5)> UTF8_validate:129
20150130 170215.900 (3372365568)       (6)> UTF8_char_validate:79
20150130 170215.900 (3372365568)       (6)< UTF8_char_validate:113
20150130 170215.900 (3372365568)       (6)> UTF8_char_validate:79
20150130 170215.900 (3372365568)       (6)< UTF8_char_validate:113
20150130 170215.900 (3372365568)       (6)> UTF8_char_validate:79
20150130 170215.900 (3372365568)       (6)< UTF8_char_validate:113
20150130 170215.900 (3372365568)       (6)> UTF8_char_validate:79
20150130 170215.900 (3372365568)       (6)< UTF8_char_validate:113
20150130 170215.900 (3372365568)       (6)> UTF8_char_validate:79
20150130 170215.900 (3372365568)       (6)< UTF8_char_validate:113
20150130 170215.900 (3372365568)       (6)> UTF8_char_validate:79
20150130 170215.900 (3372365568)       (6)< UTF8_char_validate:113
20150130 170215.900 (3372365568)       (6)> UTF8_char_validate:79
20150130 170215.901 (3372365568)       (6)< UTF8_char_validate:113
20150130 170215.901 (3372365568)       (6)> UTF8_char_validate:79
20150130 170215.901 (3372365568)       (6)< UTF8_char_validate:113
20150130 170215.901 (3372365568)       (6)> UTF8_char_validate:79
20150130 170215.901 (3372365568)       (6)< UTF8_char_validate:113
20150130 170215.901 (3372365568)       (6)> UTF8_char_validate:79
20150130 170215.901 (3372365568)       (6)< UTF8_char_validate:113
20150130 170215.901 (3372365568)       (6)> UTF8_char_validate:79
20150130 170215.901 (3372365568)       (6)< UTF8_char_validate:113
20150130 170215.901 (3372365568)       (6)> UTF8_char_validate:79
20150130 170215.901 (3372365568)       (6)< UTF8_char_validate:113
20150130 170215.901 (3372365568)       (6)> UTF8_char_validate:79
20150130 170215.901 (3372365568)       (6)< UTF8_char_validate:113
20150130 170215.901 (3372365568)      (5)< UTF8_validate:141 (1)
20150130 170215.901 (3372365568)     (4)< UTF8_validateString:157 (1)
20150130 170215.901 (3372365568)     (4)> MQTTAsync_assignMsgId:2173
20150130 170215.901 (3372365568)     (4)< MQTTAsync_assignMsgId:2197 (3)
20150130 170215.901 (3372365568)     (4)> MQTTStrncpy:736
20150130 170215.901 (3372365568)     (4)< MQTTStrncpy:746
20150130 170215.901 (3372365568)     (4)> MQTTAsync_addCommand:737
20150130 170215.901 (3372365568)     (4)< MQTTAsync_addCommand:768 (0)
20150130 170215.901 (3372365568)    (3)< MQTTAsync_send:2394 (0)
20150130 170215.901 (3372365568)   (2)< MQTTAsync_sendMessage:2420 (0)
Sent message with token value 3
20150130 170215.901 (3372365568)   (2)> MQTTAsync_retry:2430
20150130 170215.901 (3372365568)    (3)> MQTTProtocol_retry:629
20150130 170215.901 (3372365568)    (3)< MQTTProtocol_retry:648
20150130 170215.901 (3372365568)   (2)< MQTTAsync_retry:2440
20150130 170215.901 (3372365568)  (1)< MQTTAsync_cycle:2699 (0)
20150130 170215.901 (3372365568)  (1)> MQTTAsync_cycle:2563
20150130 170215.901 (3380758272)  (1)< Thread_wait_cond:416 (0)
20150130 170215.901 (3380758272)  (1)> Thread_wait_cond:402
20150130 170215.901 (3372365568)   (2)> Socket_getReadySocket:216
20150130 170215.901 (3380758272)  (1)< Thread_wait_cond:416 (110)
20150130 170215.901 (3380758272)  (1)> MQTTAsync_checkTimeouts:1179
20150130 170215.901 (3380758272)  (1)< MQTTAsync_checkTimeouts:1251
20150130 170215.901 (3380758272)  (1)> MQTTAsync_processCommand:937
20150130 170215.901 (3380758272)   (2)> MQTTProtocol_startPublish:147
20150130 170215.901 (3380758272)    (3)> MQTTProtocol_createMessage:175
20150130 170215.901 (3380758272)     (4)> MQTTProtocol_storePublication:210
20150130 170215.901 (3380758272)     (4)< MQTTProtocol_storePublication:230
20150130 170216.901 (3380758272)    (3)< MQTTProtocol_createMessage:195
20150130 170216.901 (3380758272)    (3)> MQTTProtocol_startPublishCommon:124
20150130 170216.901 (3380758272)     (4)> MQTTPacket_send_publish:677
20150130 170216.901 (3380758272)      (5)> MQTTPacket_sends:226
20150130 170216.901 (3380758272)       (6)> MQTTPacket_encode:268
20150130 170216.901 (3380758272)       (6)< MQTTPacket_encode:278 (1)
20150130 170216.901 (3380758272)       (6)> MQTTPersistence_put:347
20150130 170216.901 (3380758272)       (6)< MQTTPersistence_put:381 (0)
20150130 170216.901 (3380758272)       (6)> Socket_putdatas:443
20150130 170216.901 (3380758272)        (7)> Socket_writev:399
20150130 170216.901 (3380758272)        (7)< Socket_writev:420 (31)
20150130 170216.901 (3380758272)       (6)< Socket_putdatas:485 (0)
20150130 170216.901 (3380758272)      (5)< MQTTPacket_sends:253 (0)
20150130 170216.901 3 ExampleClientPub -> PUBLISH msgid: 3 qos: 1 retained: 0 (0) payload: Hello World!
20150130 170216.901 (3380758272)     (4)< MQTTPacket_send_publish:716 (0)
20150130 170216.901 (3380758272)    (3)< MQTTProtocol_startPublishCommon:128 (0)
20150130 170216.901 (3380758272)   (2)< MQTTProtocol_startPublish:158 (0)
20150130 170216.901 (3380758272)  (1)< MQTTAsync_processCommand:1169
20150130 170216.901 (3380758272)  (1)> Thread_wait_cond:402
20150130 170216.901 (3372365568)    (3)> Socket_continueWrites:777
20150130 170216.902 (3372365568)    (3)< Socket_continueWrites:799 (0)
20150130 170216.902 (3372365568)    (3)> isReady:192
20150130 170216.902 (3372365568)    (3)< isReady:197 (1)
20150130 170216.902 (3372365568)   (2)< Socket_getReadySocket:282 (3)
20150130 170216.902 (3372365568)   (2)> MQTTPacket_Factory:104
20150130 170216.902 (3372365568)    (3)> Socket_getch:297
20150130 170216.902 (3372365568)     (4)> SocketBuffer_getQueuedChar:189
20150130 170216.902 (3372365568)     (4)< SocketBuffer_getQueuedChar:208 (-22)
20150130 170216.902 (3372365568)     (4)> SocketBuffer_queueChar:268
20150130 170216.902 (3372365568)     (4)< SocketBuffer_queueChar:292
20150130 170216.902 (3372365568)    (3)< Socket_getch:318 (0)
20150130 170216.902 (3372365568)    (3)> MQTTPacket_decode:297
20150130 170216.902 (3372365568)     (4)> Socket_getch:297
20150130 170216.902 (3372365568)      (5)> SocketBuffer_getQueuedChar:189
20150130 170216.902 (3372365568)      (5)< SocketBuffer_getQueuedChar:208 (-22)
20150130 170216.902 (3372365568)      (5)> SocketBuffer_queueChar:268
20150130 170216.902 (3372365568)      (5)< SocketBuffer_queueChar:292
20150130 170216.902 (3372365568)     (4)< Socket_getch:318 (0)
20150130 170216.902 (3372365568)    (3)< MQTTPacket_decode:317 (0)
20150130 170216.902 (3372365568)    (3)> Socket_getdata:336
20150130 170216.902 (3372365568)     (4)> SocketBuffer_getQueuedData:149
20150130 170216.902 (3372365568)     (4)< SocketBuffer_getQueuedData:174
20150130 170216.902 (3372365568)     (4)> SocketBuffer_complete:244
20150130 170216.902 (3372365568)     (4)< SocketBuffer_complete:253
20150130 170216.902 (3372365568)    (3)< Socket_getdata:370
20150130 170216.902 (3372365568)    (3)> MQTTPacket_ack:653
20150130 170216.902 (3372365568)    (3)< MQTTPacket_ack:656
20150130 170216.902 (3372365568)   (2)< MQTTPacket_Factory:162 (0)
20150130 170216.902 (3372365568)   (2)> MQTTProtocol_handlePubacks:318
20150130 170216.902 3 ExampleClientPub <- PUBACK msgid: 3
20150130 170216.902 PUBACK received from client ExampleClientPub for message id 3 - removing publication
20150130 170216.902 (3372365568)    (3)> MQTTPersistence_remove:399
20150130 170216.902 (3372365568)    (3)< MQTTPersistence_remove:418 (0)
20150130 170216.902 (3372365568)    (3)> MQTTProtocol_removePublication:240
20150130 170216.902 (3372365568)    (3)< MQTTProtocol_removePublication:247
20150130 170216.902 (3372365568)   (2)< MQTTProtocol_handlePubacks:341 (0)
20150130 170216.902 Calling publish success for client ExampleClientPub
Message with token value 3 delivery confirmed
20150130 170216.902 (3372365568)   (2)> MQTTAsync_sendMessage:2405
20150130 170216.902 (3372365568)    (3)> MQTTAsync_send:2357
20150130 170216.902 (3372365568)     (4)> UTF8_validateString:155
20150130 170216.902 (3372365568)      (5)> UTF8_validate:129
20150130 170216.902 (3372365568)       (6)> UTF8_char_validate:79
20150130 170216.902 (3372365568)       (6)< UTF8_char_validate:113
20150130 170216.902 (3372365568)       (6)> UTF8_char_validate:79
20150130 170216.902 (3372365568)       (6)< UTF8_char_validate:113
20150130 170216.902 (3372365568)       (6)> UTF8_char_validate:79
20150130 170216.902 (3372365568)       (6)< UTF8_char_validate:113
20150130 170216.902 (3372365568)       (6)> UTF8_char_validate:79
20150130 170216.902 (3372365568)       (6)< UTF8_char_validate:113
20150130 170216.902 (3372365568)       (6)> UTF8_char_validate:79
20150130 170216.902 (3372365568)       (6)< UTF8_char_validate:113
20150130 170216.902 (3372365568)       (6)> UTF8_char_validate:79
20150130 170216.902 (3372365568)       (6)< UTF8_char_validate:113
20150130 170216.902 (3372365568)       (6)> UTF8_char_validate:79
20150130 170216.902 (3372365568)       (6)< UTF8_char_validate:113
20150130 170216.902 (3372365568)       (6)> UTF8_char_validate:79
20150130 170216.902 (3372365568)       (6)< UTF8_char_validate:113
20150130 170216.902 (3372365568)       (6)> UTF8_char_validate:79
20150130 170216.902 (3372365568)       (6)< UTF8_char_validate:113
20150130 170216.902 (3372365568)       (6)> UTF8_char_validate:79
20150130 170216.902 (3372365568)       (6)< UTF8_char_validate:113
20150130 170216.902 (3372365568)       (6)> UTF8_char_validate:79
20150130 170216.902 (3372365568)       (6)< UTF8_char_validate:113
20150130 170216.902 (3372365568)       (6)> UTF8_char_validate:79
20150130 170216.902 (3372365568)       (6)< UTF8_char_validate:113
20150130 170216.902 (3372365568)       (6)> UTF8_char_validate:79
20150130 170216.902 (3372365568)       (6)< UTF8_char_validate:113
20150130 170216.902 (3372365568)      (5)< UTF8_validate:141 (1)
20150130 170216.902 (3372365568)     (4)< UTF8_validateString:157 (1)
20150130 170216.902 (3372365568)     (4)> MQTTAsync_assignMsgId:2173
20150130 170216.902 (3372365568)     (4)< MQTTAsync_assignMsgId:2197 (4)
20150130 170216.902 (3372365568)     (4)> MQTTStrncpy:736
20150130 170216.902 (3372365568)     (4)< MQTTStrncpy:746
20150130 170216.902 (3372365568)     (4)> MQTTAsync_addCommand:737
20150130 170216.902 (3372365568)     (4)< MQTTAsync_addCommand:768 (0)
20150130 170216.902 (3372365568)    (3)< MQTTAsync_send:2394 (0)
20150130 170216.902 (3372365568)   (2)< MQTTAsync_sendMessage:2420 (0)
Sent message with token value 4
20150130 170216.902 (3380758272)  (1)< Thread_wait_cond:416 (0)
20150130 170216.902 (3380758272)  (1)> Thread_wait_cond:402
20150130 170216.902 (3372365568)   (2)> MQTTAsync_retry:2430
20150130 170216.903 (3372365568)    (3)> MQTTProtocol_retry:629
20150130 170216.903 (3372365568)    (3)< MQTTProtocol_retry:648
20150130 170216.903 (3372365568)   (2)< MQTTAsync_retry:2440
20150130 170216.903 (3372365568)  (1)< MQTTAsync_cycle:2699 (0)
20150130 170216.903 (3372365568)  (1)> MQTTAsync_cycle:2563
20150130 170216.903 (3372365568)   (2)> Socket_getReadySocket:216
20150130 170216.903 (3380758272)  (1)< Thread_wait_cond:416 (110)
20150130 170216.903 (3380758272)  (1)> MQTTAsync_checkTimeouts:1179
20150130 170216.903 (3380758272)  (1)< MQTTAsync_checkTimeouts:1251
20150130 170216.903 (3380758272)  (1)> MQTTAsync_processCommand:937
20150130 170216.903 (3380758272)   (2)> MQTTProtocol_startPublish:147
20150130 170216.903 (3380758272)    (3)> MQTTProtocol_createMessage:175
20150130 170216.903 (3380758272)     (4)> MQTTProtocol_storePublication:210
20150130 170216.903 (3380758272)     (4)< MQTTProtocol_storePublication:230
20150130 170216.903 (3380758272)    (3)< MQTTProtocol_createMessage:195
20150130 170216.903 (3380758272)    (3)> MQTTProtocol_startPublishCommon:124
20150130 170216.903 (3380758272)     (4)> MQTTPacket_send_publish:677
20150130 170216.903 (3380758272)      (5)> MQTTPacket_sends:226
20150130 170216.903 (3380758272)       (6)> MQTTPacket_encode:268
20150130 170216.903 (3380758272)       (6)< MQTTPacket_encode:278 (1)
20150130 170217.903 (3380758272)       (6)> MQTTPersistence_put:347
20150130 170217.903 (3380758272)       (6)< MQTTPersistence_put:381 (0)
20150130 170217.903 (3380758272)       (6)> Socket_putdatas:443
20150130 170217.903 (3380758272)        (7)> Socket_writev:399
20150130 170217.903 (3380758272)        (7)< Socket_writev:420 (31)
20150130 170217.903 (3380758272)       (6)< Socket_putdatas:485 (0)
20150130 170217.903 (3380758272)      (5)< MQTTPacket_sends:253 (0)
20150130 170217.903 3 ExampleClientPub -> PUBLISH msgid: 4 qos: 1 retained: 0 (0) payload: Hello World!
20150130 170217.903 (3380758272)     (4)< MQTTPacket_send_publish:716 (0)
20150130 170217.903 (3380758272)    (3)< MQTTProtocol_startPublishCommon:128 (0)
20150130 170217.903 (3380758272)   (2)< MQTTProtocol_startPublish:158 (0)
20150130 170217.903 (3380758272)  (1)< MQTTAsync_processCommand:1169
20150130 170217.903 (3380758272)  (1)> Thread_wait_cond:402
20150130 170217.903 (3372365568)    (3)> Socket_continueWrites:777
20150130 170217.903 (3372365568)    (3)< Socket_continueWrites:799 (0)
20150130 170217.903 (3372365568)    (3)> isReady:192
20150130 170217.903 (3372365568)    (3)< isReady:197 (1)
20150130 170217.903 (3372365568)   (2)< Socket_getReadySocket:282 (3)
20150130 170217.903 (3372365568)   (2)> MQTTPacket_Factory:104
20150130 170217.903 (3372365568)    (3)> Socket_getch:297
20150130 170217.904 (3372365568)     (4)> SocketBuffer_getQueuedChar:189
20150130 170217.904 (3372365568)     (4)< SocketBuffer_getQueuedChar:208 (-22)
20150130 170217.904 (3372365568)     (4)> SocketBuffer_queueChar:268
20150130 170217.904 (3372365568)     (4)< SocketBuffer_queueChar:292
20150130 170217.904 (3372365568)    (3)< Socket_getch:318 (0)
20150130 170217.904 (3372365568)    (3)> MQTTPacket_decode:297
20150130 170217.904 (3372365568)     (4)> Socket_getch:297
20150130 170217.904 (3372365568)      (5)> SocketBuffer_getQueuedChar:189
20150130 170217.904 (3372365568)      (5)< SocketBuffer_getQueuedChar:208 (-22)
20150130 170217.904 (3372365568)      (5)> SocketBuffer_queueChar:268
20150130 170217.904 (3372365568)      (5)< SocketBuffer_queueChar:292
20150130 170217.904 (3372365568)     (4)< Socket_getch:318 (0)
20150130 170217.904 (3372365568)    (3)< MQTTPacket_decode:317 (0)
20150130 170217.904 (3372365568)    (3)> Socket_getdata:336
20150130 170217.904 (3372365568)     (4)> SocketBuffer_getQueuedData:149
20150130 170217.904 (3372365568)     (4)< SocketBuffer_getQueuedData:174
20150130 170217.904 (3372365568)     (4)> SocketBuffer_complete:244
20150130 170217.904 (3372365568)     (4)< SocketBuffer_complete:253
20150130 170217.904 (3372365568)    (3)< Socket_getdata:370
20150130 170217.904 (3372365568)    (3)> MQTTPacket_ack:653
20150130 170217.904 (3372365568)    (3)< MQTTPacket_ack:656
20150130 170217.904 (3372365568)   (2)< MQTTPacket_Factory:162 (0)
20150130 170217.904 (3372365568)   (2)> MQTTProtocol_handlePubacks:318
20150130 170217.904 3 ExampleClientPub <- PUBACK msgid: 4
20150130 170217.904 PUBACK received from client ExampleClientPub for message id 4 - removing publication
20150130 170217.904 (3372365568)    (3)> MQTTPersistence_remove:399
20150130 170217.904 (3372365568)    (3)< MQTTPersistence_remove:418 (0)
20150130 170217.904 (3372365568)    (3)> MQTTProtocol_removePublication:240
20150130 170217.904 (3372365568)    (3)< MQTTProtocol_removePublication:247
20150130 170217.904 (3372365568)   (2)< MQTTProtocol_handlePubacks:341 (0)
20150130 170217.904 Calling publish success for client ExampleClientPub
Message with token value 4 delivery confirmed
20150130 170217.904 (3372365568)   (2)> MQTTAsync_sendMessage:2405
20150130 170217.904 (3372365568)    (3)> MQTTAsync_send:2357
20150130 170217.904 (3372365568)     (4)> UTF8_validateString:155
20150130 170217.904 (3372365568)      (5)> UTF8_validate:129
20150130 170217.904 (3372365568)       (6)> UTF8_char_validate:79
20150130 170217.904 (3372365568)       (6)< UTF8_char_validate:113
20150130 170217.904 (3372365568)       (6)> UTF8_char_validate:79
20150130 170217.904 (3372365568)       (6)< UTF8_char_validate:113
20150130 170217.904 (3372365568)       (6)> UTF8_char_validate:79
20150130 170217.904 (3372365568)       (6)< UTF8_char_validate:113
20150130 170217.904 (3372365568)       (6)> UTF8_char_validate:79
20150130 170217.904 (3372365568)       (6)< UTF8_char_validate:113
20150130 170217.904 (3372365568)       (6)> UTF8_char_validate:79
20150130 170217.904 (3372365568)       (6)< UTF8_char_validate:113
20150130 170217.904 (3372365568)       (6)> UTF8_char_validate:79
20150130 170217.904 (3372365568)       (6)< UTF8_char_validate:113
20150130 170217.904 (3372365568)       (6)> UTF8_char_validate:79
20150130 170217.904 (3372365568)       (6)< UTF8_char_validate:113
20150130 170217.904 (3372365568)       (6)> UTF8_char_validate:79
20150130 170217.904 (3372365568)       (6)< UTF8_char_validate:113
20150130 170217.904 (3372365568)       (6)> UTF8_char_validate:79
20150130 170217.904 (3372365568)       (6)< UTF8_char_validate:113
20150130 170217.904 (3372365568)       (6)> UTF8_char_validate:79
20150130 170217.904 (3372365568)       (6)< UTF8_char_validate:113
20150130 170217.904 (3372365568)       (6)> UTF8_char_validate:79
20150130 170217.904 (3372365568)       (6)< UTF8_char_validate:113
20150130 170217.904 (3372365568)       (6)> UTF8_char_validate:79
20150130 170217.904 (3372365568)       (6)< UTF8_char_validate:113
20150130 170217.904 (3372365568)       (6)> UTF8_char_validate:79
20150130 170217.905 (3372365568)       (6)< UTF8_char_validate:113
20150130 170217.905 (3372365568)      (5)< UTF8_validate:141 (1)
20150130 170217.905 (3372365568)     (4)< UTF8_validateString:157 (1)
20150130 170217.905 (3372365568)     (4)> MQTTAsync_assignMsgId:2173
20150130 170217.905 (3372365568)     (4)< MQTTAsync_assignMsgId:2197 (5)
20150130 170217.905 (3372365568)     (4)> MQTTStrncpy:736
20150130 170217.905 (3372365568)     (4)< MQTTStrncpy:746
20150130 170217.905 (3372365568)     (4)> MQTTAsync_addCommand:737
20150130 170217.905 (3372365568)     (4)< MQTTAsync_addCommand:768 (0)
20150130 170217.905 (3372365568)    (3)< MQTTAsync_send:2394 (0)
20150130 170217.905 (3372365568)   (2)< MQTTAsync_sendMessage:2420 (0)
Sent message with token value 5
20150130 170217.905 (3380758272)  (1)< Thread_wait_cond:416 (0)
20150130 170217.905 (3380758272)  (1)> Thread_wait_cond:402
20150130 170217.905 (3372365568)   (2)> MQTTAsync_retry:2430
20150130 170217.905 (3372365568)    (3)> MQTTProtocol_keepalive:512
20150130 170217.905 (3372365568)    (3)< MQTTProtocol_keepalive:545
20150130 170217.905 (3372365568)    (3)> MQTTProtocol_retry:629
20150130 170217.905 (3372365568)     (4)> MQTTProtocol_retries:559
20150130 170217.905 (3372365568)     (4)< MQTTProtocol_retries:615
20150130 170217.905 (3372365568)    (3)< MQTTProtocol_retry:648
20150130 170217.905 (3372365568)   (2)< MQTTAsync_retry:2440
20150130 170217.905 (3372365568)  (1)< MQTTAsync_cycle:2699 (0)
20150130 170217.905 (3372365568)  (1)> MQTTAsync_cycle:2563
20150130 170217.905 (3372365568)   (2)> Socket_getReadySocket:216
20150130 170217.905 (3380758272)  (1)< Thread_wait_cond:416 (110)
20150130 170217.905 (3380758272)  (1)> MQTTAsync_checkTimeouts:1179
20150130 170217.905 (3380758272)  (1)< MQTTAsync_checkTimeouts:1251
20150130 170217.905 (3380758272)  (1)> MQTTAsync_processCommand:937
20150130 170217.905 (3380758272)   (2)> MQTTProtocol_startPublish:147
20150130 170217.905 (3380758272)    (3)> MQTTProtocol_createMessage:175
20150130 170217.905 (3380758272)     (4)> MQTTProtocol_storePublication:210
20150130 170217.905 (3380758272)     (4)< MQTTProtocol_storePublication:230
20150130 170217.905 (3380758272)    (3)< MQTTProtocol_createMessage:195
20150130 170217.905 (3380758272)    (3)> MQTTProtocol_startPublishCommon:124
20150130 170217.905 (3380758272)     (4)> MQTTPacket_send_publish:677
20150130 170217.905 (3380758272)      (5)> MQTTPacket_sends:226
20150130 170217.905 (3380758272)       (6)> MQTTPacket_encode:268
20150130 170217.905 (3380758272)       (6)< MQTTPacket_encode:278 (1)
20150130 170217.905 (3380758272)       (6)> MQTTPersistence_put:347
20150130 170217.905 (3380758272)       (6)< MQTTPersistence_put:381 (0)
20150130 170218.905 (3380758272)       (6)> Socket_putdatas:443
20150130 170218.905 (3380758272)        (7)> Socket_writev:399
20150130 170218.905 (3380758272)        (7)< Socket_writev:420 (31)
20150130 170218.905 (3380758272)       (6)< Socket_putdatas:485 (0)
20150130 170218.905 (3380758272)      (5)< MQTTPacket_sends:253 (0)
20150130 170218.905 3 ExampleClientPub -> PUBLISH msgid: 5 qos: 1 retained: 0 (0) payload: Hello World!
20150130 170218.905 (3380758272)     (4)< MQTTPacket_send_publish:716 (0)
20150130 170218.905 (3380758272)    (3)< MQTTProtocol_startPublishCommon:128 (0)
20150130 170218.905 (3380758272)   (2)< MQTTProtocol_startPublish:158 (0)
20150130 170218.905 (3380758272)  (1)< MQTTAsync_processCommand:1169
20150130 170218.905 (3380758272)  (1)> Thread_wait_cond:402
20150130 170218.905 (3372365568)    (3)> Socket_continueWrites:777
20150130 170218.905 (3372365568)    (3)< Socket_continueWrites:799 (0)
20150130 170218.905 (3372365568)    (3)> isReady:192
20150130 170218.905 (3372365568)    (3)< isReady:197 (1)
20150130 170218.905 (3372365568)   (2)< Socket_getReadySocket:282 (3)
20150130 170218.905 (3372365568)   (2)> MQTTPacket_Factory:104
20150130 170218.905 (3372365568)    (3)> Socket_getch:297
20150130 170218.905 (3372365568)     (4)> SocketBuffer_getQueuedChar:189
20150130 170218.905 (3372365568)     (4)< SocketBuffer_getQueuedChar:208 (-22)
20150130 170218.905 (3372365568)     (4)> SocketBuffer_queueChar:268
20150130 170218.905 (3372365568)     (4)< SocketBuffer_queueChar:292
20150130 170218.905 (3372365568)    (3)< Socket_getch:318 (0)
20150130 170218.905 (3372365568)    (3)> MQTTPacket_decode:297
20150130 170218.905 (3372365568)     (4)> Socket_getch:297
20150130 170218.905 (3372365568)      (5)> SocketBuffer_getQueuedChar:189
20150130 170218.905 (3372365568)      (5)< SocketBuffer_getQueuedChar:208 (-22)
20150130 170218.905 (3372365568)      (5)> SocketBuffer_queueChar:268
20150130 170218.905 (3372365568)      (5)< SocketBuffer_queueChar:292
20150130 170218.905 (3372365568)     (4)< Socket_getch:318 (0)
20150130 170218.905 (3372365568)    (3)< MQTTPacket_decode:317 (0)
20150130 170218.905 (3372365568)    (3)> Socket_getdata:336
20150130 170218.905 (3372365568)     (4)> SocketBuffer_getQueuedData:149
20150130 170218.905 (3372365568)     (4)< SocketBuffer_getQueuedData:174
20150130 170218.905 (3372365568)     (4)> SocketBuffer_complete:244
20150130 170218.905 (3372365568)     (4)< SocketBuffer_complete:253
20150130 170218.905 (3372365568)    (3)< Socket_getdata:370
20150130 170218.905 (3372365568)    (3)> MQTTPacket_ack:653
20150130 170218.905 (3372365568)    (3)< MQTTPacket_ack:656
20150130 170218.905 (3372365568)   (2)< MQTTPacket_Factory:162 (0)
20150130 170218.905 (3372365568)   (2)> MQTTProtocol_handlePubacks:318
20150130 170218.905 3 ExampleClientPub <- PUBACK msgid: 5
20150130 170218.905 PUBACK received from client ExampleClientPub for message id 5 - removing publication
20150130 170218.905 (3372365568)    (3)> MQTTPersistence_remove:399
20150130 170218.905 (3372365568)    (3)< MQTTPersistence_remove:418 (0)
20150130 170218.905 (3372365568)    (3)> MQTTProtocol_removePublication:240
20150130 170218.905 (3372365568)    (3)< MQTTProtocol_removePublication:247
20150130 170218.905 (3372365568)   (2)< MQTTProtocol_handlePubacks:341 (0)
20150130 170218.905 Calling publish success for client ExampleClientPub
Message with token value 5 delivery confirmed
20150130 170218.905 (3372365568)   (2)> MQTTAsync_disconnect1:2083
20150130 170218.905 (3372365568)    (3)> MQTTAsync_addCommand:737
20150130 170218.905 (3372365568)    (3)< MQTTAsync_addCommand:768 (0)
20150130 170218.905 (3372365568)   (2)< MQTTAsync_disconnect1:2111 (0)
20150130 170218.905 (3372365568)   (2)> MQTTAsync_retry:2430
20150130 170218.905 (3372365568)    (3)> MQTTProtocol_retry:629
20150130 170218.905 (3372365568)    (3)< MQTTProtocol_retry:648
20150130 170218.905 (3372365568)   (2)< MQTTAsync_retry:2440
20150130 170218.905 (3372365568)  (1)< MQTTAsync_cycle:2699 (0)
20150130 170218.905 (3372365568)  (1)> MQTTAsync_cycle:2563
20150130 170218.905 (3372365568)   (2)> Socket_getReadySocket:216
20150130 170218.906 (3380758272)  (1)< Thread_wait_cond:416 (0)
20150130 170218.906 (3380758272)  (1)> Thread_wait_cond:402
20150130 170218.906 (3391796992) (0)> MQTTAsync_destroy:1360
20150130 170218.906 (3391796992)  (1)> MQTTAsync_removeResponsesAndCommands:1320
20150130 170218.906 0 responses removed for client ExampleClientPub
20150130 170218.906 1 commands removed for client ExampleClientPub
20150130 170218.906 (3391796992)  (1)< MQTTAsync_removeResponsesAndCommands:1352
20150130 170218.906 (3391796992)  (1)> MQTTStrncpy:736
20150130 170218.906 (3391796992)  (1)< MQTTStrncpy:746
20150130 170218.906 (3391796992)  (1)> MQTTPersistence_close:131
20150130 170218.906 (3391796992)  (1)< MQTTPersistence_close:143 (0)
20150130 170218.906 (3391796992)  (1)> MQTTAsync_emptyMessageQueue:1296
20150130 170218.906 (3391796992)  (1)< MQTTAsync_emptyMessageQueue:1310
20150130 170218.906 (3391796992)  (1)> MQTTProtocol_freeClient:658
20150130 170218.906 (3391796992)   (2)> MQTTProtocol_freeMessageList:716
20150130 170218.906 (3391796992)    (3)> MQTTProtocol_emptyMessageList:699
20150130 170218.906 (3391796992)    (3)< MQTTProtocol_emptyMessageList:706
20150130 170218.906 (3391796992)   (2)< MQTTProtocol_freeMessageList:719
20150130 170218.906 (3391796992)   (2)> MQTTProtocol_freeMessageList:716
20150130 170218.906 (3391796992)    (3)> MQTTProtocol_emptyMessageList:699
20150130 170218.912 (3391796992)    (3)< MQTTProtocol_emptyMessageList:706
20150130 170218.912 (3391796992)   (2)< MQTTProtocol_freeMessageList:719
20150130 170218.912 (3391796992)  (1)< MQTTProtocol_freeClient:687
20150130 170218.912 Removed client ExampleClientPub from bstate->clients, socket 3
20150130 170218.912 (3391796992)  (1)> MQTTAsync_terminate:440
20150130 170218.912 (3391796992)   (2)> MQTTAsync_stop:1697
20150130 170218.912 Conn_count is 0
20150130 170218.912 sleeping
20150130 170218.912 (3391796992)    (3)> MQTTAsync_sleep:305
20150130 170218.912 (3391796992)    (3)< MQTTAsync_sleep:311
20150130 170218.912 sleeping
20150130 170218.912 (3391796992)    (3)> MQTTAsync_sleep:305
20150130 170218.912 (3391796992)    (3)< MQTTAsync_sleep:311
20150130 170218.912 sleeping
20150130 170218.912 (3391796992)    (3)> MQTTAsync_sleep:305
20150130 170218.912 (3391796992)    (3)< MQTTAsync_sleep:311
20150130 170218.912 sleeping
20150130 170218.912 (3391796992)    (3)> MQTTAsync_sleep:305
20150130 170218.912 (3391796992)    (3)< MQTTAsync_sleep:311
20150130 170218.912 sleeping
20150130 170219.313 (3391796992)    (3)> MQTTAsync_sleep:305
20150130 170219.313 (3391796992)    (3)< MQTTAsync_sleep:311
20150130 170219.313 sleeping
20150130 170219.313 (3391796992)    (3)> MQTTAsync_sleep:305
20150130 170219.313 (3391796992)    (3)< MQTTAsync_sleep:311
20150130 170219.313 sleeping
20150130 170219.313 (3391796992)    (3)> MQTTAsync_sleep:305
20150130 170219.313 (3391796992)    (3)< MQTTAsync_sleep:311
20150130 170219.313 sleeping
20150130 170219.313 (3391796992)    (3)> MQTTAsync_sleep:305
20150130 170219.313 (3391796992)    (3)< MQTTAsync_sleep:311
20150130 170219.313 sleeping
20150130 170219.313 (3391796992)    (3)> MQTTAsync_sleep:305
20150130 170219.313 (3391796992)    (3)< MQTTAsync_sleep:311
20150130 170219.313 sleeping
20150130 170219.313 (3391796992)    (3)> MQTTAsync_sleep:305
20150130 170219.313 (3380758272)  (1)< Thread_wait_cond:416 (110)
20150130 170219.313 (3380758272)  (1)> MQTTAsync_checkTimeouts:1179
20150130 170219.313 (3380758272)  (1)< MQTTAsync_checkTimeouts:1251
20150130 170219.313 (3380758272) (0)< MQTTAsync_sendThread:1289
20150130 170219.907 (3372365568)    (3)> Socket_continueWrites:777
20150130 170219.907 (3372365568)    (3)< Socket_continueWrites:799 (0)
20150130 170219.907 (3372365568)    (3)> isReady:192
20150130 170219.907 (3372365568)    (3)< isReady:197 (0)
20150130 170219.907 (3372365568)   (2)< Socket_getReadySocket:282 (0)
20150130 170219.907 (3372365568)   (2)> MQTTAsync_retry:2430
20150130 170219.907 (3372365568)    (3)> MQTTProtocol_retry:629
20150130 170219.907 (3372365568)    (3)< MQTTProtocol_retry:648
20150130 170219.907 (3372365568)   (2)< MQTTAsync_retry:2440
20150130 170219.907 (3372365568)  (1)< MQTTAsync_cycle:2699 (-1)
20150130 170219.907 (3372365568) (0)< MQTTAsync_receiveThread:1688
20150130 170219.907 (3391796992)    (3)< MQTTAsync_sleep:311
20150130 170219.907 (3391796992)   (2)< MQTTAsync_stop:1730 (1)
20150130 170219.907 (3391796992)   (2)> Socket_outTerminate:142
20150130 170219.907 (3391796992)    (3)> SocketBuffer_terminate:111
20150130 170219.907 (3391796992)    (3)< SocketBuffer_terminate:116
20150130 170219.907 (3391796992)   (2)< Socket_outTerminate:150
20150130 170219.907 Maximum heap use was 2160 bytes

Follow-Ups:
- Re: [paho-dev] Varying Delay for MQTT Messages
  - From: Ian Craggs
- Re: [paho-dev] Varying Delay for MQTT Messages
  - From: Chris Summer

References:
- [paho-dev] Varying Delay for MQTT Messages
  - From: Chris Summer
- Re: [paho-dev] Varying Delay for MQTT Messages
  - From: Ian Craggs
- Re: [paho-dev] Varying Delay for MQTT Messages
  - From: Frank Pagliughi
- Re: [paho-dev] Varying Delay for MQTT Messages
  - From: Chris Summer
- Re: [paho-dev] Varying Delay for MQTT Messages
  - From: Ian Craggs

Prev by Date: Re: [paho-dev] Throttling on massive message publish in Java client
Next by Date: [paho-dev] Paho Java client and WebSockets
Previous by thread: Re: [paho-dev] Varying Delay for MQTT Messages
Next by thread: Re: [paho-dev] Varying Delay for MQTT Messages
Index(es):
- Date
- Thread

Breadcrumbs