search

bmartin5692 / bumper

A standalone and self-hosted implementation of the central server used by Ecovacs vacuum robots.
GNU General Public License v3.0
301 stars 50 forks source link

MQTT connection failed #64

Closed Tutmanichtun closed 4 years ago

Tutmanichtun commented 4 years ago

Describe the bug After i start bumper on my Pi, i get a few Warnings and an Error regarding MQTT functionality, and neither the vacuum nor my mobile are able to connect. A ping from my Laptop shows that the DNS-Forwarding works as expected. I had a few other issues durings installation, which i was able to solve myself:

To Reproduce Steps to reproduce the behavior:

  1. Log into RPi
  2. execute "pipenv run python3.8 -m bumper"

Expected behavior Normal startup ;)

Screenshots

pi@DNS-Pi:~/bumper $ pipenv run python3.8 -m bumper
[2019-12-18 01:49:47,872] :: INFO :: bumper :: Starting Bumper
[2019-12-18 01:49:47,875] :: INFO :: mqttserver :: Starting MQTT Server at 127.0.1.1:8883
[2019-12-18 01:49:48,129] :: INFO :: xmppserver :: Starting XMPP Server at 127.0.1.1:5223
[2019-12-18 01:49:48,131] :: WARNING :: hbmqtt.client :: MQTT connection failed: ConnectionRefusedError(111, "Connect call failed ('127.0.1.1', 8883)")
[2019-12-18 01:49:48,132] :: WARNING :: hbmqtt.client :: Connection failed: ConnectException(ConnectionRefusedError(111, "Connect call failed ('127.0.1.1', 8883)"))
[2019-12-18 01:49:49,147] :: WARNING :: hbmqtt.client :: MQTT connection failed: ConnectionRefusedError(111, "Connect call failed ('127.0.1.1', 8883)")
[2019-12-18 01:49:49,150] :: WARNING :: hbmqtt.client :: Reconnection attempt failed: ConnectException(ConnectionRefusedError(111, "Connect call failed ('127.0.1.1', 8883)"))
[2019-12-18 01:49:51,157] :: WARNING :: hbmqtt.client :: MQTT connection failed: ConnectionRefusedError(111, "Connect call failed ('127.0.1.1', 8883)")
[2019-12-18 01:49:51,160] :: WARNING :: hbmqtt.client :: Reconnection attempt failed: ConnectException(ConnectionRefusedError(111, "Connect call failed ('127.0.1.1', 8883)"))
[2019-12-18 01:49:55,168] :: WARNING :: hbmqtt.client :: MQTT connection failed: ConnectionRefusedError(111, "Connect call failed ('127.0.1.1', 8883)")
[2019-12-18 01:49:55,170] :: WARNING :: hbmqtt.client :: Reconnection attempt failed: ConnectException(ConnectionRefusedError(111, "Connect call failed ('127.0.1.1', 8883)"))
[2019-12-18 01:49:55,172] :: ERROR :: hbmqtt.client :: Maximum number of connection attempts reached. Reconnection aborted

Desktop:

Smartphone:

Vacuum:

bmartin5692 commented 4 years ago

I haven't tested on a Pi in a while, especially the create certs piece.

Have you tried using the listen/announce parameters to set the IP? https://github.com/bmartin5692/bumper#command-line-usage

Let me know if that does the trick for starting it properly. Otherwise running with debug could help shed some light as well.

Tutmanichtun commented 4 years ago

No, i haven't tried these yet. A quick test shows me that the "listen" IP is the one where the XMPP and MQTT-Servers want to connect to (default is Loopback), so i tried the IP of the Raspberry itself, where bumper should run: same Error messages (with a different IP, of course ;) ). But i don't know what is meant by "announce". Here is the additional Debug-Output:

pi@DNS-Pi:~/bumper $ pipenv run python3.8 -m bumper --listen 192.168.230.2 --announce 192.168.230.2 --debug
[2019-12-20 06:43:32,079] :: INFO :: bumper :: __init__ :: start :: 179 :: Starting Bumper
[2019-12-20 06:43:32,118] :: INFO :: mqttserver :: mqttserver :: broker_coro :: 214 :: Starting MQTT Server at 192.168.230.2:8883
[2019-12-20 06:43:32,124] :: DEBUG :: hbmqtt.broker.plugins :: manager :: _load_plugins :: 61 :: Loading plugins for namespace hbmqtt.broker.plugins
[2019-12-20 06:43:32,124] :: DEBUG :: hbmqtt.broker.plugins :: manager :: _load_plugin :: 69 ::  Loading plugin bumper = bumper.mqttserver:BumperMQTTServer_Plugin
[2019-12-20 06:43:32,125] :: DEBUG :: hbmqtt.broker.plugins :: manager :: _load_plugin :: 71 ::  Initializing plugin bumper = bumper.mqttserver:BumperMQTTServer_Plugin
[2019-12-20 06:43:32,127] :: DEBUG :: hbmqtt.broker.plugins :: manager :: _load_plugins :: 65 ::  Plugin bumper ready
[2019-12-20 06:43:32,137] :: DEBUG :: hbmqtt.broker.plugins :: manager :: _load_plugin :: 69 ::  Loading plugin auth_anonymous = hbmqtt.plugins.authentication:AnonymousAuthPlugin
[2019-12-20 06:43:32,461] :: DEBUG :: hbmqtt.broker.plugins :: manager :: _load_plugin :: 71 ::  Initializing plugin auth_anonymous = hbmqtt.plugins.authentication:AnonymousAuthPlugin
[2019-12-20 06:43:32,463] :: DEBUG :: hbmqtt.broker.plugins :: manager :: _load_plugins :: 65 ::  Plugin auth_anonymous ready
[2019-12-20 06:43:32,464] :: DEBUG :: hbmqtt.broker.plugins :: manager :: _load_plugin :: 69 ::  Loading plugin auth_file = hbmqtt.plugins.authentication:FileAuthPlugin
[2019-12-20 06:43:32,469] :: DEBUG :: hbmqtt.broker.plugins :: manager :: _load_plugin :: 71 ::  Initializing plugin auth_file = hbmqtt.plugins.authentication:FileAuthPlugin
[2019-12-20 06:43:32,471] :: DEBUG :: hbmqtt.broker.plugins.auth_file :: authentication :: _read_password_file :: 63 :: Reading user database from /home/pi/bumper/bumper/passwd
[2019-12-20 06:43:32,474] :: DEBUG :: hbmqtt.client.plugins :: manager :: _load_plugins :: 61 :: Loading plugins for namespace hbmqtt.client.plugins
[2019-12-20 06:43:32,476] :: DEBUG :: hbmqtt.client.plugins :: manager :: _load_plugin :: 69 ::  Loading plugin packet_logger_plugin = hbmqtt.plugins.logging:PacketLoggerPlugin
[2019-12-20 06:43:32,484] :: DEBUG :: hbmqtt.client.plugins :: manager :: _load_plugin :: 71 ::  Initializing plugin packet_logger_plugin = hbmqtt.plugins.logging:PacketLoggerPlugin
[2019-12-20 06:43:32,485] :: DEBUG :: hbmqtt.client.plugins :: manager :: _load_plugins :: 65 ::  Plugin packet_logger_plugin ready
[2019-12-20 06:43:32,493] :: DEBUG :: hbmqtt.client :: client :: connect :: 140 :: Connect to: mqtts://192.168.230.2:8883/
[2019-12-20 06:43:32,551] :: INFO :: xmppserver :: xmppserver :: start_async_server :: 29 :: Starting XMPP Server at 192.168.230.2:5223
[2019-12-20 06:43:32,565] :: WARNING :: hbmqtt.client :: client :: _connect_coro :: 426 :: MQTT connection failed: ConnectionRefusedError(111, "Connect call failed ('192.168.230.2', 8883)")
[2019-12-20 06:43:32,567] :: WARNING :: hbmqtt.client :: client :: connect :: 145 :: Connection failed: ConnectException(ConnectionRefusedError(111, "Connect call failed ('192.168.230.2', 8883)"))
[2019-12-20 06:43:32,568] :: DEBUG :: hbmqtt.client :: client :: reconnect :: 193 :: Reconnecting with session parameters: Session(clientId=helper1@bumper/helper1, state=disconnected)
[2019-12-20 06:43:33,573] :: DEBUG :: hbmqtt.client :: client :: reconnect :: 200 :: Reconnect attempt 1 ...
[2019-12-20 06:43:33,586] :: WARNING :: hbmqtt.client :: client :: _connect_coro :: 426 :: MQTT connection failed: ConnectionRefusedError(111, "Connect call failed ('192.168.230.2', 8883)")
[2019-12-20 06:43:33,588] :: WARNING :: hbmqtt.client :: client :: reconnect :: 203 :: Reconnection attempt failed: ConnectException(ConnectionRefusedError(111, "Connect call failed ('192.168.230.2', 8883)"))
[2019-12-20 06:43:33,589] :: DEBUG :: hbmqtt.client :: client :: reconnect :: 209 :: Waiting 2 second before next attempt
[2019-12-20 06:43:35,594] :: DEBUG :: hbmqtt.client :: client :: reconnect :: 200 :: Reconnect attempt 2 ...
[2019-12-20 06:43:35,607] :: WARNING :: hbmqtt.client :: client :: _connect_coro :: 426 :: MQTT connection failed: ConnectionRefusedError(111, "Connect call failed ('192.168.230.2', 8883)")
[2019-12-20 06:43:35,608] :: WARNING :: hbmqtt.client :: client :: reconnect :: 203 :: Reconnection attempt failed: ConnectException(ConnectionRefusedError(111, "Connect call failed ('192.168.230.2', 8883)"))
[2019-12-20 06:43:35,609] :: DEBUG :: hbmqtt.client :: client :: reconnect :: 209 :: Waiting 4 second before next attempt
[2019-12-20 06:43:39,614] :: DEBUG :: hbmqtt.client :: client :: reconnect :: 200 :: Reconnect attempt 3 ...
[2019-12-20 06:43:39,627] :: WARNING :: hbmqtt.client :: client :: _connect_coro :: 426 :: MQTT connection failed: ConnectionRefusedError(111, "Connect call failed ('192.168.230.2', 8883)")
[2019-12-20 06:43:39,629] :: WARNING :: hbmqtt.client :: client :: reconnect :: 203 :: Reconnection attempt failed: ConnectException(ConnectionRefusedError(111, "Connect call failed ('192.168.230.2', 8883)"))
[2019-12-20 06:43:39,630] :: ERROR :: hbmqtt.client :: client :: reconnect :: 205 :: Maximum number of connection attempts reached. Reconnection aborted
bmartin5692 commented 4 years ago

@Tutmanichtun - Delete the passwd file you created, it is not needed and may be causing issues.

