Analyzing Kura Logs in CloudService MQTT

This note is about how to understand basic action in kura logs so I asume you have installed kura and mqtt working in your IoT stuff.

BeaconScanner Item

The beaconScanner is a openSource project and you can use the default code or tune your code , in this example we use the default.

The beaconScanner use the bluetooth device so we have this process running maybe it depends hardware.

 

root@rg-10-20-s0:~# ps auxww|grep -i hcidump |grep -v grep
root 12136 0.0 0.0 2132 432 ? S 22:25 0:00 hcidump -i hci0 -R -w /dev/fd/3
root@rg-10-20-s0:~#

Then you can start your BeaconScanner

018-06-10 22:35:23,923 [qtp3671452-143] WARN o.e.k.n.a.v.l.WpaSupplicantConfigReader - WPA in client mode is not configured
2018-06-10 22:35:23,930 [qtp3671452-143] WARN o.e.k.n.a.v.l.PppConfigReader - getModemConfig() :: PPPD peer file does not exist - /etc/ppp/peers/HE910-D_2-1.5
2018-06-10 22:35:24,144 [qtp3671452-143] INFO o.e.k.c.c.ConfigurationServiceImpl - Loading init configurations from: 1528669870428...
2018-06-10 22:35:24,552 [qtp3671452-143] INFO o.e.k.c.c.ConfigurationServiceImpl - Merging configuration for pid: org.eclipse.kura.example.beacon.scanner.BeaconScannerExample
2018-06-10 22:35:24,561 [qtp3671452-143] INFO o.e.k.c.c.ConfigurationServiceImpl - Updating Configuration of ConfigurableComponent org.eclipse.kura.example.beacon.scanner.BeaconScannerExample ... Done.
2018-06-10 22:35:24,597 [Component Resolve Thread (Bundle 6)] INFO o.e.k.l.b.l.BluetoothLeScanner - Starting bluetooth le beacon scan...
2018-06-10 22:35:24,788 [qtp3671452-143] INFO o.e.k.c.c.ConfigurationServiceImpl - Writing snapshot - Saving /opt/eurotech/esf/data/snapshots/snapshot_1528670124562.xml...
2018-06-10 22:35:25,372 [qtp3671452-143] INFO o.e.k.c.c.ConfigurationServiceImpl - Writing snapshot - Saving /opt/eurotech/esf/data/snapshots/snapshot_1528670124562.xml... Done.
2018-06-10 22:35:25,375 [qtp3671452-143] INFO o.e.k.c.c.ConfigurationServiceImpl - Snapshots Garbage Collector. Deleting /opt/eurotech/esf/data/snapshots/snapshot_1528665378674.xml
2018-06-10 22:35:25,839 [qtp3671452-147] WARN o.e.k.n.a.v.l.WpaSupplicantConfigReader - WPA in client mode is not configured
2018-06-10 22:35:25,845 [qtp3671452-147] WARN o.e.k.n.a.v.l.PppConfigReader - getModemConfig() :: PPPD peer file does not exist - /etc/ppp/peers/HE910-D_2-1.5
2018-06-10 22:35:26,062 [BluetoothProcess BTSnoop Gobbler] INFO o.e.k.c.d.DataServiceImpl - Storing message on topic :#account-name/#client-id/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6, priority: 5
2018-06-10 22:35:26,068 [BluetoothProcess BTSnoop Gobbler] INFO o.e.k.c.d.DataServiceImpl - Stored message on topic :#account-name/#client-id/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6, priority: 5
2018-06-10 22:35:26,081 [DataServiceImpl:Submit] INFO o.e.k.c.d.DataServiceImpl - DataPublisherService not connecte
d

The bold text show you the most important stuff, where the messages is stored, two first bold messages, then try to connect to cloud service (mqtt broker)
The third bold messages is about cloud service, from now is off.

#account-name/#client-id/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6 This is the TOPIC, the two first level are set in the kura dashboard the other one are set in the beaconScanner code.

Then after start beaconScanner two new process appear in order to use bluetooth command.
root 13218 0.0 0.0 1588 160 ? S 22:35 0:00 hcitool -i hci0 lescan-passive --duplicates
root 13220 0.0 0.2 2896 1184 ? S 22:35 0:00 /bin/bash /tmp/BluetoothUtil.btsnoopdump.sh hci0
root 13222 0.0 0.0 2132 432 ? S 22:35 0:00 hcidump -i hci0 -R -w /dev/fd/3

If we stop the beaconScanner now, those process must be killed.

