Request for independent test of scale disconnection behaviour

a112358132134 commented 2 years ago

I have an odd scenario occurring that I'm hoping someone can independently reconfirm or disprove.

Steps to reperform:

Start mqtt broker, pyde1
Connect to DE1, scale
Forcefully switch scale off (e.g. pull out power)

Behaviour observed after step 3:

As expected, after a short wait (1-3 seconds), pyde1 reports scale as disconnected.
However, shortly after that (1-3 seconds) pyde1 also reports the DE1 as disconnected. Note that a reconnection is quickly attempted and subsequently succeeds, so this is a temporary situation.

The odd behaviour (from my perspective) is the impact the scale disconnection appears to have on the DE1 connection. Does anyone else see this, or is it something unique to my setup? If not unique to me, is this supposed to happen?

NB: Nothing appears in journalctl about any of this.

jeffsf commented 2 years ago

You can enable low-level Bluetooth debugging by changing the LOGFILE handler the root.bleak logger to DEBUG

This is likely an OS or hardware issue.

Is this with the Decent Scale, which is unsupported?

(Please put details of your software versions and/or suggestions of priority into the body, rather than the title)

jeffsf commented 2 years ago

2022-01-13 08:34:08,872 INFO [Controller] Scale: disconnect_callback: Disconnected from AtomaxSkaleII at FF:06:AF:aa:bb:cc, willful_disconnect: False
2022-01-13 08:34:08,889 INFO [Controller] Scale: Will try reconnecting to AtomaxSkaleII at FF:06:AF:aa:bb:cc
2022-01-13 08:34:08,890 INFO [Controller] Scale: Connecting to AtomaxSkaleII at FF:06:AF:aa:bb:cc
2022-01-13 08:34:19,113 ERROR [Controller] Scale: Connection failed to AtomaxSkaleII at FF:06:AF:aa:bb:cc
2022-01-13 08:34:19,122 INFO [Controller] Scale: Will try reconnecting to AtomaxSkaleII at FF:06:AF:aa:bb:cc
2022-01-13 08:34:19,123 INFO [Controller] Scale: Connecting to AtomaxSkaleII at FF:06:AF:aa:bb:cc
2022-01-13 08:34:29,303 ERROR [Controller] Scale: Connection failed to AtomaxSkaleII at FF:06:AF:aa:bb:cc
2022-01-13 08:34:29,315 INFO [Controller] Scale: Will try reconnecting to AtomaxSkaleII at FF:06:AF:aa:bb:cc
2022-01-13 08:34:29,316 INFO [Controller] Scale: Connecting to AtomaxSkaleII at FF:06:AF:aa:bb:cc
2022-01-13 08:34:39,487 ERROR [Controller] Scale: Connection failed to AtomaxSkaleII at FF:06:AF:aa:bb:cc
2022-01-13 08:34:39,491 INFO [Controller] Scale: Will try reconnecting to AtomaxSkaleII at FF:06:AF:aa:bb:cc
2022-01-13 08:34:39,492 INFO [Controller] Scale: Connecting to AtomaxSkaleII at FF:06:AF:aa:bb:cc
2022-01-13 08:34:46,565 INFO [Controller] Scale: Connected to AtomaxSkaleII at FF:06:AF:aa:bb:cc
2022-01-13 08:34:46,571 INFO [Controller] Scale: Scale.standard_initialization()
2022-01-13 08:34:46,832 INFO [Controller] Scale.AtomaxIIScale: Display on
2022-01-13 08:34:46,920 INFO [Controller] Scale.AtomaxIIScale: Sending weight updates
2022-01-13 08:34:46,929 WARNING [Controller] Scale.Processor: Resetting scale due to gap in reports: 38.579 > 0.8 s
2022-01-13 08:34:47,035 INFO [Controller] Scale.AtomaxIIScale: Sending button updates
2022-01-13 08:34:47,063 INFO [Controller] Scale: Loading scale-period estimate of 0.10312 from database
2022-01-13 08:34:47,157 INFO [Controller] Scale.AtomaxIIScale: Grams selected
2022-01-13 08:34:47,160 INFO [Controller] Scale: Ready

a112358132134 commented 2 years ago

Thanks @jeffsf.

Yes, this is with the Decent Scale, which I appreciate is unsupported.