Once you do that, try running again in debug. After your run if it doesn't work, could you provide the mqttserver.log file?

Tutmanichtun commented 4 years ago

This is the output of the command itself:

pi@DNS-Pi:~/bumper $ pipenv run python3.8 -m bumper --listen 192.168.230.2 --announce 192.168.230.2 --debug
[2019-12-26 21:31:49,346] :: INFO :: bumper :: __init__ :: start :: 179 :: Starting Bumper
[2019-12-26 21:31:49,359] :: INFO :: mqttserver :: mqttserver :: broker_coro :: 214 :: Starting MQTT Server at 192.168.230.2:8883
[2019-12-26 21:31:49,364] :: DEBUG :: hbmqtt.broker.plugins :: manager :: _load_plugins :: 61 :: Loading plugins for namespace hbmqtt.broker.plugins
[2019-12-26 21:31:49,365] :: DEBUG :: hbmqtt.broker.plugins :: manager :: _load_plugin :: 69 ::  Loading plugin bumper = bumper.mqttserver:BumperMQTTServer_Plugin
[2019-12-26 21:31:49,366] :: DEBUG :: hbmqtt.broker.plugins :: manager :: _load_plugin :: 71 ::  Initializing plugin bumper = bumper.mqttserver:BumperMQTTServer_Plugin
[2019-12-26 21:31:49,368] :: DEBUG :: hbmqtt.broker.plugins :: manager :: _load_plugins :: 65 ::  Plugin bumper ready
[2019-12-26 21:31:49,378] :: DEBUG :: hbmqtt.broker.plugins :: manager :: _load_plugin :: 69 ::  Loading plugin auth_anonymous = hbmqtt.plugins.authentication:AnonymousAuthPlugin
[2019-12-26 21:31:49,679] :: DEBUG :: hbmqtt.broker.plugins :: manager :: _load_plugin :: 71 ::  Initializing plugin auth_anonymous = hbmqtt.plugins.authentication:AnonymousAuthPlugin
[2019-12-26 21:31:49,680] :: DEBUG :: hbmqtt.broker.plugins :: manager :: _load_plugins :: 65 ::  Plugin auth_anonymous ready
[2019-12-26 21:31:49,682] :: DEBUG :: hbmqtt.broker.plugins :: manager :: _load_plugin :: 69 ::  Loading plugin auth_file = hbmqtt.plugins.authentication:FileAuthPlugin
[2019-12-26 21:31:49,687] :: DEBUG :: hbmqtt.broker.plugins :: manager :: _load_plugin :: 71 ::  Initializing plugin auth_file = hbmqtt.plugins.authentication:FileAuthPlugin
[2019-12-26 21:31:49,688] :: WARNING :: hbmqtt.broker.plugins.auth_file :: authentication :: _read_password_file :: 73 :: Password file /home/pi/bumper/bumper/passwd not found
[2019-12-26 21:31:49,689] :: DEBUG :: hbmqtt.broker.plugins :: manager :: _load_plugins :: 65 ::  Plugin auth_file ready
[2019-12-26 21:31:49,690] :: DEBUG :: hbmqtt.broker.plugins :: manager :: _load_plugin :: 69 ::  Loading plugin broker_sys = hbmqtt.plugins.sys.broker:BrokerSysPlugin
[2019-12-26 21:31:49,701] :: DEBUG :: hbmqtt.broker.plugins :: manager :: _load_plugin :: 71 ::  Initializing plugin broker_sys = hbmqtt.plugins.sys.broker:BrokerSysPlugin
[2019-12-26 21:31:49,703] :: DEBUG :: hbmqtt.broker.plugins :: manager :: _load_plugins :: 65 ::  Plugin broker_sys ready
[2019-12-26 21:31:49,704] :: DEBUG :: hbmqtt.broker.plugins :: manager :: _load_plugin :: 69 ::  Loading plugin packet_logger_plugin = hbmqtt.plugins.logging:PacketLoggerPlugin
[2019-12-26 21:31:49,721] :: DEBUG :: hbmqtt.broker.plugins :: manager :: _load_plugin :: 71 ::  Initializing plugin packet_logger_plugin = hbmqtt.plugins.logging:PacketLoggerPlugin
[2019-12-26 21:31:49,723] :: DEBUG :: hbmqtt.broker.plugins :: manager :: _load_plugins :: 65 ::  Plugin packet_logger_plugin ready
[2019-12-26 21:31:49,724] :: DEBUG :: hbmqtt.broker.plugins :: manager :: _load_plugin :: 69 ::  Loading plugin topic_taboo = hbmqtt.plugins.topic_checking:TopicTabooPlugin
[2019-12-26 21:31:49,731] :: DEBUG :: hbmqtt.broker.plugins :: manager :: _load_plugin :: 71 ::  Initializing plugin topic_taboo = hbmqtt.plugins.topic_checking:TopicTabooPlugin
[2019-12-26 21:31:49,733] :: DEBUG :: hbmqtt.broker.plugins :: manager :: _load_plugins :: 65 ::  Plugin topic_taboo ready
[2019-12-26 21:31:49,737] :: DEBUG :: hbmqtt.broker :: broker :: start :: 218 :: Broker starting
[2019-12-26 21:31:49,746] :: DEBUG :: hbmqtt.broker :: broker :: start :: 231 :: Listener configuration 'default' is not bound
[2019-12-26 21:31:49,771] :: DEBUG :: hbmqtt.client.plugins :: manager :: _load_plugins :: 61 :: Loading plugins for namespace hbmqtt.client.plugins
[2019-12-26 21:31:49,772] :: DEBUG :: hbmqtt.client.plugins :: manager :: _load_plugin :: 69 ::  Loading plugin packet_logger_plugin = hbmqtt.plugins.logging:PacketLoggerPlugin
[2019-12-26 21:31:49,778] :: DEBUG :: hbmqtt.client.plugins :: manager :: _load_plugin :: 71 ::  Initializing plugin packet_logger_plugin = hbmqtt.plugins.logging:PacketLoggerPlugin
[2019-12-26 21:31:49,779] :: DEBUG :: hbmqtt.client.plugins :: manager :: _load_plugins :: 65 ::  Plugin packet_logger_plugin ready
[2019-12-26 21:31:49,784] :: DEBUG :: hbmqtt.client :: client :: connect :: 140 :: Connect to: mqtts://192.168.230.2:8883/
[2019-12-26 21:31:49,799] :: INFO :: xmppserver :: xmppserver :: start_async_server :: 29 :: Starting XMPP Server at 192.168.230.2:5223
[2019-12-26 21:31:49,816] :: WARNING :: hbmqtt.client :: client :: _connect_coro :: 426 :: MQTT connection failed: ConnectionRefusedError(111, "Connect call failed ('192.168.230.2', 8883)")
[2019-12-26 21:31:49,818] :: WARNING :: hbmqtt.client :: client :: connect :: 145 :: Connection failed: ConnectException(ConnectionRefusedError(111, "Connect call failed ('192.168.230.2', 8883)"))
[2019-12-26 21:31:49,819] :: DEBUG :: hbmqtt.client :: client :: reconnect :: 193 :: Reconnecting with session parameters: Session(clientId=helper1@bumper/helper1, state=disconnected)
[2019-12-26 21:31:49,830] :: INFO :: hbmqtt.broker :: broker :: start :: 284 :: Listener 'tls1' bind to 192.168.230.2:8883 (max_connections=-1)
[2019-12-26 21:31:49,836] :: DEBUG :: hbmqtt.broker :: broker :: start :: 293 :: Broker started
[2019-12-26 21:31:49,842] :: DEBUG :: hbmqtt.broker :: broker :: retain_message :: 602 :: Retaining message on topic $SYS/broker/version
[2019-12-26 21:31:49,843] :: DEBUG :: hbmqtt.broker.plugins.broker_sys :: broker :: on_broker_post_start :: 72 :: Setup $SYS broadcasting every 10 secondes
[2019-12-26 21:31:50,824] :: DEBUG :: hbmqtt.client :: client :: reconnect :: 200 :: Reconnect attempt 1 ...
[2019-12-26 21:31:50,953] :: INFO :: hbmqtt.broker :: broker :: acquire_connection :: 89 :: Listener 'tls1': 1 connections acquired
[2019-12-26 21:31:50,955] :: INFO :: hbmqtt.broker :: broker :: client_connected :: 354 :: Connection from 192.168.230.2:40674 on listener 'tls1'
[2019-12-26 21:31:50,978] :: DEBUG :: hbmqtt.client.plugins.packet_logger_plugin :: logging :: on_mqtt_packet_sent :: 44 :: helper1@bumper/helper1 -out-> ConnectPacket(ts=2019-12-26 21:31:50.969009, fixed=MQTTFixedHeader(length=34, flags=0x0), variable=ConnectVariableHeader(proto_name=MQTT, proto_level=4, flags=0x2, keepalive=9), payload=ConnectVariableHeader(client_id=helper1@bumper/helper1, will_topic=None, will_message=None, username=None, password=None))
[2019-12-26 21:31:50,993] :: DEBUG :: hbmqtt.broker :: broker :: delete_session :: 783 :: Delete session : session helper1@bumper/helper1 doesn't exist
[2019-12-26 21:31:50,994] :: DEBUG :: hbmqtt.broker :: broker :: client_connected :: 389 :: Keep-alive timeout=11
[2019-12-26 21:31:51,001] :: DEBUG :: hbmqtt.broker.plugins.packet_logger_plugin :: logging :: on_mqtt_packet_received :: 36 :: <-in-- ConnectPacket(ts=2019-12-26 21:31:50.982806, fixed=MQTTFixedHeader(length=34, flags=0x0), variable=ConnectVariableHeader(proto_name=MQTT, proto_level=4, flags=0x2, keepalive=9), payload=ConnectVariableHeader(client_id=helper1@bumper/helper1, will_topic=None, will_message=None, username=None, password=None))
[2019-12-26 21:31:51,006] :: DEBUG :: hbmqtt.broker :: broker :: authenticate :: 560 :: 'bumper' plugin result: True
[2019-12-26 21:31:51,018] :: DEBUG :: hbmqtt.broker :: broker :: client_connected :: 413 :: helper1@bumper/helper1 Start messages handling
[2019-12-26 21:31:51,029] :: DEBUG :: hbmqtt.broker.plugins.packet_logger_plugin :: logging :: on_mqtt_packet_sent :: 44 :: helper1@bumper/helper1 -out-> ConnackPacket(ts=2019-12-26 21:31:51.008682, fixed=MQTTFixedHeader(length=2, flags=0x0), variable=ConnackVariableHeader(session_parent=0x0, return_code=0x0), payload=None)
[2019-12-26 21:31:51,040] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: _reader_loop :: 357 :: helper1@bumper/helper1 Starting reader coro
[2019-12-26 21:31:51,063] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: start :: 111 :: Handler tasks started
[2019-12-26 21:31:51,064] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: _retry_deliveries :: 150 :: Begin messages delivery retries
[2019-12-26 21:31:51,065] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: _retry_deliveries :: 158 :: End messages delivery retries
[2019-12-26 21:31:51,066] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: start :: 113 :: Handler ready
[2019-12-26 21:31:51,069] :: DEBUG :: hbmqtt.broker :: broker :: client_connected :: 415 :: Retained messages queue size: 0
[2019-12-26 21:31:51,070] :: DEBUG :: hbmqtt.broker :: broker :: publish_session_retained_messages :: 740 :: Publishing 0 messages retained for session (client id=helper1@bumper/helper1)
[2019-12-26 21:31:51,081] :: DEBUG :: hbmqtt.client.plugins.packet_logger_plugin :: logging :: on_mqtt_packet_received :: 34 :: helper1@bumper/helper1 <-in-- ConnackPacket(ts=2019-12-26 21:31:51.051556, fixed=MQTTFixedHeader(length=2, flags=0x0), variable=ConnackVariableHeader(session_parent=0x0, return_code=0x0), payload=None)
[2019-12-26 21:31:51,083] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: _reader_loop :: 357 :: helper1@bumper/helper1 Starting reader coro
[2019-12-26 21:31:51,095] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: mqtt_deliver_next_message :: 459 :: 0 message(s) available for delivery
[2019-12-26 21:31:51,102] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: start :: 111 :: Handler tasks started
[2019-12-26 21:31:51,103] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: _retry_deliveries :: 150 :: Begin messages delivery retries
[2019-12-26 21:31:51,104] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: _retry_deliveries :: 158 :: End messages delivery retries
[2019-12-26 21:31:51,105] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: start :: 113 :: Handler ready
[2019-12-26 21:31:51,108] :: DEBUG :: hbmqtt.client :: client :: _connect_coro :: 415 :: connected to 192.168.230.2:8883
[2019-12-26 21:31:51,119] :: DEBUG :: hbmqtt.client :: client :: handle_connection_close :: 440 :: Watch broker disconnection
[2019-12-26 21:31:51,120] :: DEBUG :: hbmqtt.client.plugins.packet_logger_plugin :: logging :: on_mqtt_packet_sent :: 44 :: helper1@bumper/helper1 -out-> SubscribePacket(ts=2019-12-26 21:31:51.113437, fixed=MQTTFixedHeader(length=73, flags=0x2), variable=PacketIdVariableHeader(packet_id=1), payload=SubscribePayload(topics=[('iot/p2p/+/+/+/+/helper1/bumper/helper1/+/+/+', 0), ('iot/p2p/+', 0), ('iot/atr/+', 0)]))
[2019-12-26 21:31:51,139] :: DEBUG :: hbmqtt.broker.plugins.packet_logger_plugin :: logging :: on_mqtt_packet_received :: 34 :: helper1@bumper/helper1 <-in-- SubscribePacket(ts=2019-12-26 21:31:51.128036, fixed=MQTTFixedHeader(length=73, flags=0x2), variable=PacketIdVariableHeader(packet_id=1), payload=SubscribePayload(topics=[('iot/p2p/+/+/+/+/helper1/bumper/helper1/+/+/+', 0), ('iot/p2p/+', 0), ('iot/atr/+', 0)]))
[2019-12-26 21:31:51,147] :: DEBUG :: hbmqtt.broker :: broker :: client_connected :: 465 :: helper1@bumper/helper1 handling subscription
[2019-12-26 21:31:51,171] :: DEBUG :: hbmqtt.broker :: broker :: topic_filtering :: 595 :: 'bumper' plugin result: None
[2019-12-26 21:31:51,173] :: DEBUG :: hbmqtt.broker :: broker :: topic_filtering :: 595 :: 'auth_anonymous' plugin result: None
[2019-12-26 21:31:51,174] :: DEBUG :: hbmqtt.broker :: broker :: topic_filtering :: 595 :: 'auth_file' plugin result: None
[2019-12-26 21:31:51,175] :: DEBUG :: hbmqtt.broker :: broker :: topic_filtering :: 595 :: 'broker_sys' plugin result: None
[2019-12-26 21:31:51,176] :: DEBUG :: hbmqtt.broker :: broker :: topic_filtering :: 595 :: 'packet_logger_plugin' plugin result: None
[2019-12-26 21:31:51,177] :: DEBUG :: hbmqtt.broker :: broker :: topic_filtering :: 595 :: 'topic_taboo' plugin result: True
[2019-12-26 21:31:51,428] :: DEBUG :: hbmqtt.broker :: broker :: topic_filtering :: 595 :: 'bumper' plugin result: None
[2019-12-26 21:31:51,429] :: DEBUG :: hbmqtt.broker :: broker :: topic_filtering :: 595 :: 'auth_anonymous' plugin result: None
[2019-12-26 21:31:51,430] :: DEBUG :: hbmqtt.broker :: broker :: topic_filtering :: 595 :: 'auth_file' plugin result: None
[2019-12-26 21:31:51,431] :: DEBUG :: hbmqtt.broker :: broker :: topic_filtering :: 595 :: 'broker_sys' plugin result: None
[2019-12-26 21:31:51,432] :: DEBUG :: hbmqtt.broker :: broker :: topic_filtering :: 595 :: 'packet_logger_plugin' plugin result: None
[2019-12-26 21:31:51,433] :: DEBUG :: hbmqtt.broker :: broker :: topic_filtering :: 595 :: 'topic_taboo' plugin result: True
[2019-12-26 21:31:51,450] :: INFO :: confserver :: confserver :: start_server :: 152 :: Starting ConfServer at 192.168.230.2:443
[2019-12-26 21:31:51,464] :: INFO :: confserver :: confserver :: start_server :: 152 :: Starting ConfServer at 192.168.230.2:8007
[2019-12-26 21:31:51,483] :: DEBUG :: hbmqtt.broker :: broker :: topic_filtering :: 595 :: 'bumper' plugin result: None
[2019-12-26 21:31:51,484] :: DEBUG :: hbmqtt.broker :: broker :: topic_filtering :: 595 :: 'auth_anonymous' plugin result: None
[2019-12-26 21:31:51,485] :: DEBUG :: hbmqtt.broker :: broker :: topic_filtering :: 595 :: 'auth_file' plugin result: None
[2019-12-26 21:31:51,486] :: DEBUG :: hbmqtt.broker :: broker :: topic_filtering :: 595 :: 'broker_sys' plugin result: None
[2019-12-26 21:31:51,487] :: DEBUG :: hbmqtt.broker :: broker :: topic_filtering :: 595 :: 'packet_logger_plugin' plugin result: None
[2019-12-26 21:31:51,488] :: DEBUG :: hbmqtt.broker :: broker :: topic_filtering :: 595 :: 'topic_taboo' plugin result: True
[2019-12-26 21:31:51,497] :: DEBUG :: hbmqtt.broker :: broker :: publish_retained_messages_for_subscription :: 755 :: Begin broadcasting messages retained due to subscription on 'iot/p2p/+/+/+/+/helper1/bumper/helper1/+/+/+' from (client id=helper1@bumper/helper1)
[2019-12-26 21:31:51,498] :: DEBUG :: hbmqtt.broker :: broker :: publish_retained_messages_for_subscription :: 760 :: matching : $SYS/broker/version iot/p2p/+/+/+/+/helper1/bumper/helper1/+/+/+
[2019-12-26 21:31:51,505] :: DEBUG :: hbmqtt.broker :: broker :: publish_retained_messages_for_subscription :: 769 :: End broadcasting messages retained due to subscription on 'iot/p2p/+/+/+/+/helper1/bumper/helper1/+/+/+' from (client id=helper1@bumper/helper1)
[2019-12-26 21:31:51,506] :: DEBUG :: hbmqtt.broker :: broker :: publish_retained_messages_for_subscription :: 755 :: Begin broadcasting messages retained due to subscription on 'iot/p2p/+' from (client id=helper1@bumper/helper1)
[2019-12-26 21:31:51,507] :: DEBUG :: hbmqtt.broker :: broker :: publish_retained_messages_for_subscription :: 760 :: matching : $SYS/broker/version iot/p2p/+
[2019-12-26 21:31:51,510] :: DEBUG :: hbmqtt.broker :: broker :: publish_retained_messages_for_subscription :: 769 :: End broadcasting messages retained due to subscription on 'iot/p2p/+' from (client id=helper1@bumper/helper1)
[2019-12-26 21:31:51,511] :: DEBUG :: hbmqtt.broker :: broker :: publish_retained_messages_for_subscription :: 755 :: Begin broadcasting messages retained due to subscription on 'iot/atr/+' from (client id=helper1@bumper/helper1)
[2019-12-26 21:31:51,512] :: DEBUG :: hbmqtt.broker :: broker :: publish_retained_messages_for_subscription :: 760 :: matching : $SYS/broker/version iot/atr/+
[2019-12-26 21:31:51,515] :: DEBUG :: hbmqtt.broker :: broker :: publish_retained_messages_for_subscription :: 769 :: End broadcasting messages retained due to subscription on 'iot/atr/+' from (client id=helper1@bumper/helper1)
[2019-12-26 21:31:51,518] :: DEBUG :: hbmqtt.broker :: broker :: client_connected :: 481 :: {'iot/p2p/+/+/+/+/helper1/bumper/helper1/+/+/+': [(Session(clientId=helper1@bumper/helper1, state=connected), 0)], 'iot/p2p/+': [(Session(clientId=helper1@bumper/helper1, state=connected), 0)], 'iot/atr/+': [(Session(clientId=helper1@bumper/helper1, state=connected), 0)]}
[2019-12-26 21:31:51,522] :: ERROR :: confserver :: confserver :: start_server :: 176 :: error while attempting to bind on address ('192.168.230.2', 443): permission denied
[2019-12-26 21:31:51,530] :: DEBUG :: hbmqtt.broker.plugins.packet_logger_plugin :: logging :: on_mqtt_packet_sent :: 44 :: helper1@bumper/helper1 -out-> SubackPacket(ts=2019-12-26 21:31:51.490622, fixed=MQTTFixedHeader(length=5, flags=0x0), variable=PacketIdVariableHeader(packet_id=1), payload=SubackPayload(return_codes=[0, 0, 0]))
[2019-12-26 21:31:51,533] :: INFO :: bumper :: __init__ :: shutdown :: 226 :: Shutting down
[2019-12-26 21:31:51,538] :: DEBUG :: hbmqtt.broker :: broker :: shutdown :: 328 :: Broker closing
[2019-12-26 21:31:51,539] :: INFO :: hbmqtt.broker :: broker :: shutdown :: 329 :: Broker closed
[2019-12-26 21:31:51,542] :: INFO :: bumper :: __init__ :: shutdown :: 252 :: Shutdown complete
[2019-12-26 21:31:51,558] :: DEBUG :: hbmqtt.client.plugins.packet_logger_plugin :: logging :: on_mqtt_packet_received :: 34 :: helper1@bumper/helper1 <-in-- SubackPacket(ts=2019-12-26 21:31:51.549572, fixed=MQTTFixedHeader(length=5, flags=0x0), variable=PacketIdVariableHeader(packet_id=1), payload=SubackPayload(return_codes=[0, 0, 0]))
[2019-12-26 21:31:51,567] :: DEBUG :: hbmqtt.client :: client :: deliver_message :: 331 :: Waiting message delivery
[2019-12-26 21:31:51,570] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: mqtt_deliver_next_message :: 459 :: 0 message(s) available for delivery
[2019-12-26 21:31:56,445] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: _reader_loop :: 423 :: Task cancelled, reader loop ending
[2019-12-26 21:31:56,447] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: broker_handler :: handle_disconnect :: 57 :: Client disconnecting
[2019-12-26 21:31:56,448] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: _reader_loop :: 437 :: helper1@bumper/helper1 Reader coro stopped
[2019-12-26 21:31:56,449] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: _stop_waiters :: 133 :: Stopping 0 puback waiters
[2019-12-26 21:31:56,450] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: _stop_waiters :: 134 :: Stopping 0 pucomp waiters
[2019-12-26 21:31:56,451] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: _stop_waiters :: 135 :: Stopping 0 purec waiters
[2019-12-26 21:31:56,452] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: _stop_waiters :: 136 :: Stopping 0 purel waiters
[2019-12-26 21:31:56,454] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: stop :: 121 :: waiting for tasks to be stopped
[2019-12-26 21:31:56,464] :: DEBUG :: hbmqtt.broker :: broker :: client_connected :: 500 :: Client loop cancelled
[2019-12-26 21:31:56,465] :: DEBUG :: hbmqtt.broker :: broker :: client_connected :: 507 :: helper1@bumper/helper1 Client disconnected
[2019-12-26 21:31:56,466] :: INFO :: hbmqtt.broker :: broker :: release_connection :: 100 :: Listener 'tls1': 0 connections acquired
[2019-12-26 21:31:56,469] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: mqtt_deliver_next_message :: 465 :: Delivering message None
[2019-12-26 21:31:56,473] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: mqtt_deliver_next_message :: 465 :: Delivering message None
[2019-12-26 21:31:56,476] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: _reader_loop :: 423 :: Task cancelled, reader loop ending
[2019-12-26 21:31:56,477] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: client_handler :: handle_connection_closed :: 170 :: Broker closed connection
[2019-12-26 21:31:56,478] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: _reader_loop :: 437 :: helper1@bumper/helper1 Reader coro stopped
[2019-12-26 21:31:56,479] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: _stop_waiters :: 133 :: Stopping 0 puback waiters
[2019-12-26 21:31:56,480] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: _stop_waiters :: 134 :: Stopping 0 pucomp waiters
[2019-12-26 21:31:56,482] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: _stop_waiters :: 135 :: Stopping 0 purec waiters
[2019-12-26 21:31:56,483] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: _stop_waiters :: 136 :: Stopping 0 purel waiters
[2019-12-26 21:31:56,484] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: stop :: 121 :: waiting for tasks to be stopped
[2019-12-26 21:31:56,503] :: INFO :: bumper :: __init__ :: shutdown :: 226 :: Shutting down
[2019-12-26 21:31:56,504] :: INFO :: bumper :: __init__ :: shutdown :: 252 :: Shutdown complete
Exception ignored in: <bound method StreamReaderProtocol._on_reader_gc of <asyncio.streams.StreamReaderProtocol object at 0x7561fac0>>
Traceback (most recent call last):
  File "/usr/local/lib/python3.8/asyncio/streams.py", line 245, in _on_reader_gc
  File "/usr/local/lib/python3.8/asyncio/sslproto.py", line 400, in abort
  File "/usr/local/lib/python3.8/asyncio/sslproto.py", line 732, in _abort
  File "/usr/local/lib/python3.8/asyncio/selector_events.py", line 660, in abort
  File "/usr/local/lib/python3.8/asyncio/selector_events.py", line 711, in _force_close
  File "/usr/local/lib/python3.8/asyncio/base_events.py", line 711, in call_soon
  File "/usr/local/lib/python3.8/asyncio/base_events.py", line 504, in _check_closed