2018-06-10 22:48:41,896 [Component Resolve Thread (Bundle 6)] INFO o.e.k.l.b.l.BluetoothLeScanner - Killing hcitool...
2018-06-10 22:48:41,956 [Component Resolve Thread (Bundle 6)] INFO o.e.k.l.b.l.BluetoothLeScanner - Killing btdump...
2018-06-10 22:48:41,956 [Component Resolve Thread (Bundle 6)] INFO o.e.k.l.b.u.BluetoothProcess - Closing streams and killing...

Then just only appear…

root 13222 0.0 0.0 2132 432 ? S 22:35 0:00 hcidump -i hci0 -R -w /dev/fd/3

So if you start the beaconScanner then you remove battery the logs show do not show you anymore this Beacon or if you move this beacon so far away from the scanner.

CLOUDSERVICE
This is thew way where you connect to a broker, using different protocols or services, in this case I m using the same broker created in previous post.
Let start to connect our cloud service from your kura dashboard and then checks logs.(remember we have beaconscanner running but no one beacon are on or near my scanner).

2018-06-10 22:54:20,096 [qtp3671452-42] INFO o.e.k.c.d.DataServiceImpl - Reconnect task running. Stopping it
2018-06-10 22:54:20,097 [qtp3671452-42] INFO o.e.k.c.d.t.m.MqttDataTransport - Creating a new client instance
2018-06-10 22:54:20,098 [qtp3671452-42] INFO o.e.k.c.d.t.m.MqttDataTransport - Using memory persistence for in-flight messages
2018-06-10 22:54:20,099 [qtp3671452-42] INFO o.e.k.c.d.t.m.MqttDataTransport - # ------------------------------------------------------------
2018-06-10 22:54:20,100 [qtp3671452-42] INFO o.e.k.c.d.t.m.MqttDataTransport - # Connection Properties
2018-06-10 22:54:20,101 [qtp3671452-42] INFO o.e.k.c.d.t.m.MqttDataTransport - # broker = ws://www.itrestauracion.com.ar:9001
2018-06-10 22:54:20,102 [qtp3671452-42] INFO o.e.k.c.d.t.m.MqttDataTransport - # clientId = baticueva
2018-06-10 22:54:20,103 [qtp3671452-42] INFO o.e.k.c.d.t.m.MqttDataTransport - # username = batman
2018-06-10 22:54:20,103 [qtp3671452-42] INFO o.e.k.c.d.t.m.MqttDataTransport - # password = XXXXXXXXXXXXXX
2018-06-10 22:54:20,104 [qtp3671452-42] INFO o.e.k.c.d.t.m.MqttDataTransport - # keepAlive = 30
2018-06-10 22:54:20,105 [qtp3671452-42] INFO o.e.k.c.d.t.m.MqttDataTransport - # timeout = 20
2018-06-10 22:54:20,105 [qtp3671452-42] INFO o.e.k.c.d.t.m.MqttDataTransport - # cleanSession = true
2018-06-10 22:54:20,106 [qtp3671452-42] INFO o.e.k.c.d.t.m.MqttDataTransport - # MQTT version = 3.1.1
2018-06-10 22:54:20,106 [qtp3671452-42] INFO o.e.k.c.d.t.m.MqttDataTransport - # willDestination = dc/batman/baticueva
2018-06-10 22:54:20,107 [qtp3671452-42] INFO o.e.k.c.d.t.m.MqttDataTransport - # willMessage =
2018-06-10 22:54:20,108 [qtp3671452-42] INFO o.e.k.c.d.t.m.MqttDataTransport - #
2018-06-10 22:54:20,109 [qtp3671452-42] INFO o.e.k.c.d.t.m.MqttDataTransport - # Connecting...
2018-06-10 22:54:21,206 [qtp3671452-42] INFO o.e.k.c.d.t.m.MqttDataTransport - # Connected!
2018-06-10 22:54:21,206 [qtp3671452-42] INFO o.e.k.c.d.t.m.MqttDataTransport - # ------------------------------------------------------------
2018-06-10 22:54:21,207 [qtp3671452-42] INFO o.e.k.c.d.DataServiceImpl - Notified connected
2018-06-10 22:54:21,207 [qtp3671452-42] INFO o.e.k.c.d.DataServiceImpl - New session established. Unpublishing all in-flight messages. Disregarding the QoS level, this may cause duplicate messages.
2018-06-10 22:54:21,217 [qtp3671452-42] INFO o.e.k.c.d.t.m.MqttDataTransport - Subscribing to topic: dc/dc/batman/baticueva/# with QoS: 1
2018-06-10 22:54:21,609 [qtp3671452-42] INFO o.e.k.c.Cloudlet - Cloud Client Connection Restored
2018-06-10 22:54:21,610 [qtp3671452-42] INFO o.e.k.c.Cloudlet - Cloud Client Connection Restored
2018-06-10 22:54:21,611 [qtp3671452-42] INFO o.e.k.c.Cloudlet - Cloud Client Connection Restored
2018-06-10 22:54:21,612 [qtp3671452-42] INFO o.e.k.c.Cloudlet - Cloud Client Connection Restored
2018-06-10 22:54:21,612 [qtp3671452-42] INFO o.e.k.c.Cloudlet - Cloud Client Connection Restored
2018-06-10 22:54:21,613 [qtp3671452-42] INFO o.e.k.c.Cloudlet - Cloud Client Connection Restored
2018-06-10 22:54:21,614 [qtp3671452-42] INFO o.e.k.c.p.ProvisioningServiceImpl - onConnectionEstablished
2018-06-10 22:54:21,614 [qtp3671452-42] INFO o.e.k.c.Cloudlet - Cloud Client Connection Restored
2018-06-10 22:54:21,615 [qtp3671452-42] INFO c.e.f.d.i.DiagnosticsServiceImpl - Connection established
2018-06-10 22:54:21,615 [qtp3671452-42] INFO c.e.f.d.i.DiagnosticsServiceImpl - Connection established