With the DEBUG flag set for bleak, there are no smoking guns on a root cause. I also tried the other way around (i.e. switching off the DE1), and got the same result (scale briefly disconnects before reconnecting).

All my systems are running bluez v5.62 which, from a bit of searching, appears to have a lot of anecdotally reported connection regressions over prior versions. The only bluetooth devices I use are the DE1 and the Decent Scale, so I don't have a broader perspective on the validity of these opinions. I assume you're running the default bullseye bluez v5.55 on your rpi?

Here is the full log output for a forced scale disconnect:

2022-01-14 08:52:30,021 INFO [MainProcess] Config.YAML: Loading config overrides from /usr/local/etc/pyde1/pyde1.conf
2022-01-14 08:52:30,128 DEBUG [MainProcess] Config.YAML: Setting mqtt.TOPIC_ROOT
2022-01-14 08:52:30,129 DEBUG [MainProcess] Config.YAML: Setting mqtt.CLIENT_ID_PREFIX
2022-01-14 08:52:30,130 DEBUG [MainProcess] Config.YAML: Setting mqtt.BROKER_HOSTNAME
2022-01-14 08:52:30,131 DEBUG [MainProcess] Config.YAML: Setting mqtt.BROKER_PORT
2022-01-14 08:52:30,132 DEBUG [MainProcess] Config.YAML: Setting mqtt.TRANSPORT
2022-01-14 08:52:30,133 DEBUG [MainProcess] Config.YAML: Setting mqtt.KEEPALIVE
2022-01-14 08:52:30,134 DEBUG [MainProcess] Config.YAML: Setting mqtt.USERNAME
2022-01-14 08:52:30,135 DEBUG [MainProcess] Config.YAML: Setting mqtt.PASSWORD
2022-01-14 08:52:30,136 DEBUG [MainProcess] Config.YAML: Setting mqtt.DEBUG
2022-01-14 08:52:30,137 DEBUG [MainProcess] Config.YAML: Setting http.SERVER_HOST
2022-01-14 08:52:30,138 DEBUG [MainProcess] Config.YAML: Setting http.SERVER_PORT
2022-01-14 08:52:30,139 DEBUG [MainProcess] Config.YAML: Setting http.SERVER_ROOT
2022-01-14 08:52:30,140 DEBUG [MainProcess] Config.YAML: Setting logging.LOG_DIRECTORY
2022-01-14 08:52:30,141 DEBUG [MainProcess] Config.YAML: Setting logging.LOG_FILENAME
2022-01-14 08:52:30,141 DEBUG [MainProcess] Config.YAML: Setting logging.formatters.STYLE
2022-01-14 08:52:30,142 DEBUG [MainProcess] Config.YAML: Setting logging.formatters.LOGFILE
2022-01-14 08:52:30,143 DEBUG [MainProcess] Config.YAML: Setting logging.formatters.MQTT
2022-01-14 08:52:30,144 DEBUG [MainProcess] Config.YAML: Setting logging.formatters.STDERR
2022-01-14 08:52:30,145 DEBUG [MainProcess] Config.YAML: Setting logging.handlers.LOGFILE
2022-01-14 08:52:30,146 DEBUG [MainProcess] Config.YAML: Setting logging.handlers.MQTT
2022-01-14 08:52:30,147 DEBUG [MainProcess] Config.YAML: Setting logging.handlers.STDERR
2022-01-14 08:52:30,148 DEBUG [MainProcess] Config.YAML: Setting logging.LOGGERS
2022-01-14 08:52:30,149 DEBUG [MainProcess] Config.YAML: Setting bluetooth.SCAN_TIME
2022-01-14 08:52:30,150 DEBUG [MainProcess] Config.YAML: Setting bluetooth.CONNECT_TIMEOUT
2022-01-14 08:52:30,151 DEBUG [MainProcess] Config.YAML: Setting bluetooth.DISCONNECT_TIMEOUT
2022-01-14 08:52:30,151 DEBUG [MainProcess] Config.YAML: Setting bluetooth.SCAN_CACHE_EXPIRY
2022-01-14 08:52:30,152 DEBUG [MainProcess] Config.YAML: Setting bluetooth.RECONNECT_RETRY_COUNT
2022-01-14 08:52:30,153 DEBUG [MainProcess] Config.YAML: Setting bluetooth.RECONNECT_GAP
2022-01-14 08:52:30,155 DEBUG [MainProcess] Config.YAML: Setting bluetooth.ID_FILE_DIRECTORY
2022-01-14 08:52:30,156 DEBUG [MainProcess] Config.YAML: Setting bluetooth.ID_FILE_SUFFIX
2022-01-14 08:52:30,157 DEBUG [MainProcess] Config.YAML: Setting database.FILENAME
2022-01-14 08:52:30,158 DEBUG [MainProcess] Config.YAML: Setting de1.LINE_FREQUENCY
2022-01-14 08:52:30,159 DEBUG [MainProcess] Config.YAML: Setting de1.STOP_AT_WEIGHT_ADJUST
2022-01-14 08:52:30,160 INFO [MainProcess] Config.YAML: Config overrides loaded from /usr/local/etc/pyde1/pyde1.conf
2022-01-14 08:52:30,813 INFO [MainProcess] root: Configured stderr_handler: <StreamHandler <stderr> (WARNING)>
2022-01-14 08:52:30,815 INFO [MainProcess] root: Configured mqtt_handler: <PipeHandler (ERROR)>
2022-01-14 08:52:30,823 INFO [MainProcess] root: Configured logfile_handler: <WatchedFileHandler /var/log/pyde1/pyde1.log (INFO)>
2022-01-14 08:52:30,825 INFO [MainProcess] root: Started <logging.handlers.QueueListener object at 0xffff97955a60>
2022-01-14 08:52:30,827 DEBUG [MainProcess] root: log_queue_listener handlers: (<StreamHandler <stderr> (WARNING)>, <PipeHandler (ERROR)>, <WatchedFileHandler /var/log/pyde1/pyde1.log (INFO)>)
2022-01-14 08:52:30,874 INFO [MainProcess] Logging.Config: Setting root.aiosqlite to INFO
2022-01-14 08:52:30,877 INFO [MainProcess] Logging.Config: Setting root.asyncio to INFO
2022-01-14 08:52:30,878 INFO [MainProcess] Logging.Config: Setting root.bleak to DEBUG
2022-01-14 08:52:30,933 INFO [MainProcess] Supervised.Process.LogMQTT: Starting
2022-01-14 08:52:30,956 INFO [MainProcess] Supervised.Process.LogMQTT: Started: <Process name='LogMQTT' pid=3283 parent=3237 started>
2022-01-14 08:52:30,961 INFO [MainProcess] Supervised.Process.OutboundAPI: Starting
2022-01-14 08:52:30,981 INFO [MainProcess] Supervised.Process.OutboundAPI: Started: <Process name='OutboundAPI' pid=3284 parent=3237 started>
2022-01-14 08:52:30,987 INFO [MainProcess] Supervised.Process.InboundAPI: Starting
2022-01-14 08:52:31,011 INFO [MainProcess] Supervised.Process.InboundAPI: Started: <Process name='InboundAPI' pid=3285 parent=3237 started>
2022-01-14 08:52:31,031 INFO [MainProcess] Supervised.Process.DatabaseLogger: Starting
2022-01-14 08:52:31,056 INFO [MainProcess] Supervised.Process.DatabaseLogger: Started: <Process name='DatabaseLogger' pid=3286 parent=3237 started>
2022-01-14 08:52:31,072 INFO [MainProcess] Supervised.Process.Controller: Starting
2022-01-14 08:52:31,099 INFO [MainProcess] Supervised.Process.Controller: Started: <Process name='Controller' pid=3288 parent=3237 started>
2022-01-14 08:52:31,111 INFO [MainProcess] Run: About to start loop
2022-01-14 08:52:33,255 INFO [LogMQTT] Logging.Config: Setting root.aiosqlite to INFO
2022-01-14 08:52:33,273 INFO [LogMQTT] Logging.Config: Setting root.asyncio to INFO
2022-01-14 08:52:33,277 INFO [LogMQTT] Logging.Config: Setting root.bleak to DEBUG
2022-01-14 08:52:33,252 INFO [OutboundAPI] Logging.Config: Setting root.aiosqlite to INFO
2022-01-14 08:52:33,291 INFO [LogMQTT] LogMQTT: Watching for shutdown event
2022-01-14 08:52:33,259 INFO [OutboundAPI] Logging.Config: Setting root.asyncio to INFO
2022-01-14 08:52:33,260 INFO [OutboundAPI] Logging.Config: Setting root.bleak to DEBUG
2022-01-14 08:52:33,275 INFO [OutboundAPI] Outbound: Watching for shutdown event
2022-01-14 08:52:33,318 INFO [OutboundAPI] Supervised.Task.heartbeat: Starting
2022-01-14 08:52:33,325 INFO [OutboundAPI] Outbound: Connecting with username 'pyde1'
2022-01-14 08:52:33,361 INFO [LogMQTT] Supervised.Task.heartbeat: Starting
2022-01-14 08:52:33,367 INFO [LogMQTT] LogMQTT: Connecting with username 'pyde1'
2022-01-14 08:52:33,421 INFO [OutboundAPI] Outbound.MQTTClient: CB: Connect: flags: {'session present': 0}, reasonCode: Success, properties [ReceiveMaximum : 20, TopicAliasMaximum : 10]
2022-01-14 08:52:33,448 INFO [LogMQTT] LogMQTT.MQTTClient: CB: Connect: flags: {'session present': 0}, reasonCode: Success, properties [ReceiveMaximum : 20, TopicAliasMaximum : 10]
2022-01-14 08:52:33,810 INFO [DatabaseLogger] Logging.Config: Setting root.aiosqlite to INFO
2022-01-14 08:52:33,815 INFO [DatabaseLogger] Logging.Config: Setting root.asyncio to INFO
2022-01-14 08:52:33,816 INFO [DatabaseLogger] Logging.Config: Setting root.bleak to DEBUG
2022-01-14 08:52:33,827 INFO [DatabaseLogger] Database.Logger: Watching for shutdown event
2022-01-14 08:52:33,855 INFO [DatabaseLogger] Supervised.Task.heartbeat: Starting
2022-01-14 08:52:33,860 INFO [DatabaseLogger] Supervised.Task.record_data: Starting
2022-01-14 08:52:34,082 INFO [InboundAPI] Logging.Config: Setting root.aiosqlite to INFO
2022-01-14 08:52:34,086 INFO [InboundAPI] Logging.Config: Setting root.asyncio to INFO
2022-01-14 08:52:34,089 INFO [InboundAPI] Logging.Config: Setting root.bleak to DEBUG
2022-01-14 08:52:34,092 INFO [InboundAPI] Inbound: Watching for shutdown event
2022-01-14 08:52:34,125 INFO [InboundAPI] Supervised.Task.heartbeat: Starting
2022-01-14 08:52:34,156 INFO [InboundAPI] Supervised.Executor.HTTPServer.serve_forever: Starting
2022-01-14 08:52:34,278 INFO [Controller] Logging.Config: Setting root.aiosqlite to INFO
2022-01-14 08:52:34,281 INFO [Controller] Logging.Config: Setting root.asyncio to INFO
2022-01-14 08:52:34,283 INFO [Controller] Logging.Config: Setting root.bleak to DEBUG
2022-01-14 08:52:34,288 INFO [Controller] Controller: Watching for shutdown event
2022-01-14 08:52:34,314 INFO [Controller] Supervised.Task._request_queue_processor: Starting
2022-01-14 08:52:34,323 INFO [Controller] Supervised.Task._response_queue_processor: Starting
2022-01-14 08:52:34,339 INFO [Controller] DE1: prepare_for_connection(wipe_address=True)
2022-01-14 08:53:54,236 INFO [InboundAPI] Inbound.HTTP: Request: PATCH /scan HTTP/1.1
2022-01-14 08:53:54,305 INFO [Controller] Supervised.Task.DiscoveredDevices._device_add_queue_worker: Starting
2022-01-14 08:53:54,347 INFO [DatabaseLogger] Database.Notifications: No rolling buffer for ScannerNotification
2022-01-14 08:53:54,400 WARNING [Controller] root.asyncio: Executing <Task pending name='RequestQueueProcessor' coro=<SupervisedTask._create_work.<locals>.wrapped() running at /home/pyde1/venv/pyde1/lib/python3.9/site-packages/pyDE1/supervise.py:131> wait_for=<Future pending cb=[BaseSelectorEventLoop._sock_read_done(11, handle=<Handle BaseS...events.py:259>)(), <TaskWakeupMethWrapper object at 0xffff9c086280>()] created at /usr/lib/python3.9/asyncio/base_events.py:424> cb=[SupervisedWork._start()] created at /home/pyde1/venv/pyde1/lib/python3.9/site-packages/pyDE1/supervise.py:137> took 0.122 seconds
2022-01-14 08:53:54,443 INFO [Controller] FlowSequencer: FlowSequencer subscriptions done
2022-01-14 08:53:54,889 INFO [InboundAPI] Inbound.HTTP: 657 200 "OK" - PATCH /scan HTTP/1.1 192.168.0.5
2022-01-14 08:53:56,096 INFO [DatabaseLogger] Database.Notifications: No rolling buffer for ScannerNotification
2022-01-14 08:53:59,792 INFO [DatabaseLogger] Database.Notifications: No rolling buffer for ScannerNotification
2022-01-14 08:54:00,243 WARNING [Controller] root.asyncio: Executing <Handle MessageBus._message_reader() created at /usr/lib/python3.9/asyncio/selector_events.py:259> took 0.280 seconds
2022-01-14 08:54:00,276 INFO [DatabaseLogger] Database.Notifications: No rolling buffer for ScannerNotification
2022-01-14 08:54:01,812 INFO [InboundAPI] Inbound.HTTP: Request: GET /scan/devices HTTP/1.1
2022-01-14 08:54:01,831 INFO [InboundAPI] Inbound.HTTP: 21 200 "OK" - GET /scan/devices HTTP/1.1 192.168.0.5
2022-01-14 08:54:06,117 INFO [InboundAPI] Inbound.HTTP: Request: PATCH /de1/id HTTP/1.1
2022-01-14 08:54:06,135 INFO [Controller] DE1: Address change requested for DE1 from None to E9:91:9E:3E:83:55
2022-01-14 08:54:06,136 INFO [Controller] DE1: Disconnecting from DE1
2022-01-14 08:54:06,137 INFO [Controller] DE1: Disconnecting from DE1, no client
2022-01-14 08:54:06,138 INFO [Controller] DE1: prepare_for_connection(wipe_address=True)
2022-01-14 08:54:06,153 INFO [Controller] DE1: Connecting to DE1 at E9:91:9E:3E:83:55
2022-01-14 08:54:08,073 WARNING [Controller] root.asyncio: Executing <Handle MessageBus._message_reader() created at /usr/lib/python3.9/asyncio/selector_events.py:259> took 0.570 seconds
2022-01-14 08:54:08,085 INFO [Controller] DE1: Connected to DE1 at E9:91:9E:3E:83:55
2022-01-14 08:54:08,099 INFO [Controller] DE1: initialize_after_connection()
2022-01-14 08:54:08,253 INFO [InboundAPI] Inbound.HTTP: 2140 200 "OK" - PATCH /de1/id HTTP/1.1 192.168.0.5
2022-01-14 08:54:09,485 INFO [Controller] DE1.CUUID.ReadFromMMR.Write: 0x00 (0): 0x80 0010 Cpu_Firmware_Build:  (0)
2022-01-14 08:54:10,172 INFO [Controller] DE1.CUUID.ReadFromMMR.Write: 0x03 (3): 0x80 0000 Hw_Config:  (0)
2022-01-14 08:54:10,309 INFO [Controller] DE1.CUUID.ReadFromMMR.Write: 0x11 (17): 0x80 3808 Fan_Threshold:  (0)
2022-01-14 08:54:10,434 INFO [Controller] DE1: Waiting for 23 responses
2022-01-14 08:54:11,018 INFO [InboundAPI] Inbound.HTTP: Request: PATCH /scale/id HTTP/1.1
2022-01-14 08:54:11,036 INFO [Controller] Scale.Processor: Request to replace scale with FF:FF:10:00:02:C0
2022-01-14 08:54:11,038 INFO [Controller] Scale.Processor: Disconnecting None
2022-01-14 08:54:11,083 INFO [Controller] root.Scale.DecentScale: Starting button press handler
2022-01-14 08:54:11,108 INFO [Controller] Scale: Connecting to DecentScale at FF:FF:10:00:02:C0
2022-01-14 08:54:11,370 WARNING [Controller] root.asyncio: Executing <Handle MessageBus._message_reader() created at /usr/lib/python3.9/asyncio/selector_events.py:259> took 0.123 seconds
2022-01-14 08:54:11,446 WARNING [Controller] DE1.C_API: Unexpected decode requested for 0x3820 0 0x0 (unimplemented MMR)
2022-01-14 08:54:11,453 WARNING [Controller] DE1.C_API: Unexpected decode requested for 0x3824 0 0x0 (unimplemented MMR)
2022-01-14 08:54:12,079 INFO [Controller] DE1: 23 responses received in 2.634 seconds
2022-01-14 08:54:12,084 INFO [Controller] DE1: Ready
2022-01-14 08:54:12,107 INFO [Controller] DE1.CUUID.Calibration: Acquired write/notify lock
2022-01-14 08:54:12,109 INFO [Controller] DE1.CUUID.Calibration.Write: Read CalFlow de1: 0 meas: 0
2022-01-14 08:54:12,664 INFO [Controller] DE1.CUUID.Calibration.Notify: Read CalFlow de1: 1.0 meas: 1.18631
2022-01-14 08:54:12,701 INFO [Controller] DE1.CUUID.Calibration: Acquired write/notify lock
2022-01-14 08:54:12,709 INFO [Controller] DE1.CUUID.Calibration.Write: ReadFactory CalFlow de1: 0 meas: 0
2022-01-14 08:54:13,335 INFO [Controller] DE1.CUUID.Calibration.Notify: ReadFactory CalFlow de1: 1.0 meas: 1.10001
2022-01-14 08:54:13,471 WARNING [Controller] root.asyncio: Executing <Handle MessageBus._message_reader() created at /usr/lib/python3.9/asyncio/selector_events.py:259> took 0.131 seconds
2022-01-14 08:54:13,496 INFO [Controller] DE1.CUUID.Calibration: Acquired write/notify lock
2022-01-14 08:54:13,498 INFO [Controller] DE1.CUUID.Calibration.Write: Read CalPressure de1: 0 meas: 0
2022-01-14 08:54:13,513 INFO [Controller] Scale: Connected to DecentScale at FF:FF:10:00:02:C0
2022-01-14 08:54:13,529 INFO [Controller] Scale: Scale.standard_initialization()
2022-01-14 08:54:13,556 INFO [InboundAPI] Inbound.HTTP: 2541 200 "OK" - PATCH /scale/id HTTP/1.1 192.168.0.5
2022-01-14 08:54:13,908 INFO [Controller] DE1.CUUID.Calibration.Notify: Read CalPressure de1: 1.0 meas: 1.21191
2022-01-14 08:54:13,921 INFO [Controller] DE1.CUUID.Calibration: Acquired write/notify lock
2022-01-14 08:54:13,922 INFO [Controller] DE1.CUUID.Calibration.Write: ReadFactory CalPressure de1: 0 meas: 0
2022-01-14 08:54:14,291 INFO [Controller] root.Scale.DecentScale: Display on request was not confirmed; may have failed (but hard to know on v1.0 firmware)
2022-01-14 08:54:14,292 INFO [Controller] root.Scale.DecentScale: Sending weight updates
2022-01-14 08:54:14,292 INFO [Controller] root.Scale.DecentScale: Sending button updates
2022-01-14 08:54:14,331 INFO [Controller] Scale: Loading scale-period estimate of 0.10528 from database
2022-01-14 08:54:14,341 INFO [Controller] Scale: Ready
2022-01-14 08:54:14,496 INFO [Controller] DE1.CUUID.Calibration.Notify: ReadFactory CalPressure de1: 1.0 meas: 1.07001
2022-01-14 08:54:14,509 INFO [Controller] DE1.CUUID.Calibration: Acquired write/notify lock
2022-01-14 08:54:14,511 INFO [Controller] DE1.CUUID.Calibration.Write: Read CalTemp de1: 0 meas: 0
2022-01-14 08:54:15,158 INFO [Controller] DE1.CUUID.Calibration.Notify: Read CalTemp de1: 0.0 meas: -1.99998
2022-01-14 08:54:15,181 INFO [Controller] DE1.CUUID.Calibration: Acquired write/notify lock
2022-01-14 08:54:15,186 INFO [Controller] DE1.CUUID.Calibration.Write: ReadFactory CalTemp de1: 0 meas: 0
2022-01-14 08:54:15,785 INFO [Controller] DE1.CUUID.Calibration.Notify: ReadFactory CalTemp de1: 0.0 meas: 0.0
2022-01-14 08:54:42,563 INFO [Controller] Scale: disconnect_callback: Disconnected from DecentScale at FF:FF:10:00:02:C0, willful_disconnect: False
2022-01-14 08:54:42,641 INFO [Controller] Scale: Will try reconnecting to DecentScale at FF:FF:10:00:02:C0
2022-01-14 08:54:42,647 INFO [Controller] Scale: Connecting to DecentScale at FF:FF:10:00:02:C0
2022-01-14 08:54:43,179 ERROR [Controller] Scale: Connection failed to DecentScale at FF:FF:10:00:02:C0
2022-01-14 08:54:43,199 INFO [Controller] Scale: Will try reconnecting to DecentScale at FF:FF:10:00:02:C0
2022-01-14 08:54:43,202 INFO [Controller] Scale: Connecting to DecentScale at FF:FF:10:00:02:C0
2022-01-14 08:54:45,169 INFO [Controller] DE1: disconnect_callback: Disconnected from DE1 at E9:91:9E:3E:83:55, willful_disconnect: False
2022-01-14 08:54:45,178 INFO [Controller] DE1: prepare_for_connection(wipe_address=False)
2022-01-14 08:54:45,214 INFO [Controller] DE1: Will try reconnecting to DE1 at E9:91:9E:3E:83:55
2022-01-14 08:54:45,230 INFO [Controller] DE1: Connecting to DE1 at E9:91:9E:3E:83:55
2022-01-14 08:54:46,538 WARNING [Controller] root.asyncio: Executing <Handle MessageBus._message_reader() created at /usr/lib/python3.9/asyncio/selector_events.py:259> took 0.303 seconds
2022-01-14 08:54:46,544 INFO [Controller] DE1: Connected to DE1 at E9:91:9E:3E:83:55
2022-01-14 08:54:46,550 INFO [Controller] DE1: initialize_after_connection()
2022-01-14 08:54:47,701 WARNING [Controller] DE1: Unexpected update period 200 from <pyDE1.de1.events.ShotSampleUpdate object at 0xffff97788be0>
2022-01-14 08:54:47,898 INFO [Controller] DE1.CUUID.ReadFromMMR.Write: 0x00 (0): 0x80 0010 Cpu_Firmware_Build:  (0)
2022-01-14 08:54:48,342 INFO [Controller] DE1.CUUID.ReadFromMMR.Write: 0x03 (3): 0x80 0000 Hw_Config:  (0)
2022-01-14 08:54:48,501 INFO [Controller] DE1.CUUID.ReadFromMMR.Write: 0x11 (17): 0x80 3808 Fan_Threshold:  (0)
2022-01-14 08:54:48,584 INFO [Controller] DE1: Waiting for 23 responses
2022-01-14 08:54:49,615 WARNING [Controller] DE1.C_API: Unexpected decode requested for 0x3820 0 0x0 (unimplemented MMR)
2022-01-14 08:54:49,623 WARNING [Controller] DE1.C_API: Unexpected decode requested for 0x3824 0 0x0 (unimplemented MMR)
2022-01-14 08:54:50,271 INFO [Controller] DE1: 23 responses received in 2.403 seconds
2022-01-14 08:54:50,279 INFO [Controller] DE1: Ready
2022-01-14 08:54:50,304 INFO [Controller] DE1.CUUID.Calibration: Acquired write/notify lock
2022-01-14 08:54:50,309 INFO [Controller] DE1.CUUID.Calibration.Write: Read CalFlow de1: 0 meas: 0
2022-01-14 08:54:50,851 INFO [Controller] DE1.CUUID.Calibration.Notify: Read CalFlow de1: 1.0 meas: 1.18631
2022-01-14 08:54:50,864 INFO [Controller] DE1.CUUID.Calibration: Acquired write/notify lock
2022-01-14 08:54:50,869 INFO [Controller] DE1.CUUID.Calibration.Write: ReadFactory CalFlow de1: 0 meas: 0
2022-01-14 08:54:51,471 INFO [Controller] DE1.CUUID.Calibration.Notify: ReadFactory CalFlow de1: 1.0 meas: 1.10001
2022-01-14 08:54:51,483 INFO [Controller] DE1.CUUID.Calibration: Acquired write/notify lock
2022-01-14 08:54:51,484 INFO [Controller] DE1.CUUID.Calibration.Write: Read CalPressure de1: 0 meas: 0
2022-01-14 08:54:52,112 INFO [Controller] DE1.CUUID.Calibration.Notify: Read CalPressure de1: 1.0 meas: 1.21191
2022-01-14 08:54:52,141 INFO [Controller] DE1.CUUID.Calibration: Acquired write/notify lock
2022-01-14 08:54:52,143 INFO [Controller] DE1.CUUID.Calibration.Write: ReadFactory CalPressure de1: 0 meas: 0
2022-01-14 08:54:52,716 INFO [Controller] DE1.CUUID.Calibration.Notify: ReadFactory CalPressure de1: 1.0 meas: 1.07001
2022-01-14 08:54:52,734 INFO [Controller] DE1.CUUID.Calibration: Acquired write/notify lock
2022-01-14 08:54:52,736 INFO [Controller] DE1.CUUID.Calibration.Write: Read CalTemp de1: 0 meas: 0
2022-01-14 08:54:53,370 INFO [Controller] DE1.CUUID.Calibration.Notify: Read CalTemp de1: 0.0 meas: -1.99998
2022-01-14 08:54:53,385 INFO [Controller] DE1.CUUID.Calibration: Acquired write/notify lock
2022-01-14 08:54:53,387 INFO [Controller] DE1.CUUID.Calibration.Write: ReadFactory CalTemp de1: 0 meas: 0
2022-01-14 08:54:53,699 ERROR [Controller] Scale: Connection failed to DecentScale at FF:FF:10:00:02:C0
2022-01-14 08:54:53,733 INFO [Controller] Scale: Will try reconnecting to DecentScale at FF:FF:10:00:02:C0
2022-01-14 08:54:53,739 INFO [Controller] Scale: Connecting to DecentScale at FF:FF:10:00:02:C0
2022-01-14 08:54:53,974 INFO [Controller] DE1.CUUID.Calibration.Notify: ReadFactory CalTemp de1: 0.0 meas: 0.0
2022-01-14 08:54:56,134 WARNING [Controller] root.asyncio: Executing <Handle MessageBus._message_reader() created at /usr/lib/python3.9/asyncio/selector_events.py:259> took 0.118 seconds
2022-01-14 08:54:56,143 INFO [Controller] Scale: Connected to DecentScale at FF:FF:10:00:02:C0
2022-01-14 08:54:56,151 INFO [Controller] Scale: Scale.standard_initialization()
2022-01-14 08:54:56,954 INFO [Controller] root.Scale.DecentScale: Display on request was not confirmed; may have failed (but hard to know on v1.0 firmware)
2022-01-14 08:54:56,955 INFO [Controller] root.Scale.DecentScale: Sending weight updates
2022-01-14 08:54:56,956 INFO [Controller] root.Scale.DecentScale: Sending button updates
2022-01-14 08:54:56,981 INFO [Controller] Scale: Loading scale-period estimate of 0.10528 from database
2022-01-14 08:54:56,990 INFO [Controller] Scale: Ready
2022-01-14 08:57:08,264 WARNING [Controller] root.asyncio: Executing <Handle MessageBus._message_reader() created at /usr/lib/python3.9/asyncio/selector_events.py:259> took 0.272 seconds

a112358132134 commented 2 years ago

There are a few DBus-related connection errors in bluez 5.62 that are apparently fixed in 5.63, including: https://github.com/bluez/bluez/commit/ebf2d7935690c00c7fd12768177e2023fc63c9fe

5.63 was released ~5 days ago, hence should hit Manjaro stable shortly. I'll retest once it's available.

EDIT: Forgot to mention I'm happy to close this ticket given you couldn't reproduce it. I'll raise another if I find any evidence to the contrary.

jeffsf commented 2 years ago

running the default bullseye bluez v5.55

Yes, v5.55

I'll avoid upgrading until at least 5.63, from the sound of it!

jeffsf / pyDE1

Request for independent test of scale disconnection behaviour #19