RuntimeError: Event loop is closed

And here todays entrys in the logfile (i ran the command twice, first time without IP addresses):

[2019-12-26 21:30:18,046] :: INFO :: mqttserver :: mqttserver :: broker_coro :: 214 :: Starting MQTT Server at 127.0.1.1:8883
[2019-12-26 21:30:18,057] :: DEBUG :: hbmqtt.broker.plugins :: manager :: _load_plugins :: 61 :: Loading plugins for namespace hbmqtt.broker.plugins
[2019-12-26 21:30:18,058] :: DEBUG :: hbmqtt.broker.plugins :: manager :: _load_plugin :: 69 ::  Loading plugin bumper = bumper.mqttserver:BumperMQTTServer_Plugin
[2019-12-26 21:30:18,060] :: DEBUG :: hbmqtt.broker.plugins :: manager :: _load_plugin :: 71 ::  Initializing plugin bumper = bumper.mqttserver:BumperMQTTServer_Plugin
[2019-12-26 21:30:18,063] :: DEBUG :: hbmqtt.broker.plugins :: manager :: _load_plugins :: 65 ::  Plugin bumper ready
[2019-12-26 21:30:18,083] :: DEBUG :: hbmqtt.broker.plugins :: manager :: _load_plugin :: 69 ::  Loading plugin auth_anonymous = hbmqtt.plugins.authentication:AnonymousAuthPlugin
[2019-12-26 21:30:18,502] :: DEBUG :: hbmqtt.broker.plugins :: manager :: _load_plugin :: 71 ::  Initializing plugin auth_anonymous = hbmqtt.plugins.authentication:AnonymousAuthPlugin
[2019-12-26 21:30:18,504] :: DEBUG :: hbmqtt.broker.plugins :: manager :: _load_plugins :: 65 ::  Plugin auth_anonymous ready
[2019-12-26 21:30:18,505] :: DEBUG :: hbmqtt.broker.plugins :: manager :: _load_plugin :: 69 ::  Loading plugin auth_file = hbmqtt.plugins.authentication:FileAuthPlugin
[2019-12-26 21:30:18,510] :: DEBUG :: hbmqtt.broker.plugins :: manager :: _load_plugin :: 71 ::  Initializing plugin auth_file = hbmqtt.plugins.authentication:FileAuthPlugin
[2019-12-26 21:30:18,512] :: WARNING :: hbmqtt.broker.plugins.auth_file :: authentication :: _read_password_file :: 73 :: Password file /home/pi/bumper/bumper/passwd not found
[2019-12-26 21:30:18,513] :: DEBUG :: hbmqtt.broker.plugins :: manager :: _load_plugins :: 65 ::  Plugin auth_file ready
[2019-12-26 21:30:18,514] :: DEBUG :: hbmqtt.broker.plugins :: manager :: _load_plugin :: 69 ::  Loading plugin broker_sys = hbmqtt.plugins.sys.broker:BrokerSysPlugin
[2019-12-26 21:30:18,535] :: DEBUG :: hbmqtt.broker.plugins :: manager :: _load_plugin :: 71 ::  Initializing plugin broker_sys = hbmqtt.plugins.sys.broker:BrokerSysPlugin
[2019-12-26 21:30:18,537] :: DEBUG :: hbmqtt.broker.plugins :: manager :: _load_plugins :: 65 ::  Plugin broker_sys ready
[2019-12-26 21:30:18,538] :: DEBUG :: hbmqtt.broker.plugins :: manager :: _load_plugin :: 69 ::  Loading plugin packet_logger_plugin = hbmqtt.plugins.logging:PacketLoggerPlugin
[2019-12-26 21:30:18,555] :: DEBUG :: hbmqtt.broker.plugins :: manager :: _load_plugin :: 71 ::  Initializing plugin packet_logger_plugin = hbmqtt.plugins.logging:PacketLoggerPlugin
[2019-12-26 21:30:18,556] :: DEBUG :: hbmqtt.broker.plugins :: manager :: _load_plugins :: 65 ::  Plugin packet_logger_plugin ready
[2019-12-26 21:30:18,557] :: DEBUG :: hbmqtt.broker.plugins :: manager :: _load_plugin :: 69 ::  Loading plugin topic_taboo = hbmqtt.plugins.topic_checking:TopicTabooPlugin
[2019-12-26 21:30:18,567] :: DEBUG :: hbmqtt.broker.plugins :: manager :: _load_plugin :: 71 ::  Initializing plugin topic_taboo = hbmqtt.plugins.topic_checking:TopicTabooPlugin
[2019-12-26 21:30:18,569] :: DEBUG :: hbmqtt.broker.plugins :: manager :: _load_plugins :: 65 ::  Plugin topic_taboo ready
[2019-12-26 21:30:18,573] :: DEBUG :: hbmqtt.broker :: broker :: start :: 218 :: Broker starting
[2019-12-26 21:30:18,586] :: DEBUG :: hbmqtt.broker :: broker :: start :: 231 :: Listener configuration 'default' is not bound
[2019-12-26 21:30:18,604] :: DEBUG :: hbmqtt.client.plugins :: manager :: _load_plugins :: 61 :: Loading plugins for namespace hbmqtt.client.plugins
[2019-12-26 21:30:18,605] :: DEBUG :: hbmqtt.client.plugins :: manager :: _load_plugin :: 69 ::  Loading plugin packet_logger_plugin = hbmqtt.plugins.logging:PacketLoggerPlugin
[2019-12-26 21:30:18,607] :: DEBUG :: hbmqtt.client.plugins :: manager :: _load_plugin :: 71 ::  Initializing plugin packet_logger_plugin = hbmqtt.plugins.logging:PacketLoggerPlugin
[2019-12-26 21:30:18,608] :: DEBUG :: hbmqtt.client.plugins :: manager :: _load_plugins :: 65 ::  Plugin packet_logger_plugin ready
[2019-12-26 21:30:18,611] :: DEBUG :: hbmqtt.client :: client :: connect :: 140 :: Connect to: mqtts://127.0.1.1:8883/
[2019-12-26 21:30:18,628] :: WARNING :: hbmqtt.client :: client :: _connect_coro :: 426 :: MQTT connection failed: ConnectionRefusedError(111, "Connect call failed ('127.0.1.1', 8883)")
[2019-12-26 21:30:18,629] :: WARNING :: hbmqtt.client :: client :: connect :: 145 :: Connection failed: ConnectException(ConnectionRefusedError(111, "Connect call failed ('127.0.1.1', 8883)"))
[2019-12-26 21:30:18,630] :: DEBUG :: hbmqtt.client :: client :: reconnect :: 193 :: Reconnecting with session parameters: Session(clientId=helper1@bumper/helper1, state=disconnected)
[2019-12-26 21:30:18,636] :: INFO :: hbmqtt.broker :: broker :: start :: 284 :: Listener 'tls1' bind to 127.0.1.1:8883 (max_connections=-1)
[2019-12-26 21:30:18,639] :: DEBUG :: hbmqtt.broker :: broker :: start :: 293 :: Broker started
[2019-12-26 21:30:18,645] :: DEBUG :: hbmqtt.broker :: broker :: retain_message :: 602 :: Retaining message on topic $SYS/broker/version
[2019-12-26 21:30:18,646] :: DEBUG :: hbmqtt.broker.plugins.broker_sys :: broker :: on_broker_post_start :: 72 :: Setup $SYS broadcasting every 10 secondes
[2019-12-26 21:30:19,634] :: DEBUG :: hbmqtt.client :: client :: reconnect :: 200 :: Reconnect attempt 1 ...
[2019-12-26 21:30:19,743] :: INFO :: hbmqtt.broker :: broker :: acquire_connection :: 89 :: Listener 'tls1': 1 connections acquired
[2019-12-26 21:30:19,744] :: INFO :: hbmqtt.broker :: broker :: client_connected :: 354 :: Connection from 127.0.0.1:33266 on listener 'tls1'
[2019-12-26 21:30:19,774] :: DEBUG :: hbmqtt.client.plugins.packet_logger_plugin :: logging :: on_mqtt_packet_sent :: 44 :: helper1@bumper/helper1 -out-> ConnectPacket(ts=2019-12-26 21:30:19.762065, fixed=MQTTFixedHeader(length=34, flags=0x0), variable=ConnectVariableHeader(proto_name=MQTT, proto_level=4, flags=0x2, keepalive=9), payload=ConnectVariableHeader(client_id=helper1@bumper/helper1, will_topic=None, will_message=None, username=None, password=None))
[2019-12-26 21:30:19,782] :: DEBUG :: hbmqtt.broker :: broker :: delete_session :: 783 :: Delete session : session helper1@bumper/helper1 doesn't exist
[2019-12-26 21:30:19,783] :: DEBUG :: hbmqtt.broker :: broker :: client_connected :: 389 :: Keep-alive timeout=11
[2019-12-26 21:30:19,788] :: DEBUG :: hbmqtt.broker.plugins.packet_logger_plugin :: logging :: on_mqtt_packet_received :: 36 :: <-in-- ConnectPacket(ts=2019-12-26 21:30:19.777796, fixed=MQTTFixedHeader(length=34, flags=0x0), variable=ConnectVariableHeader(proto_name=MQTT, proto_level=4, flags=0x2, keepalive=9), payload=ConnectVariableHeader(client_id=helper1@bumper/helper1, will_topic=None, will_message=None, username=None, password=None))
[2019-12-26 21:30:19,791] :: DEBUG :: hbmqtt.broker :: broker :: authenticate :: 560 :: 'bumper' plugin result: True
[2019-12-26 21:30:19,798] :: DEBUG :: hbmqtt.broker :: broker :: client_connected :: 413 :: helper1@bumper/helper1 Start messages handling
[2019-12-26 21:30:19,804] :: DEBUG :: hbmqtt.broker.plugins.packet_logger_plugin :: logging :: on_mqtt_packet_sent :: 44 :: helper1@bumper/helper1 -out-> ConnackPacket(ts=2019-12-26 21:30:19.792980, fixed=MQTTFixedHeader(length=2, flags=0x0), variable=ConnackVariableHeader(session_parent=0x0, return_code=0x0), payload=None)
[2019-12-26 21:30:19,813] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: _reader_loop :: 357 :: helper1@bumper/helper1 Starting reader coro
[2019-12-26 21:30:19,825] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: start :: 111 :: Handler tasks started
[2019-12-26 21:30:19,826] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: _retry_deliveries :: 150 :: Begin messages delivery retries
[2019-12-26 21:30:19,826] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: _retry_deliveries :: 158 :: End messages delivery retries
[2019-12-26 21:30:19,827] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: start :: 113 :: Handler ready
[2019-12-26 21:30:19,828] :: DEBUG :: hbmqtt.broker :: broker :: client_connected :: 415 :: Retained messages queue size: 0
[2019-12-26 21:30:19,829] :: DEBUG :: hbmqtt.broker :: broker :: publish_session_retained_messages :: 740 :: Publishing 0 messages retained for session (client id=helper1@bumper/helper1)
[2019-12-26 21:30:19,834] :: DEBUG :: hbmqtt.client.plugins.packet_logger_plugin :: logging :: on_mqtt_packet_received :: 34 :: helper1@bumper/helper1 <-in-- ConnackPacket(ts=2019-12-26 21:30:19.819900, fixed=MQTTFixedHeader(length=2, flags=0x0), variable=ConnackVariableHeader(session_parent=0x0, return_code=0x0), payload=None)
[2019-12-26 21:30:19,836] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: _reader_loop :: 357 :: helper1@bumper/helper1 Starting reader coro
[2019-12-26 21:30:19,841] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: mqtt_deliver_next_message :: 459 :: 0 message(s) available for delivery
[2019-12-26 21:30:19,844] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: start :: 111 :: Handler tasks started
[2019-12-26 21:30:19,845] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: _retry_deliveries :: 150 :: Begin messages delivery retries
[2019-12-26 21:30:19,846] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: _retry_deliveries :: 158 :: End messages delivery retries
[2019-12-26 21:30:19,846] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: start :: 113 :: Handler ready
[2019-12-26 21:30:19,848] :: DEBUG :: hbmqtt.client :: client :: _connect_coro :: 415 :: connected to 127.0.1.1:8883
[2019-12-26 21:30:19,853] :: DEBUG :: hbmqtt.client :: client :: handle_connection_close :: 440 :: Watch broker disconnection
[2019-12-26 21:30:19,854] :: DEBUG :: hbmqtt.client.plugins.packet_logger_plugin :: logging :: on_mqtt_packet_sent :: 44 :: helper1@bumper/helper1 -out-> SubscribePacket(ts=2019-12-26 21:30:19.850861, fixed=MQTTFixedHeader(length=73, flags=0x2), variable=PacketIdVariableHeader(packet_id=1), payload=SubscribePayload(topics=[('iot/p2p/+/+/+/+/helper1/bumper/helper1/+/+/+', 0), ('iot/p2p/+', 0), ('iot/atr/+', 0)]))
[2019-12-26 21:30:19,864] :: DEBUG :: hbmqtt.broker.plugins.packet_logger_plugin :: logging :: on_mqtt_packet_received :: 34 :: helper1@bumper/helper1 <-in-- SubscribePacket(ts=2019-12-26 21:30:19.858824, fixed=MQTTFixedHeader(length=73, flags=0x2), variable=PacketIdVariableHeader(packet_id=1), payload=SubscribePayload(topics=[('iot/p2p/+/+/+/+/helper1/bumper/helper1/+/+/+', 0), ('iot/p2p/+', 0), ('iot/atr/+', 0)]))
[2019-12-26 21:30:19,868] :: DEBUG :: hbmqtt.broker :: broker :: client_connected :: 465 :: helper1@bumper/helper1 handling subscription
[2019-12-26 21:30:19,881] :: DEBUG :: hbmqtt.broker :: broker :: topic_filtering :: 595 :: 'bumper' plugin result: None
[2019-12-26 21:30:19,882] :: DEBUG :: hbmqtt.broker :: broker :: topic_filtering :: 595 :: 'auth_anonymous' plugin result: None
[2019-12-26 21:30:19,882] :: DEBUG :: hbmqtt.broker :: broker :: topic_filtering :: 595 :: 'auth_file' plugin result: None
[2019-12-26 21:30:19,883] :: DEBUG :: hbmqtt.broker :: broker :: topic_filtering :: 595 :: 'broker_sys' plugin result: None
[2019-12-26 21:30:19,883] :: DEBUG :: hbmqtt.broker :: broker :: topic_filtering :: 595 :: 'packet_logger_plugin' plugin result: None
[2019-12-26 21:30:19,884] :: DEBUG :: hbmqtt.broker :: broker :: topic_filtering :: 595 :: 'topic_taboo' plugin result: True
[2019-12-26 21:30:20,014] :: DEBUG :: hbmqtt.broker :: broker :: topic_filtering :: 595 :: 'bumper' plugin result: None
[2019-12-26 21:30:20,015] :: DEBUG :: hbmqtt.broker :: broker :: topic_filtering :: 595 :: 'auth_anonymous' plugin result: None
[2019-12-26 21:30:20,015] :: DEBUG :: hbmqtt.broker :: broker :: topic_filtering :: 595 :: 'auth_file' plugin result: None
[2019-12-26 21:30:20,016] :: DEBUG :: hbmqtt.broker :: broker :: topic_filtering :: 595 :: 'broker_sys' plugin result: None
[2019-12-26 21:30:20,016] :: DEBUG :: hbmqtt.broker :: broker :: topic_filtering :: 595 :: 'packet_logger_plugin' plugin result: None
[2019-12-26 21:30:20,017] :: DEBUG :: hbmqtt.broker :: broker :: topic_filtering :: 595 :: 'topic_taboo' plugin result: True
[2019-12-26 21:30:20,046] :: DEBUG :: hbmqtt.broker :: broker :: topic_filtering :: 595 :: 'bumper' plugin result: None
[2019-12-26 21:30:20,047] :: DEBUG :: hbmqtt.broker :: broker :: topic_filtering :: 595 :: 'auth_anonymous' plugin result: None
[2019-12-26 21:30:20,047] :: DEBUG :: hbmqtt.broker :: broker :: topic_filtering :: 595 :: 'auth_file' plugin result: None
[2019-12-26 21:30:20,048] :: DEBUG :: hbmqtt.broker :: broker :: topic_filtering :: 595 :: 'broker_sys' plugin result: None
[2019-12-26 21:30:20,048] :: DEBUG :: hbmqtt.broker :: broker :: topic_filtering :: 595 :: 'packet_logger_plugin' plugin result: None
[2019-12-26 21:30:20,049] :: DEBUG :: hbmqtt.broker :: broker :: topic_filtering :: 595 :: 'topic_taboo' plugin result: True
[2019-12-26 21:30:20,053] :: DEBUG :: hbmqtt.broker :: broker :: publish_retained_messages_for_subscription :: 755 :: Begin broadcasting messages retained due to subscription on 'iot/p2p/+/+/+/+/helper1/bumper/helper1/+/+/+' from (client id=helper1@bumper/helper1)
[2019-12-26 21:30:20,054] :: DEBUG :: hbmqtt.broker :: broker :: publish_retained_messages_for_subscription :: 760 :: matching : $SYS/broker/version iot/p2p/+/+/+/+/helper1/bumper/helper1/+/+/+
[2019-12-26 21:30:20,057] :: DEBUG :: hbmqtt.broker :: broker :: publish_retained_messages_for_subscription :: 769 :: End broadcasting messages retained due to subscription on 'iot/p2p/+/+/+/+/helper1/bumper/helper1/+/+/+' from (client id=helper1@bumper/helper1)
[2019-12-26 21:30:20,058] :: DEBUG :: hbmqtt.broker :: broker :: publish_retained_messages_for_subscription :: 755 :: Begin broadcasting messages retained due to subscription on 'iot/p2p/+' from (client id=helper1@bumper/helper1)
[2019-12-26 21:30:20,059] :: DEBUG :: hbmqtt.broker :: broker :: publish_retained_messages_for_subscription :: 760 :: matching : $SYS/broker/version iot/p2p/+
[2019-12-26 21:30:20,060] :: DEBUG :: hbmqtt.broker :: broker :: publish_retained_messages_for_subscription :: 769 :: End broadcasting messages retained due to subscription on 'iot/p2p/+' from (client id=helper1@bumper/helper1)
[2019-12-26 21:30:20,061] :: DEBUG :: hbmqtt.broker :: broker :: publish_retained_messages_for_subscription :: 755 :: Begin broadcasting messages retained due to subscription on 'iot/atr/+' from (client id=helper1@bumper/helper1)
[2019-12-26 21:30:20,062] :: DEBUG :: hbmqtt.broker :: broker :: publish_retained_messages_for_subscription :: 760 :: matching : $SYS/broker/version iot/atr/+
[2019-12-26 21:30:20,063] :: DEBUG :: hbmqtt.broker :: broker :: publish_retained_messages_for_subscription :: 769 :: End broadcasting messages retained due to subscription on 'iot/atr/+' from (client id=helper1@bumper/helper1)
[2019-12-26 21:30:20,065] :: DEBUG :: hbmqtt.broker :: broker :: client_connected :: 481 :: {'iot/p2p/+/+/+/+/helper1/bumper/helper1/+/+/+': [(Session(clientId=helper1@bumper/helper1, state=connected), 0)], 'iot/p2p/+': [(Session(clientId=helper1@bumper/helper1, state=connected), 0)], 'iot/atr/+': [(Session(clientId=helper1@bumper/helper1, state=connected), 0)]}
[2019-12-26 21:30:20,071] :: DEBUG :: hbmqtt.broker.plugins.packet_logger_plugin :: logging :: on_mqtt_packet_sent :: 44 :: helper1@bumper/helper1 -out-> SubackPacket(ts=2019-12-26 21:30:20.050220, fixed=MQTTFixedHeader(length=5, flags=0x0), variable=PacketIdVariableHeader(packet_id=1), payload=SubackPayload(return_codes=[0, 0, 0]))
[2019-12-26 21:30:20,075] :: DEBUG :: hbmqtt.broker :: broker :: shutdown :: 328 :: Broker closing
[2019-12-26 21:30:20,076] :: INFO :: hbmqtt.broker :: broker :: shutdown :: 329 :: Broker closed
[2019-12-26 21:30:20,088] :: DEBUG :: hbmqtt.client.plugins.packet_logger_plugin :: logging :: on_mqtt_packet_received :: 34 :: helper1@bumper/helper1 <-in-- SubackPacket(ts=2019-12-26 21:30:20.082364, fixed=MQTTFixedHeader(length=5, flags=0x0), variable=PacketIdVariableHeader(packet_id=1), payload=SubackPayload(return_codes=[0, 0, 0]))
[2019-12-26 21:30:20,098] :: DEBUG :: hbmqtt.client :: client :: deliver_message :: 331 :: Waiting message delivery
[2019-12-26 21:30:20,101] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: mqtt_deliver_next_message :: 459 :: 0 message(s) available for delivery
[2019-12-26 21:30:25,029] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: _reader_loop :: 423 :: Task cancelled, reader loop ending
[2019-12-26 21:30:25,030] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: broker_handler :: handle_disconnect :: 57 :: Client disconnecting
[2019-12-26 21:30:25,031] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: _reader_loop :: 437 :: helper1@bumper/helper1 Reader coro stopped
[2019-12-26 21:30:25,032] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: _stop_waiters :: 133 :: Stopping 0 puback waiters
[2019-12-26 21:30:25,033] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: _stop_waiters :: 134 :: Stopping 0 pucomp waiters
[2019-12-26 21:30:25,035] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: _stop_waiters :: 135 :: Stopping 0 purec waiters
[2019-12-26 21:30:25,036] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: _stop_waiters :: 136 :: Stopping 0 purel waiters
[2019-12-26 21:30:25,037] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: stop :: 121 :: waiting for tasks to be stopped
[2019-12-26 21:30:25,046] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: _reader_loop :: 423 :: Task cancelled, reader loop ending
[2019-12-26 21:30:25,048] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: client_handler :: handle_connection_closed :: 170 :: Broker closed connection
[2019-12-26 21:30:25,049] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: _reader_loop :: 437 :: helper1@bumper/helper1 Reader coro stopped
[2019-12-26 21:30:25,050] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: _stop_waiters :: 133 :: Stopping 0 puback waiters
[2019-12-26 21:30:25,051] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: _stop_waiters :: 134 :: Stopping 0 pucomp waiters
[2019-12-26 21:30:25,052] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: _stop_waiters :: 135 :: Stopping 0 purec waiters
[2019-12-26 21:30:25,053] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: _stop_waiters :: 136 :: Stopping 0 purel waiters
[2019-12-26 21:30:25,055] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: stop :: 121 :: waiting for tasks to be stopped
[2019-12-26 21:30:25,062] :: DEBUG :: hbmqtt.broker :: broker :: client_connected :: 500 :: Client loop cancelled
[2019-12-26 21:30:25,063] :: DEBUG :: hbmqtt.broker :: broker :: client_connected :: 507 :: helper1@bumper/helper1 Client disconnected
[2019-12-26 21:30:25,064] :: INFO :: hbmqtt.broker :: broker :: release_connection :: 100 :: Listener 'tls1': 0 connections acquired
[2019-12-26 21:30:25,068] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: mqtt_deliver_next_message :: 465 :: Delivering message None
[2019-12-26 21:30:25,070] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: mqtt_deliver_next_message :: 465 :: Delivering message None
[2019-12-26 21:31:49,359] :: INFO :: mqttserver :: mqttserver :: broker_coro :: 214 :: Starting MQTT Server at 192.168.230.2:8883
[2019-12-26 21:31:49,364] :: DEBUG :: hbmqtt.broker.plugins :: manager :: _load_plugins :: 61 :: Loading plugins for namespace hbmqtt.broker.plugins
[2019-12-26 21:31:49,365] :: DEBUG :: hbmqtt.broker.plugins :: manager :: _load_plugin :: 69 ::  Loading plugin bumper = bumper.mqttserver:BumperMQTTServer_Plugin
[2019-12-26 21:31:49,366] :: DEBUG :: hbmqtt.broker.plugins :: manager :: _load_plugin :: 71 ::  Initializing plugin bumper = bumper.mqttserver:BumperMQTTServer_Plugin
[2019-12-26 21:31:49,368] :: DEBUG :: hbmqtt.broker.plugins :: manager :: _load_plugins :: 65 ::  Plugin bumper ready
[2019-12-26 21:31:49,378] :: DEBUG :: hbmqtt.broker.plugins :: manager :: _load_plugin :: 69 ::  Loading plugin auth_anonymous = hbmqtt.plugins.authentication:AnonymousAuthPlugin
[2019-12-26 21:31:49,679] :: DEBUG :: hbmqtt.broker.plugins :: manager :: _load_plugin :: 71 ::  Initializing plugin auth_anonymous = hbmqtt.plugins.authentication:AnonymousAuthPlugin
[2019-12-26 21:31:49,680] :: DEBUG :: hbmqtt.broker.plugins :: manager :: _load_plugins :: 65 ::  Plugin auth_anonymous ready
[2019-12-26 21:31:49,682] :: DEBUG :: hbmqtt.broker.plugins :: manager :: _load_plugin :: 69 ::  Loading plugin auth_file = hbmqtt.plugins.authentication:FileAuthPlugin
[2019-12-26 21:31:49,687] :: DEBUG :: hbmqtt.broker.plugins :: manager :: _load_plugin :: 71 ::  Initializing plugin auth_file = hbmqtt.plugins.authentication:FileAuthPlugin
[2019-12-26 21:31:49,688] :: WARNING :: hbmqtt.broker.plugins.auth_file :: authentication :: _read_password_file :: 73 :: Password file /home/pi/bumper/bumper/passwd not found
[2019-12-26 21:31:49,689] :: DEBUG :: hbmqtt.broker.plugins :: manager :: _load_plugins :: 65 ::  Plugin auth_file ready
[2019-12-26 21:31:49,690] :: DEBUG :: hbmqtt.broker.plugins :: manager :: _load_plugin :: 69 ::  Loading plugin broker_sys = hbmqtt.plugins.sys.broker:BrokerSysPlugin
[2019-12-26 21:31:49,701] :: DEBUG :: hbmqtt.broker.plugins :: manager :: _load_plugin :: 71 ::  Initializing plugin broker_sys = hbmqtt.plugins.sys.broker:BrokerSysPlugin
[2019-12-26 21:31:49,703] :: DEBUG :: hbmqtt.broker.plugins :: manager :: _load_plugins :: 65 ::  Plugin broker_sys ready
[2019-12-26 21:31:49,704] :: DEBUG :: hbmqtt.broker.plugins :: manager :: _load_plugin :: 69 ::  Loading plugin packet_logger_plugin = hbmqtt.plugins.logging:PacketLoggerPlugin
[2019-12-26 21:31:49,721] :: DEBUG :: hbmqtt.broker.plugins :: manager :: _load_plugin :: 71 ::  Initializing plugin packet_logger_plugin = hbmqtt.plugins.logging:PacketLoggerPlugin
[2019-12-26 21:31:49,723] :: DEBUG :: hbmqtt.broker.plugins :: manager :: _load_plugins :: 65 ::  Plugin packet_logger_plugin ready
[2019-12-26 21:31:49,724] :: DEBUG :: hbmqtt.broker.plugins :: manager :: _load_plugin :: 69 ::  Loading plugin topic_taboo = hbmqtt.plugins.topic_checking:TopicTabooPlugin
[2019-12-26 21:31:49,731] :: DEBUG :: hbmqtt.broker.plugins :: manager :: _load_plugin :: 71 ::  Initializing plugin topic_taboo = hbmqtt.plugins.topic_checking:TopicTabooPlugin
[2019-12-26 21:31:49,733] :: DEBUG :: hbmqtt.broker.plugins :: manager :: _load_plugins :: 65 ::  Plugin topic_taboo ready
[2019-12-26 21:31:49,737] :: DEBUG :: hbmqtt.broker :: broker :: start :: 218 :: Broker starting
[2019-12-26 21:31:49,746] :: DEBUG :: hbmqtt.broker :: broker :: start :: 231 :: Listener configuration 'default' is not bound
[2019-12-26 21:31:49,771] :: DEBUG :: hbmqtt.client.plugins :: manager :: _load_plugins :: 61 :: Loading plugins for namespace hbmqtt.client.plugins
[2019-12-26 21:31:49,772] :: DEBUG :: hbmqtt.client.plugins :: manager :: _load_plugin :: 69 ::  Loading plugin packet_logger_plugin = hbmqtt.plugins.logging:PacketLoggerPlugin
[2019-12-26 21:31:49,778] :: DEBUG :: hbmqtt.client.plugins :: manager :: _load_plugin :: 71 ::  Initializing plugin packet_logger_plugin = hbmqtt.plugins.logging:PacketLoggerPlugin
[2019-12-26 21:31:49,779] :: DEBUG :: hbmqtt.client.plugins :: manager :: _load_plugins :: 65 ::  Plugin packet_logger_plugin ready
[2019-12-26 21:31:49,784] :: DEBUG :: hbmqtt.client :: client :: connect :: 140 :: Connect to: mqtts://192.168.230.2:8883/
[2019-12-26 21:31:49,816] :: WARNING :: hbmqtt.client :: client :: _connect_coro :: 426 :: MQTT connection failed: ConnectionRefusedError(111, "Connect call failed ('192.168.230.2', 8883)")
[2019-12-26 21:31:49,818] :: WARNING :: hbmqtt.client :: client :: connect :: 145 :: Connection failed: ConnectException(ConnectionRefusedError(111, "Connect call failed ('192.168.230.2', 8883)"))
[2019-12-26 21:31:49,819] :: DEBUG :: hbmqtt.client :: client :: reconnect :: 193 :: Reconnecting with session parameters: Session(clientId=helper1@bumper/helper1, state=disconnected)
[2019-12-26 21:31:49,830] :: INFO :: hbmqtt.broker :: broker :: start :: 284 :: Listener 'tls1' bind to 192.168.230.2:8883 (max_connections=-1)
[2019-12-26 21:31:49,836] :: DEBUG :: hbmqtt.broker :: broker :: start :: 293 :: Broker started
[2019-12-26 21:31:49,842] :: DEBUG :: hbmqtt.broker :: broker :: retain_message :: 602 :: Retaining message on topic $SYS/broker/version
[2019-12-26 21:31:49,843] :: DEBUG :: hbmqtt.broker.plugins.broker_sys :: broker :: on_broker_post_start :: 72 :: Setup $SYS broadcasting every 10 secondes
[2019-12-26 21:31:50,824] :: DEBUG :: hbmqtt.client :: client :: reconnect :: 200 :: Reconnect attempt 1 ...
[2019-12-26 21:31:50,953] :: INFO :: hbmqtt.broker :: broker :: acquire_connection :: 89 :: Listener 'tls1': 1 connections acquired
[2019-12-26 21:31:50,955] :: INFO :: hbmqtt.broker :: broker :: client_connected :: 354 :: Connection from 192.168.230.2:40674 on listener 'tls1'
[2019-12-26 21:31:50,978] :: DEBUG :: hbmqtt.client.plugins.packet_logger_plugin :: logging :: on_mqtt_packet_sent :: 44 :: helper1@bumper/helper1 -out-> ConnectPacket(ts=2019-12-26 21:31:50.969009, fixed=MQTTFixedHeader(length=34, flags=0x0), variable=ConnectVariableHeader(proto_name=MQTT, proto_level=4, flags=0x2, keepalive=9), payload=ConnectVariableHeader(client_id=helper1@bumper/helper1, will_topic=None, will_message=None, username=None, password=None))
[2019-12-26 21:31:50,993] :: DEBUG :: hbmqtt.broker :: broker :: delete_session :: 783 :: Delete session : session helper1@bumper/helper1 doesn't exist
[2019-12-26 21:31:50,994] :: DEBUG :: hbmqtt.broker :: broker :: client_connected :: 389 :: Keep-alive timeout=11
[2019-12-26 21:31:51,001] :: DEBUG :: hbmqtt.broker.plugins.packet_logger_plugin :: logging :: on_mqtt_packet_received :: 36 :: <-in-- ConnectPacket(ts=2019-12-26 21:31:50.982806, fixed=MQTTFixedHeader(length=34, flags=0x0), variable=ConnectVariableHeader(proto_name=MQTT, proto_level=4, flags=0x2, keepalive=9), payload=ConnectVariableHeader(client_id=helper1@bumper/helper1, will_topic=None, will_message=None, username=None, password=None))
[2019-12-26 21:31:51,006] :: DEBUG :: hbmqtt.broker :: broker :: authenticate :: 560 :: 'bumper' plugin result: True
[2019-12-26 21:31:51,018] :: DEBUG :: hbmqtt.broker :: broker :: client_connected :: 413 :: helper1@bumper/helper1 Start messages handling
[2019-12-26 21:31:51,029] :: DEBUG :: hbmqtt.broker.plugins.packet_logger_plugin :: logging :: on_mqtt_packet_sent :: 44 :: helper1@bumper/helper1 -out-> ConnackPacket(ts=2019-12-26 21:31:51.008682, fixed=MQTTFixedHeader(length=2, flags=0x0), variable=ConnackVariableHeader(session_parent=0x0, return_code=0x0), payload=None)
[2019-12-26 21:31:51,040] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: _reader_loop :: 357 :: helper1@bumper/helper1 Starting reader coro
[2019-12-26 21:31:51,063] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: start :: 111 :: Handler tasks started
[2019-12-26 21:31:51,064] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: _retry_deliveries :: 150 :: Begin messages delivery retries
[2019-12-26 21:31:51,065] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: _retry_deliveries :: 158 :: End messages delivery retries
[2019-12-26 21:31:51,066] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: start :: 113 :: Handler ready
[2019-12-26 21:31:51,069] :: DEBUG :: hbmqtt.broker :: broker :: client_connected :: 415 :: Retained messages queue size: 0
[2019-12-26 21:31:51,070] :: DEBUG :: hbmqtt.broker :: broker :: publish_session_retained_messages :: 740 :: Publishing 0 messages retained for session (client id=helper1@bumper/helper1)
[2019-12-26 21:31:51,081] :: DEBUG :: hbmqtt.client.plugins.packet_logger_plugin :: logging :: on_mqtt_packet_received :: 34 :: helper1@bumper/helper1 <-in-- ConnackPacket(ts=2019-12-26 21:31:51.051556, fixed=MQTTFixedHeader(length=2, flags=0x0), variable=ConnackVariableHeader(session_parent=0x0, return_code=0x0), payload=None)
[2019-12-26 21:31:51,083] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: _reader_loop :: 357 :: helper1@bumper/helper1 Starting reader coro
[2019-12-26 21:31:51,095] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: mqtt_deliver_next_message :: 459 :: 0 message(s) available for delivery
[2019-12-26 21:31:51,102] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: start :: 111 :: Handler tasks started
[2019-12-26 21:31:51,103] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: _retry_deliveries :: 150 :: Begin messages delivery retries
[2019-12-26 21:31:51,104] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: _retry_deliveries :: 158 :: End messages delivery retries
[2019-12-26 21:31:51,105] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: start :: 113 :: Handler ready
[2019-12-26 21:31:51,108] :: DEBUG :: hbmqtt.client :: client :: _connect_coro :: 415 :: connected to 192.168.230.2:8883
[2019-12-26 21:31:51,119] :: DEBUG :: hbmqtt.client :: client :: handle_connection_close :: 440 :: Watch broker disconnection
[2019-12-26 21:31:51,120] :: DEBUG :: hbmqtt.client.plugins.packet_logger_plugin :: logging :: on_mqtt_packet_sent :: 44 :: helper1@bumper/helper1 -out-> SubscribePacket(ts=2019-12-26 21:31:51.113437, fixed=MQTTFixedHeader(length=73, flags=0x2), variable=PacketIdVariableHeader(packet_id=1), payload=SubscribePayload(topics=[('iot/p2p/+/+/+/+/helper1/bumper/helper1/+/+/+', 0), ('iot/p2p/+', 0), ('iot/atr/+', 0)]))
[2019-12-26 21:31:51,139] :: DEBUG :: hbmqtt.broker.plugins.packet_logger_plugin :: logging :: on_mqtt_packet_received :: 34 :: helper1@bumper/helper1 <-in-- SubscribePacket(ts=2019-12-26 21:31:51.128036, fixed=MQTTFixedHeader(length=73, flags=0x2), variable=PacketIdVariableHeader(packet_id=1), payload=SubscribePayload(topics=[('iot/p2p/+/+/+/+/helper1/bumper/helper1/+/+/+', 0), ('iot/p2p/+', 0), ('iot/atr/+', 0)]))
[2019-12-26 21:31:51,147] :: DEBUG :: hbmqtt.broker :: broker :: client_connected :: 465 :: helper1@bumper/helper1 handling subscription
[2019-12-26 21:31:51,171] :: DEBUG :: hbmqtt.broker :: broker :: topic_filtering :: 595 :: 'bumper' plugin result: None
[2019-12-26 21:31:51,173] :: DEBUG :: hbmqtt.broker :: broker :: topic_filtering :: 595 :: 'auth_anonymous' plugin result: None
[2019-12-26 21:31:51,174] :: DEBUG :: hbmqtt.broker :: broker :: topic_filtering :: 595 :: 'auth_file' plugin result: None
[2019-12-26 21:31:51,175] :: DEBUG :: hbmqtt.broker :: broker :: topic_filtering :: 595 :: 'broker_sys' plugin result: None
[2019-12-26 21:31:51,176] :: DEBUG :: hbmqtt.broker :: broker :: topic_filtering :: 595 :: 'packet_logger_plugin' plugin result: None
[2019-12-26 21:31:51,177] :: DEBUG :: hbmqtt.broker :: broker :: topic_filtering :: 595 :: 'topic_taboo' plugin result: True
[2019-12-26 21:31:51,428] :: DEBUG :: hbmqtt.broker :: broker :: topic_filtering :: 595 :: 'bumper' plugin result: None
[2019-12-26 21:31:51,429] :: DEBUG :: hbmqtt.broker :: broker :: topic_filtering :: 595 :: 'auth_anonymous' plugin result: None
[2019-12-26 21:31:51,430] :: DEBUG :: hbmqtt.broker :: broker :: topic_filtering :: 595 :: 'auth_file' plugin result: None
[2019-12-26 21:31:51,431] :: DEBUG :: hbmqtt.broker :: broker :: topic_filtering :: 595 :: 'broker_sys' plugin result: None
[2019-12-26 21:31:51,432] :: DEBUG :: hbmqtt.broker :: broker :: topic_filtering :: 595 :: 'packet_logger_plugin' plugin result: None
[2019-12-26 21:31:51,433] :: DEBUG :: hbmqtt.broker :: broker :: topic_filtering :: 595 :: 'topic_taboo' plugin result: True
[2019-12-26 21:31:51,483] :: DEBUG :: hbmqtt.broker :: broker :: topic_filtering :: 595 :: 'bumper' plugin result: None
[2019-12-26 21:31:51,484] :: DEBUG :: hbmqtt.broker :: broker :: topic_filtering :: 595 :: 'auth_anonymous' plugin result: None
[2019-12-26 21:31:51,485] :: DEBUG :: hbmqtt.broker :: broker :: topic_filtering :: 595 :: 'auth_file' plugin result: None
[2019-12-26 21:31:51,486] :: DEBUG :: hbmqtt.broker :: broker :: topic_filtering :: 595 :: 'broker_sys' plugin result: None
[2019-12-26 21:31:51,487] :: DEBUG :: hbmqtt.broker :: broker :: topic_filtering :: 595 :: 'packet_logger_plugin' plugin result: None
[2019-12-26 21:31:51,488] :: DEBUG :: hbmqtt.broker :: broker :: topic_filtering :: 595 :: 'topic_taboo' plugin result: True
[2019-12-26 21:31:51,497] :: DEBUG :: hbmqtt.broker :: broker :: publish_retained_messages_for_subscription :: 755 :: Begin broadcasting messages retained due to subscription on 'iot/p2p/+/+/+/+/helper1/bumper/helper1/+/+/+' from (client id=helper1@bumper/helper1)
[2019-12-26 21:31:51,498] :: DEBUG :: hbmqtt.broker :: broker :: publish_retained_messages_for_subscription :: 760 :: matching : $SYS/broker/version iot/p2p/+/+/+/+/helper1/bumper/helper1/+/+/+
[2019-12-26 21:31:51,505] :: DEBUG :: hbmqtt.broker :: broker :: publish_retained_messages_for_subscription :: 769 :: End broadcasting messages retained due to subscription on 'iot/p2p/+/+/+/+/helper1/bumper/helper1/+/+/+' from (client id=helper1@bumper/helper1)
[2019-12-26 21:31:51,506] :: DEBUG :: hbmqtt.broker :: broker :: publish_retained_messages_for_subscription :: 755 :: Begin broadcasting messages retained due to subscription on 'iot/p2p/+' from (client id=helper1@bumper/helper1)
[2019-12-26 21:31:51,507] :: DEBUG :: hbmqtt.broker :: broker :: publish_retained_messages_for_subscription :: 760 :: matching : $SYS/broker/version iot/p2p/+
[2019-12-26 21:31:51,510] :: DEBUG :: hbmqtt.broker :: broker :: publish_retained_messages_for_subscription :: 769 :: End broadcasting messages retained due to subscription on 'iot/p2p/+' from (client id=helper1@bumper/helper1)
[2019-12-26 21:31:51,511] :: DEBUG :: hbmqtt.broker :: broker :: publish_retained_messages_for_subscription :: 755 :: Begin broadcasting messages retained due to subscription on 'iot/atr/+' from (client id=helper1@bumper/helper1)
[2019-12-26 21:31:51,512] :: DEBUG :: hbmqtt.broker :: broker :: publish_retained_messages_for_subscription :: 760 :: matching : $SYS/broker/version iot/atr/+
[2019-12-26 21:31:51,515] :: DEBUG :: hbmqtt.broker :: broker :: publish_retained_messages_for_subscription :: 769 :: End broadcasting messages retained due to subscription on 'iot/atr/+' from (client id=helper1@bumper/helper1)
[2019-12-26 21:31:51,518] :: DEBUG :: hbmqtt.broker :: broker :: client_connected :: 481 :: {'iot/p2p/+/+/+/+/helper1/bumper/helper1/+/+/+': [(Session(clientId=helper1@bumper/helper1, state=connected), 0)], 'iot/p2p/+': [(Session(clientId=helper1@bumper/helper1, state=connected), 0)], 'iot/atr/+': [(Session(clientId=helper1@bumper/helper1, state=connected), 0)]}
[2019-12-26 21:31:51,530] :: DEBUG :: hbmqtt.broker.plugins.packet_logger_plugin :: logging :: on_mqtt_packet_sent :: 44 :: helper1@bumper/helper1 -out-> SubackPacket(ts=2019-12-26 21:31:51.490622, fixed=MQTTFixedHeader(length=5, flags=0x0), variable=PacketIdVariableHeader(packet_id=1), payload=SubackPayload(return_codes=[0, 0, 0]))
[2019-12-26 21:31:51,538] :: DEBUG :: hbmqtt.broker :: broker :: shutdown :: 328 :: Broker closing
[2019-12-26 21:31:51,539] :: INFO :: hbmqtt.broker :: broker :: shutdown :: 329 :: Broker closed
[2019-12-26 21:31:51,558] :: DEBUG :: hbmqtt.client.plugins.packet_logger_plugin :: logging :: on_mqtt_packet_received :: 34 :: helper1@bumper/helper1 <-in-- SubackPacket(ts=2019-12-26 21:31:51.549572, fixed=MQTTFixedHeader(length=5, flags=0x0), variable=PacketIdVariableHeader(packet_id=1), payload=SubackPayload(return_codes=[0, 0, 0]))
[2019-12-26 21:31:51,567] :: DEBUG :: hbmqtt.client :: client :: deliver_message :: 331 :: Waiting message delivery
[2019-12-26 21:31:51,570] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: mqtt_deliver_next_message :: 459 :: 0 message(s) available for delivery
[2019-12-26 21:31:56,445] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: _reader_loop :: 423 :: Task cancelled, reader loop ending
[2019-12-26 21:31:56,447] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: broker_handler :: handle_disconnect :: 57 :: Client disconnecting
[2019-12-26 21:31:56,448] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: _reader_loop :: 437 :: helper1@bumper/helper1 Reader coro stopped
[2019-12-26 21:31:56,449] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: _stop_waiters :: 133 :: Stopping 0 puback waiters
[2019-12-26 21:31:56,450] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: _stop_waiters :: 134 :: Stopping 0 pucomp waiters
[2019-12-26 21:31:56,451] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: _stop_waiters :: 135 :: Stopping 0 purec waiters
[2019-12-26 21:31:56,452] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: _stop_waiters :: 136 :: Stopping 0 purel waiters
[2019-12-26 21:31:56,454] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: stop :: 121 :: waiting for tasks to be stopped
[2019-12-26 21:31:56,464] :: DEBUG :: hbmqtt.broker :: broker :: client_connected :: 500 :: Client loop cancelled
[2019-12-26 21:31:56,465] :: DEBUG :: hbmqtt.broker :: broker :: client_connected :: 507 :: helper1@bumper/helper1 Client disconnected
[2019-12-26 21:31:56,466] :: INFO :: hbmqtt.broker :: broker :: release_connection :: 100 :: Listener 'tls1': 0 connections acquired
[2019-12-26 21:31:56,469] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: mqtt_deliver_next_message :: 465 :: Delivering message None
[2019-12-26 21:31:56,473] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: mqtt_deliver_next_message :: 465 :: Delivering message None
[2019-12-26 21:31:56,476] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: _reader_loop :: 423 :: Task cancelled, reader loop ending
[2019-12-26 21:31:56,477] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: client_handler :: handle_connection_closed :: 170 :: Broker closed connection
[2019-12-26 21:31:56,478] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: _reader_loop :: 437 :: helper1@bumper/helper1 Reader coro stopped
[2019-12-26 21:31:56,479] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: _stop_waiters :: 133 :: Stopping 0 puback waiters
[2019-12-26 21:31:56,480] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: _stop_waiters :: 134 :: Stopping 0 pucomp waiters
[2019-12-26 21:31:56,482] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: _stop_waiters :: 135 :: Stopping 0 purec waiters
[2019-12-26 21:31:56,483] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: _stop_waiters :: 136 :: Stopping 0 purel waiters
[2019-12-26 21:31:56,484] :: DEBUG :: hbmqtt.mqtt.protocol.handler :: handler :: stop :: 121 :: waiting for tasks to be stopped
bmartin5692 commented 4 years ago