Here we have in the top the main data of where are you doing your connection, so you can see a lot of stuff where you set before in your dashboard.
o.e.k.c.d.t.m.MqttDataTransport – Subscribing to topic: dc/dc/batman/baticueva/# with QoS: 1 With this we are acting as subscriber so the mqtt broker are ready to receive any data scanned by our beaconScanner app. And then a lot of services to check connections.

How many messages you see in publishing depends in how you did your configuration in cloud service for kura services and a lot of values like, QoS,etc,etc.Now lets start to put battery to our beacon device.

2018-06-10 23:04:14,568 [BluetoothProcess BTSnoop Gobbler] INFO o.e.k.c.d.DataServiceImpl - Storing message on topic :#account-name/#client-id/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6, priority: 5
2018-06-10 23:04:14,574 [BluetoothProcess BTSnoop Gobbler] INFO o.e.k.c.d.DataServiceImpl - Stored message on topic :#account-name/#client-id/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6, priority: 5
2018-06-10 23:04:14,577 [DataServiceImpl:Submit] INFO o.e.k.c.d.t.m.MqttDataTransport - Publishing message on topic: dc/batman/baticueva/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6 with QoS: 0
2018-06-10 23:04:26,382 [BluetoothProcess BTSnoop Gobbler] INFO o.e.k.c.d.DataServiceImpl - Storing message on topic :#account-name/#client-id/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6, priority: 5
2018-06-10 23:04:26,385 [BluetoothProcess BTSnoop Gobbler] INFO o.e.k.c.d.DataServiceImpl - Stored message on topic :#account-name/#client-id/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6, priority: 5
2018-06-10 23:04:26,388 [DataServiceImpl:Submit] INFO o.e.k.c.d.t.m.MqttDataTransport - Publishing message on topic: dc/batman/baticueva/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6 with QoS: 0

1528671854: Received PUBLISH from baticueva (d0, q0, r0, m0, ‘dc/batman/baticueva/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6’, … (129 bytes))
1528671866: Received PUBLISH from baticueva (d0, q0, r0, m0, ‘dc/batman/baticueva/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6’, … (128 bytes))

Yo can see now that our beaconScanner detect and publish your messages.

Here we established a connection wit mqttlen client form MacOSX

Those logs are from mqtt docker logs, you can check how mqtt broker send and receive data.
1528671933: New client connected from 45.232.92.159 as maquina (c1, k120, u'batman').
1528671933: Sending CONNACK to maquina (0, 0)
1528671947: Received SUBSCRIBE from maquina
1528671947: dc/batman/baticueva/# (QoS 0)
1528671947: maquina 0 dc/batman/baticueva/#
1528671947: Sending SUBACK to maquina

Now you can check we have the client maquina that is my machine that works as subscriber getting al messages that my IOT device send to my mqtt broker.
So we have two subscriber, my broker and my client.
The beacon scanner detect the beacon and send it to my IOT that subscribe all incoming beacon detection and my client maquina connect to the broker only to specific topic, so it is the reason why we have received and sending in each cases.

1528671956: Received PINGREQ from baticueva
1528671956: Sending PINGRESP to baticueva
1528671970: Received PUBLISH from baticueva (d0, q0, r0, m0, 'dc/batman/baticueva/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6', ... (129 bytes))
1528671970: Sending PUBLISH to maquina (d0, q0, r0, m0, 'dc/batman/baticueva/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6', ... (129 bytes))

We detect the second beacon, store wit topic and store message and then send topic to brocker, The process housekeeper delete all confirmed messages.

