hbmqtt: asyncio Warning: BrokerProtocolHandler Unhandled exception in reader coro: IncompleteReadError

I get a lot of warning on Ubuntu 17.10 like this

[2018-03-30 13:05:45,416] :: WARNING - BrokerProtocolHandler Unhandled exception in reader coro: IncompleteReadError('0 bytes read on a total of 1 expected bytes',)

here’s the version

 python3 --version
Python 3.6.3

 pip3 freeze | grep hbmqtt
hbmqtt==0.9.2

hbmqtt
[2018-03-30 13:05:35,165] :: INFO - Exited state new
[2018-03-30 13:05:35,165] :: INFO - Entered state starting
[2018-03-30 13:05:35,166] :: INFO - Listener 'default' bind to 0.0.0.0:1883 (max_connections=-1)
[2018-03-30 13:05:35,166] :: INFO - Exited state starting
[2018-03-30 13:05:35,166] :: INFO - Entered state started
[2018-03-30 13:05:45,413] :: INFO - Listener 'default': 1 connections acquired
[2018-03-30 13:05:45,413] :: INFO - Connection from 127.0.0.1:49098 on listener 'default'
[2018-03-30 13:05:45,414] :: INFO - Exited state new
[2018-03-30 13:05:45,414] :: INFO - Entered state connected
[2018-03-30 13:05:45,416] :: WARNING - BrokerProtocolHandler Unhandled exception in reader coro: IncompleteReadError('0 bytes read on a total of 1 expected bytes',)
[2018-03-30 13:05:45,416] :: INFO - Exited state connected
[2018-03-30 13:05:45,417] :: INFO - Entered state disconnected
[2018-03-30 13:05:45,417] :: INFO - Listener 'default': 0 connections acquired

hbmqtt_pub --url "mqtt://localhost:1883" -t "test/sensor1" -m "ciao"
[2018-03-30 13:05:45,409] :: INFO - hbmqtt_pub/13323-nicklang-laptop Connecting to broker
[2018-03-30 13:05:45,415] :: INFO - Exited state new
[2018-03-30 13:05:45,415] :: INFO - Entered state connected
[2018-03-30 13:05:45,415] :: INFO - hbmqtt_pub/13323-nicklang-laptop Publishing to 'test/sensor1'
[2018-03-30 13:05:45,416] :: INFO - Exited state connected
[2018-03-30 13:05:45,416] :: INFO - Entered state disconnected
[2018-03-30 13:05:45,416] :: INFO - hbmqtt_pub/13323-nicklang-laptop Disconnected from broker

the broker work fine but I get warning for every sent message

About this issue

Original URL
State: open
Created 6 years ago
Reactions: 1
Comments: 20 (1 by maintainers)

Commits related to this issue