It looks like you are getting permission denied when the server starts and is binding ports (443 specifically). Try running with sudo or root and see if it works then.

Tutmanichtun commented 4 years ago 
pi@DNS-Pi:~/bumper $ sudo pipenv run python3.8 -m bumper --listen 192.168.230.2 --announce 192.168.230.2 --debug
Traceback (most recent call last):
  File "/usr/local/lib/python3.8/runpy.py", line 183, in _run_module_as_main
    mod_name, mod_spec, code = _get_module_details(mod_name, _Error)
  File "/usr/local/lib/python3.8/runpy.py", line 142, in _get_module_details
    return _get_module_details(pkg_main_name, error)
  File "/usr/local/lib/python3.8/runpy.py", line 109, in _get_module_details
    __import__(pkg_name)
  File "/home/pi/bumper/bumper/__init__.py", line 3, in <module>
    from bumper.confserver import ConfServer
  File "/home/pi/bumper/bumper/confserver.py", line 12, in <module>
    from aiohttp import web
ModuleNotFoundError: No module named 'aiohttp'

But the module seems to be installed: pi@DNS-Pi:~/bumper $ python3.8 -c 'import aiohttp' executes without an error. Btw: I'm running pi-hole on the same Pi, but according to the Documentation there shouldn't be a conflict.

bmartin5692 commented 4 years ago

That is strange the module doesn't load while running with sudo. You may need to re-do the pipenv while running as sudo.

Tutmanichtun commented 4 years ago

Yes, that was my mistake: sudo pipenv install fixed this. Thanks for your support. :)

ErfolgreichCharismatisch commented 3 years ago

Hi, can you help me with https://github.com/bmartin5692/bumper/issues/125 ?