2018-06-10 23:06:10,629 [BluetoothProcess BTSnoop Gobbler] INFO o.e.k.c.d.DataServiceImpl - Storing message on topic :#account-name/#client-id/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6, priority: 5
2018-06-10 23:06:10,632 [BluetoothProcess BTSnoop Gobbler] INFO o.e.k.c.d.DataServiceImpl - Stored message on topic :#account-name/#client-id/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6, priority: 5
2018-06-10 23:06:10,635 [DataServiceImpl:Submit] INFO o.e.k.c.d.t.m.MqttDataTransport - Publishing message on topic: dc/batman/baticueva/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6 with QoS: 0
2018-06-10 23:09:04,357 [HouseKeeperTask] INFO o.e.k.c.d.s.HouseKeeperTask - HouseKeeperTask started.
2018-06-10 23:09:04,357 [HouseKeeperTask] INFO o.e.k.c.d.s.HouseKeeperTask - HouseKeeperTask: Delete confirmed messages...
2018-06-10 23:09:04,441 [HouseKeeperTask] INFO o.e.k.c.d.s.HouseKeeperTask - HouseKeeperTask ended.

Now we can put the battery again and just wait a while in order to publish hundred of messages….
After that test, try to remove battery or go far away with your beacon and the logs will stop, then go back with beacon and stop cloud service in order to scan beacon and store it.

2018-06-10 23:24:42,546 [qtp3671452-147] WARN o.e.k.n.a.v.l.WpaSupplicantConfigReader - WPA in client mode is not configured
2018-06-10 23:24:42,551 [qtp3671452-147] WARN o.e.k.n.a.v.l.PppConfigReader - getModemConfig() :: PPPD peer file does not exist - /etc/ppp/peers/HE910-D_2-1.5
2018-06-10 23:24:42,770 [qtp3671452-147] INFO o.e.k.c.c.ConfigurationServiceImpl - Loading init configurations from: 1528671660393...
2018-06-10 23:24:43,181 [qtp3671452-147] INFO o.e.k.c.c.ConfigurationServiceImpl - Merging configuration for pid: org.eclipse.kura.data.DataService
2018-06-10 23:24:43,192 [qtp3671452-147] INFO o.e.k.c.c.ConfigurationServiceImpl - Updating Configuration of ConfigurableComponent org.eclipse.kura.data.DataService ... Done.
2018-06-10 23:24:43,210 [Component Resolve Thread (Bundle 6)] INFO o.e.k.c.d.DataServiceImpl - Updating org.eclipse.kura.data.DataService...
2018-06-10 23:24:43,211 [Component Resolve Thread (Bundle 6)] INFO o.e.k.c.d.DataServiceImpl - Get Throttle with burst length 3 and send a message every 3000 millis
2018-06-10 23:24:43,448 [qtp3671452-147] INFO o.e.k.c.c.ConfigurationServiceImpl - Writing snapshot - Saving /opt/eurotech/esf/data/snapshots/snapshot_1528673083193.xml...
2018-06-10 23:24:43,770 [qtp3671452-147] INFO o.e.k.c.c.ConfigurationServiceImpl - Writing snapshot - Saving /opt/eurotech/esf/data/snapshots/snapshot_1528673083193.xml... Done.
2018-06-10 23:24:43,773 [qtp3671452-147] INFO o.e.k.c.c.ConfigurationServiceImpl - Snapshots Garbage Collector. Deleting /opt/eurotech/esf/data/snapshots/snapshot_1528669530806.xml
2018-06-10 23:24:44,216 [HouseKeeperTask] INFO o.e.k.c.d.s.HouseKeeperTask - HouseKeeperTask started.
2018-06-10 23:24:44,216 [HouseKeeperTask] INFO o.e.k.c.d.s.HouseKeeperTask - HouseKeeperTask: Delete confirmed messages...
2018-06-10 23:24:44,219 [HouseKeeperTask] INFO o.e.k.c.d.s.HouseKeeperTask - HouseKeeperTask ended.
2018-06-10 23:24:51,165 [qtp3671452-146] INFO o.e.k.c.d.t.m.MqttDataTransport - Disconnecting...
2018-06-10 23:24:51,166 [qtp3671452-146] INFO o.e.k.c.d.DataServiceImpl - Notified disconnecting

Stopped CloudService and deactivate te auto start.

we can see now a lot of messages like this.