Switch MQTT implementation to aiomqtt (Stability issues with the old library, see https://github.com/beerfactory/hbmqtt/issues/119) — committed to oxytu/deconz-to-mqtt by deleted user 5 years ago

Most upvoted comments

I ‘fixed’ it by not useing hbmqtt anymore. Now using mosquitto.

+11

joopy on Sep 9, 2018

Ok, think I’ve found out:

Client is running in a mixed async/sync environment.
A reload process lasting more than 10 seconds was blocking processing, and so hbmqtt wasn’t able to send the keepalive PING on time.
Solution/hotfix: Increase the client keepalive to a larger value from the default 10 seconds.

ramonpoca on Oct 16, 2018

Same problem for me in Home Assistant, any fix yet? 2018-09-24 17:21:41 WARNING (MainThread) [hbmqtt.mqtt.protocol.handler] BrokerProtocolHandler Unhandled exception in reader coro: IncompleteReadError(‘0 bytes read on a total of 1 expected bytes’,)

Merwenus on Sep 24, 2018

Keeping with the tracing, I’ve dumped it happening with wireshark. Hex dump follows. After the last c0 00 packet sent by hbmqtt, the server responds with a TCP RST (reset). Server is mosquitto 1.5.3 macos (homebrew).

00000000  10 23 00 04 4d 51 54 54  04 02 00 09 00 17 68 62   .#..MQTT ......hb
00000010  6d 71 74 74 2f 47 38 6a  34 38 42 46 50 6d 4e 6f   mqtt/G8j 48BFPmNo
00000020  60 30 45 30 7a                                     `0E0z
    00000000  20 02 00 00                                         ...
00000025  82 06 00 01 00 01 23 02                            ......#. 
    00000004  90 03 00 01 02                                     .....
0000002D  c0 00                                              ..
    00000009  d0 00                                              ..
    0000000B  34 24 00 11 2f 66 69 72  65 62 61 73 65 2f 63 6f   4$../fir ebase/co
    0000001B  6e 74 72 6f 6c 00 01 7b  22 72 65 6c 6f 61 64 22   ntrol..{ "reload"
    0000002B  3a 20 33 37 30 7d                                  : 370}
0000002F  50 02 00 01                                        P...
    00000031  62 02 00 01                                        b...
00000033  70 02 00 01                                        p...
00000037  c0 00                                              ..
00000000  10 23 00 04 4d 51 54 54  04 02 00 09 00 17 68 62   .#..MQTT ......hb
00000010  6d 71 74 74 2f 47 38 6a  34 38 42 46 50 6d 4e 6f   mqtt/G8j 48BFPmNo
00000020  60 30 45 30 7a                                     `0E0z
    00000000  20 02 00 00                                         ...
00000025  82 06 00 01 00 01 23 02                            ......#. 
    00000004  90 03 00 01 02                                     .....
0000002D  c0 00                                              ..
    00000009  d0 00                                              ..
    0000000B  34 24 00 11 2f 66 69 72  65 62 61 73 65 2f 63 6f   4$../fir ebase/co
    0000001B  6e 74 72 6f 6c 00 01 7b  22 72 65 6c 6f 61 64 22   ntrol..{ "reload"
    0000002B  3a 20 33 37 30 7d                                  : 370}
0000002F  50 02 00 01                                        P...
    00000031  62 02 00 01                                        b...
00000033  70 02 00 01                                        p...
00000037  c0 00                                              ..

and a corresponding mosquitto log for the same error:

1539722788: New connection from ::1 on port 1883.
1539722788: New client connected from ::1 as hbmqtt/1hs_mtXV?>y4xqRT (c1, k9).
1539722788: No will message specified.
1539722788: Sending CONNACK to hbmqtt/1hs_mtXV?>y4xqRT (0, 0)
1539722788: Received SUBSCRIBE from hbmqtt/1hs_mtXV?>y4xqRT
1539722788: 	# (QoS 2)
1539722788: hbmqtt/1hs_mtXV?>y4xqRT 2 #
1539722788: Sending SUBACK to hbmqtt/1hs_mtXV?>y4xqRT
1539722797: Received PINGREQ from hbmqtt/1hs_mtXV?>y4xqRT
1539722797: Sending PINGRESP to hbmqtt/1hs_mtXV?>y4xqRT
1539722806: Received PINGREQ from hbmqtt/1hs_mtXV?>y4xqRT
1539722806: Sending PINGRESP to hbmqtt/1hs_mtXV?>y4xqRT
1539722813: Received PUBLISH from gsSAIvf`EKT5YY\VKc_aeIeiwb3AH@[a;tmx]P:6X0fAlf<7[h4\ekEuZ1fH:ThV (d0, q2, r0, m7, '/firebase/control', ... (15 bytes))
1539722813: Sending PUBREC to gsSAIvf`EKT5YY\VKc_aeIeiwb3AH@[a;tmx]P:6X0fAlf<7[h4\ekEuZ1fH:ThV (Mid: 7)
1539722813: Received PUBREL from gsSAIvf`EKT5YY\VKc_aeIeiwb3AH@[a;tmx]P:6X0fAlf<7[h4\ekEuZ1fH:ThV (Mid: 7)
1539722813: Sending PUBCOMP to gsSAIvf`EKT5YY\VKc_aeIeiwb3AH@[a;tmx]P:6X0fAlf<7[h4\ekEuZ1fH:ThV (Mid: 7)
1539722813: Sending PUBLISH to hbmqtt/1hs_mtXV?>y4xqRT (d0, q2, r0, m1, '/firebase/control', ... (15 bytes))
1539722813: Received PUBREC from hbmqtt/1hs_mtXV?>y4xqRT (Mid: 1)
1539722813: Sending PUBREL to hbmqtt/1hs_mtXV?>y4xqRT (Mid: 1)
1539722813: Received PUBCOMP from hbmqtt/1hs_mtXV?>y4xqRT (Mid: 1)
1539722826: Client hbmqtt/1hs_mtXV?>y4xqRT has exceeded timeout, disconnecting.
1539722826: Socket error on client hbmqtt/1hs_mtXV?>y4xqRT, disconnecting.

ramonpoca on Oct 16, 2018

I’ve traced the error a bit. Added a logging.exception that shows:

ERROR:hbmqtt.mqtt.protocol.handler:0 bytes read on a total of 1 expected bytes
Traceback (most recent call last):
  File "/usr/local/miniconda3/lib/python3.6/site-packages/hbmqtt/mqtt/protocol/handler.py", line 373, in _
reader_loop
    keepalive_timeout, loop=self._loop)
  File "/usr/local/miniconda3/lib/python3.6/asyncio/tasks.py", line 358, in wait_for
    return fut.result()
  File "/usr/local/miniconda3/lib/python3.6/site-packages/hbmqtt/mqtt/packet.py", line 104, in from_stream
    byte1 = yield from read_or_raise(reader, 1)
  File "/usr/local/miniconda3/lib/python3.6/site-packages/hbmqtt/codecs.py", line 52, in read_or_raise
    data = yield from reader.read(n)
  File "/usr/local/miniconda3/lib/python3.6/site-packages/hbmqtt/adapters.py", line 146, in read
    data = yield from self._reader.readexactly(n)
  File "/usr/local/miniconda3/lib/python3.6/asyncio/streams.py", line 672, in readexactly
    raise IncompleteReadError(incomplete, n)
asyncio.streams.IncompleteReadError: 0 bytes read on a total of 1 expected bytes
WARNING:hbmqtt.mqtt.protocol.handler:ClientProtocolHandler Unhandled exception in reader coro: IncompleteReadError('0 bytes read on a total of 1 expected bytes',)

ramonpoca on Oct 16, 2018

Same issue here !

anthonyray on Oct 3, 2018

I discovered that the client is as well experiencing the same problem…

arnulfojr on Sep 17, 2018