2018-06-10 23:25:15,886 [BluetoothProcess BTSnoop Gobbler] INFO o.e.k.c.d.DataServiceImpl - Storing message on topic :#account-name/#client-id/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6, priority: 5
2018-06-10 23:25:15,889 [BluetoothProcess BTSnoop Gobbler] INFO o.e.k.c.d.DataServiceImpl - Stored message on topic :#account-name/#client-id/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6, priority: 5
2018-06-10 23:25:15,890 [DataServiceImpl:Submit] INFO o.e.k.c.d.DataServiceImpl - DataPublisherService not connected
2018-06-10 23:25:26,711 [BluetoothProcess BTSnoop Gobbler] INFO o.e.k.c.d.DataServiceImpl - Storing message on topic :#account-name/#client-id/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6, priority: 5
2018-06-10 23:25:26,714 [BluetoothProcess BTSnoop Gobbler] INFO o.e.k.c.d.DataServiceImpl - Stored message on topic :#account-name/#client-id/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6, priority: 5
2018-06-10 23:25:26,715 [DataServiceImpl:Submit] INFO o.e.k.c.d.DataServiceImpl - DataPublisherService not connected
2018-06-10 23:25:37,533 [BluetoothProcess BTSnoop Gobbler] INFO o.e.k.c.d.DataServiceImpl - Storing message on topic :#account-name/#client-id/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6, priority: 5
2018-06-10 23:25:37,536 [BluetoothProcess BTSnoop Gobbler] INFO o.e.k.c.d.DataServiceImpl - Stored message on topic :#account-name/#client-id/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6, priority: 5
2018-06-10 23:25:37,536 [DataServiceImpl:Submit] INFO o.e.k.c.d.DataServiceImpl - DataPublisherService not connected

It is because the beacon is there but the cloud service is inactive.Lets wait to store a some of then and stop beacon scanner.

2018-06-10 23:28:04,818 [Component Resolve Thread (Bundle 6)] INFO o.e.k.l.b.l.BluetoothLeScanner - Killing hcitool...
2018-06-10 23:28:04,884 [Component Resolve Thread (Bundle 6)] INFO o.e.k.l.b.l.BluetoothLeScanner - Killing btdump...
2018-06-10 23:28:04,884 [Component Resolve Thread (Bundle 6)] INFO o.e.k.l.b.u.BluetoothProcess - Closing streams and killing...

Now lets go to connect cloud service again.

So old stored messages are there
2018-06-10 23:28:49,972 [DataServiceImpl:Submit] INFO o.e.k.c.d.t.m.MqttDataTransport - Publishing message on topic: dc/batman/baticueva/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6 with QoS: 0
2018-06-10 23:28:52,972 [DataServiceImpl:Submit] INFO o.e.k.c.d.t.m.MqttDataTransport - Publishing message on topic: dc/batman/baticueva/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6 with QoS: 0
2018-06-10 23:28:55,973 [DataServiceImpl:Submit] INFO o.e.k.c.d.t.m.MqttDataTransport - Publishing message on topic: dc/batman/baticueva/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6 with QoS: 0
2018-06-10 23:28:58,972 [DataServiceImpl:Submit] INFO o.e.k.c.d.t.m.MqttDataTransport - Publishing message on topic: dc/batman/baticueva/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6 with QoS: 0
2018-06-10 23:29:01,972 [DataServiceImpl:Submit] INFO o.e.k.c.d.t.m.MqttDataTransport - Publishing message on topic: dc/batman/baticueva/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6 with QoS: 0
2018-06-10 23:29:04,972 [DataServiceImpl:Submit] INFO o.e.k.c.d.t.m.MqttDataTransport - Publishing message on topic: dc/batman/baticueva/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6 with QoS: 0
2018-06-10 23:29:07,972 [DataServiceImpl:Submit] INFO o.e.k.c.d.t.m.MqttDataTransport - Publishing message on topic: dc/batman/baticueva/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6 with QoS: 0
2018-06-10 23:29:10,972 [DataServiceImpl:Submit] INFO o.e.k.c.d.t.m.MqttDataTransport - Publishing message on topic: dc/batman/baticueva/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6 with QoS: 0
2018-06-10 23:29:13,972 [DataServiceImpl:Submit] INFO o.e.k.c.d.t.m.MqttDataTransport - Publishing message on topic: dc/batman/baticueva/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6 with QoS: 0
2018-06-10 23:29:16,972 [DataServiceImpl:Submit] INFO o.e.k.c.d.t.m.MqttDataTransport - Publishing message on topic: dc/batman/baticueva/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6 with QoS: 0
2018-06-10 23:29:19,972 [DataServiceImpl:Submit] INFO o.e.k.c.d.t.m.MqttDataTransport - Publishing message on topic: dc/batman/baticueva/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6 with QoS: 0
2018-06-10 23:29:22,972 [DataServiceImpl:Submit] INFO o.e.k.c.d.t.m.MqttDataTransport - Publishing message on topic: dc/batman/baticueva/BeaconScannerExample/beacons/AC:23:3F:24:9A:

and we can check that are recived by broker.
1528673328: Received PUBLISH from baticueva (d0, q0, r0, m0, 'dc/batman/baticueva/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6', ... (130 bytes))
1528673328: Sending PUBLISH to maquina (d0, q0, r0, m0, 'dc/batman/baticueva/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6', ... (130 bytes))
1528673329: Received PUBLISH from baticueva (d0, q0, r0, m0, 'dc/batman/baticueva/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6', ... (130 bytes))
1528673329: Sending PUBLISH to maquina (d0, q0, r0, m0, 'dc/batman/baticueva/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6', ... (130 bytes))
1528673329: Received PUBLISH from baticueva (d0, q0, r0, m0, 'dc/batman/baticueva/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6', ... (130 bytes))
1528673329: Sending PUBLISH to maquina (d0, q0, r0, m0, 'dc/batman/baticueva/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6', ... (130 bytes))
1528673330: Received PUBLISH from baticueva (d0, q0, r0, m0, 'dc/batman/baticueva/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6', ... (130 bytes))
1528673330: Sending PUBLISH to maquina (d0, q0, r0, m0, 'dc/batman/baticueva/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6', ... (130 bytes))
1528673333: Received PUBLISH from baticueva (d0, q0, r0, m0, 'dc/batman/baticueva/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6', ... (129 bytes))
1528673333: Sending PUBLISH to maquina (d0, q0, r0, m0, 'dc/batman/baticueva/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6', ... (129 bytes))
1528673336: Received PUBLISH from baticueva (d0, q0, r0, m0, 'dc/batman/baticueva/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6', ... (128 bytes))
1528673336: Sending PUBLISH to maquina (d0, q0, r0, m0, 'dc/batman/baticueva/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6', ... (128 bytes))
1528673339: Received PUBLISH from baticueva (d0, q0, r0, m0, 'dc/batman/baticueva/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6', ... (129 bytes))
1528673339: Sending PUBLISH to maquina (d0, q0, r0, m0, 'dc/batman/baticueva/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6', ... (129 bytes))
1528673342: Received PUBLISH from baticueva (d0, q0, r0, m0, 'dc/batman/baticueva/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6', ... (130 bytes))
1528673342: Sending PUBLISH to maquina (d0, q0, r0, m0, 'dc/batman/baticueva/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6', ... (130 bytes))
1528673345: Received PUBLISH from baticueva (d0, q0, r0, m0, 'dc/batman/baticueva/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6', ... (130 bytes))
1528673345: Sending PUBLISH to maquina (d0, q0, r0, m0, 'dc/batman/baticueva/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6', ... (130 bytes))
1528673348: Received PUBLISH from baticueva (d0, q0, r0, m0, 'dc/batman/baticueva/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6', ... (130 bytes))
1528673348: Sending PUBLISH to maquina (d0, q0, r0, m0, 'dc/batman/baticueva/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6', ... (130 bytes))
1528673351: Received PUBLISH from baticueva (d0, q0, r0, m0, 'dc/batman/baticueva/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6', ... (130 bytes))
1528673351: Sending PUBLISH to maquina (d0, q0, r0, m0, 'dc/batman/baticueva/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6', ... (130 bytes))
1528673354: Received PUBLISH from baticueva (d0, q0, r0, m0, 'dc/batman/baticueva/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6', ... (130 bytes))
1528673354: Sending PUBLISH to maquina (d0, q0, r0, m0, 'dc/batman/baticueva/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6', ... (130 bytes))
1528673357: Received PUBLISH from baticueva (d0, q0, r0, m0, 'dc/batman/baticueva/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6', ... (130 bytes))
1528673357: Sending PUBLISH to maquina (d0, q0, r0, m0, 'dc/batman/baticueva/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6', ... (130 bytes))
1528673360: Received PUBLISH from baticueva (d0, q0, r0, m0, 'dc/batman/baticueva/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6', ... (130 bytes))
1528673360: Sending PUBLISH to maquina (d0, q0, r0, m0, 'dc/batman/baticueva/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6', ... (130 bytes))
1528673363: Received PUBLISH from baticueva (d0, q0, r0, m0, 'dc/batman/baticueva/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6', ... (130 bytes))
1528673363: Sending PUBLISH to maquina (d0, q0, r0, m0, 'dc/batman/baticueva/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6', ... (130 bytes))
1528673366: Received PUBLISH from baticueva (d0, q0, r0, m0, 'dc/batman/baticueva/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6', ... (130 bytes))
1528673366: Sending PUBLISH to maquina (d0, q0, r0, m0, 'dc/batman/baticueva/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6', ... (130 bytes))
1528673369: Received PUBLISH from baticueva (d0, q0, r0, m0, 'dc/batman/baticueva/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6', ... (130 bytes))
1528673369: Sending PUBLISH to maquina (d0, q0, r0, m0, 'dc/batman/baticueva/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6', ... (130 bytes))
1528673374: Received PINGREQ from maquina

And then after a while they stop , because no more messages are in the queue .

And when we start again beaconscanner start again to detect and publish.
2018-06-10 23:31:17,121 [Component Resolve Thread (Bundle 6)] INFO o.e.k.l.b.l.BluetoothLeScanner - Starting bluetooth le beacon scan...
2018-06-10 23:31:17,315 [qtp3671452-147] INFO o.e.k.c.c.ConfigurationServiceImpl - Writing snapshot - Saving /opt/eurotech/esf/data/snapshots/snapshot_1528673477084.xml...
2018-06-10 23:31:17,575 [BluetoothProcess BTSnoop Gobbler] INFO o.e.k.c.d.DataServiceImpl - Storing message on topic :#account-name/#client-id/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6, priority: 5
2018-06-10 23:31:17,581 [BluetoothProcess BTSnoop Gobbler] INFO o.e.k.c.d.DataServiceImpl - Stored message on topic :#account-name/#client-id/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6, priority: 5
2018-06-10 23:31:17,583 [DataServiceImpl:Submit] INFO o.e.k.c.d.t.m.MqttDataTransport - Publishing message on topic: dc/batman/baticueva/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6 with QoS: 0

Now, the messages are there in broker.

1528673477: Received PUBLISH from baticueva (d0, q0, r0, m0, 'dc/batman/baticueva/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6', ... (130 bytes))
1528673477: Sending PUBLISH to maquina (d0, q0, r0, m0, 'dc/batman/baticueva/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6', ... (130 bytes))
1528673490: Received PUBLISH from baticueva (d0, q0, r0, m0, 'dc/batman/baticueva/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6', ... (130 bytes))
1528673490: Sending PUBLISH to maquina (d0, q0, r0, m0, 'dc/batman/baticueva/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6', ... (130 bytes))
1528673494: Received PINGREQ from maquina

Disconnect the cloud service from broker, lets try to store messages and check what happen after change the option in kura dashboard where show you
1528673949: Received PUBLISH from baticueva (d0, q0, r0, m0, 'dc/batman/baticueva/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6', ... (130 bytes))
1528673949: Sending PUBLISH to maquina (d0, q0, r0, m0, 'dc/batman/baticueva/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6', ... (130 bytes))
1528673960: Received PUBLISH from baticueva (d0, q0, r0, m0, 'dc/batman/baticueva/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6', ... (130 bytes))
1528673960: Sending PUBLISH to maquina (d0, q0, r0, m0, 'dc/batman/baticueva/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6', ... (130 bytes))
1528673964: Received DISCONNECT from baticueva
1528673965: Client baticueva disconnected.

Messages still apearing and sending all of them…

2018-06-10 23:44:46,860 [DataServiceImpl:ReconnectTask] INFO o.e.k.c.d.t.m.MqttDataTransport - # Connected!
2018-06-10 23:44:46,860 [DataServiceImpl:ReconnectTask] INFO o.e.k.c.d.t.m.MqttDataTransport - # ------------------------------------------------------------
2018-06-10 23:44:46,860 [DataServiceImpl:ReconnectTask] INFO o.e.k.c.d.DataServiceImpl - Notified connected
2018-06-10 23:44:46,861 [DataServiceImpl:ReconnectTask] INFO o.e.k.c.d.DataServiceImpl - New session established. Dropping all in-flight messages.
2018-06-10 23:44:46,863 [DataServiceImpl:ReconnectTask] INFO o.e.k.c.d.t.m.MqttDataTransport - Subscribing to topic: dc/dc/batman/baticueva/# with QoS: 1
2018-06-10 23:44:47,240 [DataServiceImpl:ReconnectTask] INFO o.e.k.c.Cloudlet - Cloud Client Connection Restored
2018-06-10 23:44:47,241 [DataServiceImpl:ReconnectTask] INFO o.e.k.c.Cloudlet - Cloud Client Connection Restored
2018-06-10 23:44:47,241 [DataServiceImpl:ReconnectTask] INFO o.e.k.c.Cloudlet - Cloud Client Connection Restored
2018-06-10 23:44:47,242 [DataServiceImpl:ReconnectTask] INFO o.e.k.c.Cloudlet - Cloud Client Connection Restored
2018-06-10 23:44:47,242 [DataServiceImpl:ReconnectTask] INFO o.e.k.c.Cloudlet - Cloud Client Connection Restored
2018-06-10 23:44:47,243 [DataServiceImpl:ReconnectTask] INFO o.e.k.c.Cloudlet - Cloud Client Connection Restored
2018-06-10 23:44:47,243 [DataServiceImpl:ReconnectTask] INFO o.e.k.c.p.ProvisioningServiceImpl - onConnectionEstablished
2018-06-10 23:44:47,244 [DataServiceImpl:ReconnectTask] INFO o.e.k.c.Cloudlet - Cloud Client Connection Restored
2018-06-10 23:44:47,244 [DataServiceImpl:ReconnectTask] INFO c.e.f.d.i.DiagnosticsServiceImpl - Connection established
2018-06-10 23:44:47,245 [DataServiceImpl:ReconnectTask] INFO c.e.f.d.i.DiagnosticsServiceImpl - Connection established
2018-06-10 23:44:47,255 [DataServiceImpl:ReconnectTask] INFO o.e.k.c.d.DataServiceImpl - Connected. Reconnect task will be terminated.
2018-06-10 23:44:47,264 [DataServiceImpl:Submit] INFO o.e.k.c.d.t.m.MqttDataTransport - Publishing message on topic: dc/batman/baticueva/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6 with QoS: 0
2018-06-10 23:44:47,286 [DataServiceImpl:Submit] INFO o.e.k.c.d.t.m.MqttDataTransport - Publishing message on topic: dc/batman/baticueva/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6 with QoS: 0
2018-06-10 23:44:47,290 [DataServiceImpl:Submit] INFO o.e.k.c.d.t.m.MqttDataTransport - Publishing message on topic: dc/batman/baticueva/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6 with QoS: 0
2018-06-10 23:44:47,613 [qtp3671452-143] WARN o.e.k.n.a.v.l.WpaSupplicantConfigReader - WPA in client mode is not configured
2018-06-10 23:44:47,619 [qtp3671452-143] WARN o.e.k.n.a.v.l.PppConfigReader - getModemConfig() :: PPPD peer file does not exist - /etc/ppp/peers/HE910-D_2-1.5
2018-06-10 23:44:48,238 [qtp3671452-110] WARN o.e.k.n.a.v.l.WpaSupplicantConfigReader - WPA in client mode is not configured
2018-06-10 23:44:48,244 [qtp3671452-110] WARN o.e.k.n.a.v.l.PppConfigReader - getModemConfig() :: PPPD peer file does not exist - /etc/ppp/peers/HE910-D_2-1.5
2018-06-10 23:44:48,448 [BluetoothProcess BTSnoop Gobbler] INFO o.e.k.c.d.DataServiceImpl - Storing message on topic :#account-name/#client-id/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6, priority: 5
2018-06-10 23:44:48,463 [BluetoothProcess BTSnoop Gobbler] INFO o.e.k.c.d.DataServiceImpl - Stored message on topic :#account-name/#client-id/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6, priority: 5
2018-06-10 23:44:48,602 [DataServiceImpl:Submit] INFO o.e.k.c.d.t.m.MqttDataTransport - Publishing message on topic: dc/batman/baticueva/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6 with QoS: 0
2018-06-10 23:44:51,603 [DataServiceImpl:Submit] INFO o.e.k.c.d.t.m.MqttDataTransport - Publishing message on topic: dc/batman/baticueva/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6 with QoS: 0
2018-06-10 23:44:54,602 [DataServiceImpl:Submit] INFO o.e.k.c.d.t.m.MqttDataTransport - Publishing message on topic: dc/batman/baticueva/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6 with QoS: 0
2018-06-10 23:44:57,602 [DataServiceImpl:Submit] INFO o.e.k.c.d.t.m.MqttDataTransport - Publishing message on topic: dc/batman/baticueva/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6 with QoS: 0
2018-06-10 23:44:59,267 [BluetoothProcess BTSnoop Gobbler] INFO o.e.k.c.d.DataServiceImpl - Storing message on topic :#account-name/#client-id/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6, priority: 5
2018-06-10 23:44:59,279 [BluetoothProcess BTSnoop Gobbler] INFO o.e.k.c.d.DataServiceImpl - Stored message on topic :#account-name/#client-id/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6, priority: 5
2018-06-10 23:45:00,602 [DataServiceImpl:Submit] INFO o.e.k.c.d.t.m.MqttDataTransport - Publishing message on topic: dc/batman/baticueva/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6 with QoS: 0
2018-06-10 23:45:03,603 [DataServiceImpl:Submit] INFO o.e.k.c.d.t.m.MqttDataTransport - Publishing message on topic: dc/batman/baticueva/BeaconScannerExample/beacons/AC:23:3F:24:9A:C6 with QoS: 0

So, let try to read and read and test to understand why this is happening …

Leave a Reply