General Issue with external connection: Unexpected log entries "Message queue is empty. Assuming that the device is offline" since 14. June, reconnects while iOS app is active.
Closed this issue · 14 comments
Since yesterday 14th June 20123 we recognized friction in the logs and data visualisation outage after around one month of stable processing.
Install Prerequisites
We installed the docker compose version from the commandline including alertmanager reporting to Telegram on May 30th on a MacMini M1 under Monterey and used Docker Desktop just to monitor the install.
We run an Ecoflow Delta Pro under latest Firmware V1.0.1.49, | V0.1.0 (WLAN) (not updated during use of ecoflow_exporter)
Everything worked fine except short interruptions due to network related external issues (Restarts etc.)
We also recognized short outages of receiving messages in the night at almost the same time when the Internet connection is shortly interrupted by the Provider.
Current issue
Today we restarted the containers and for a short time everything went back to normal.
Then we received the "Message queue is empty. Assuming that the device is offline" messages again.
What we figured out is that the reporting from the Ecoflow server goes back to normal as long as a local iPhone with the Ecoflow app is actively communicating with the services. The Communication drops again when the app goes to background when closing the iPhone app screen (not the app) to the background.
This could be reproduced many times.
Composer Log Example:
### usual messages before the issues (there are more different ones, but I omit them for now)
2023-06-14 08:05:45 ecoflow_exporter | 2023-06-14 06:05:45,741 INFO Processing 15 event(s) from the message queue
2023-06-14 08:05:55 ecoflow_exporter | 2023-06-14 06:05:55,759 INFO Processing 15 event(s) from the message queue
### goes offline
2023-06-14 08:06:05 ecoflow_exporter | 2023-06-14 06:06:05,772 INFO Message queue is empty. Assuming that the device is offline
2023-06-14 08:06:15 ecoflow_exporter | 2023-06-14 06:06:15,780 INFO Message queue is empty. Assuming that the device is offline
2
### messages after container restart
2023-06-15 16:24:08 ecoflow_exporter | 2023-06-15 14:24:08,139 INFO Login to EcoFlow API https://api.ecoflow.com/auth/login
2023-06-15 16:24:08 ecoflow_exporter | 2023-06-15 14:24:08,308 INFO Successfully logged in: [user]
2023-06-15 16:24:08 ecoflow_exporter | 2023-06-15 14:24:08,308 INFO Requesting IoT MQTT credentials https://api.ecoflow.com/iot-auth/app/certification
2023-06-15 16:24:08 ecoflow_exporter | 2023-06-15 14:24:08,423 INFO Successfully extracted account: app-******removed******
2023-06-15 16:24:08 ecoflow_exporter | 2023-06-15 14:24:08,443 INFO Connecting to MQTT Broker mqtt-e.ecoflow.com:8883 using client id ANDROID_******removed******
2023-06-15 16:24:08 ecoflow_exporter | 2023-06-15 14:24:08,682 INFO Subscribed to MQTT topic /app/device/property/******Ser#removed******
2023-06-15 16:24:18 ecoflow_exporter | 2023-06-15 14:24:18,635 INFO Processing 15 event(s) from the message queue
2023-06-15 16:24:18 ecoflow_exporter | 2023-06-15 14:24:18,636 INFO Created new metric from payload key pd.iconWifiMode -> ecoflow_pd_icon_wifi_mode
...
## Note: repeated many times for every property
...
2023-06-15 16:24:18 ecoflow_exporter | 2023-06-15 14:24:18,645 INFO Created new metric from payload key mppt.chgState -> ecoflow_mppt_chg_state
2023-06-15 16:24:28 ecoflow_exporter | 2023-06-15 14:24:28,653 INFO Processing 20 event(s) from the message queue
## now starts processing every 30 seconds 19 times written to the log and then goes offline
### goes online after iOS Device goes online
- 2023-06-15 11:55:52 ecoflow_exporter | 2023-06-15 09:55:52,441 INFO Processing 15 event(s) from the message queue'
2023-06-15 11:56:22 ecoflow_exporter | 2023-06-15 09:56:22,490 INFO Processing 18 event(s) from the message queue
2023-06-15 11:56:32 ecoflow_exporter | 2023-06-15 09:56:32,514 INFO Processing 16 event(s) from the message queue
2023-06-15 11:56:42 ecoflow_exporter | 2023-06-15 09:56:42,528 INFO Processing 15 event(s) from the message queue
2023-06-15 11:56:52 ecoflow_exporter | 2023-06-15 09:56:52,544 INFO Processing 10 event(s) from the message queue
### repeated after iOS goes offline until iOS Device goes online again
- 2023-06-15 15:45:28 ecoflow_exporter | 2023-06-15 13:45:28,007 INFO Message queue is empty. Assuming that the device is offline
### intermediate Grafana log messages
- 2023-06-15 15:49:27 grafana | logger=cleanup t=2023-06-15T13:49:27.38569113Z level=info msg="Completed cleanup jobs" duration=15.996333ms
2023-06-15 15:49:27 grafana | logger=grafana.update.checker t=2023-06-15T13:49:27.579195171Z level=info msg="Update check succeeded" duration=102.637208ms
2023-06-15 15:49:27 grafana | logger=plugins.update.checker t=2023-06-15T13:49:27.68191263Z level=info msg="Update check succeeded" duration=151.199709ms
### intermediate Prometheus log messages
2023-06-15 17:00:03 prometheus | ts=2023-06-15T15:00:03.132Z caller=compact.go:523 level=info component=tsdb msg="write block" mint=1686830400000 maxt=1686837600000 ulid=******removed****** duration=72.176208ms
2023-06-15 17:00:03 prometheus | ts=2023-06-15T15:00:03.137Z caller=head.go:1286 level=info component=tsdb msg="Head GC completed" caller=truncateMemory duration=1.818208ms
2023-06-15 17:00:03 prometheus | ts=2023-06-15T15:00:03.141Z caller=checkpoint.go:100 level=info component=tsdb msg="Creating checkpoint" from_segment=189 to_segment=191 mint=1686837600000
2023-06-15 17:00:03 prometheus | ts=2023-06-15T15:00:03.235Z caller=head.go:1254 level=info component=tsdb msg="WAL checkpoint complete" first=189 last=191 duration=93.9965ms
Telegram reports
We get these alerts as well as follows:
‼️ [FIRING:1] EcoFlow is offline
Description: Device [[Delta Pro]] has disappeared from the network⚠️ [FIRING:1] EcoFlow detects power outage
Description: Device [[Delta Pro]] detects power outage- ✅ [RESOLVED] EcoFlow is offline
Description: Device [[Delta Pro]] has disappeared from the network - ✅ [RESOLVED] EcoFlow detects power outage
Description: Device [[Delta Pro]] detects power outage ⚠️ [FIRING:1] EcoFlow detects power outage
Description: Device [[Delta Pro]] detects power outage- ✅ [RESOLVED] EcoFlow detects power outage
Description: Device [[Delta Pro]] detects power outage ‼️ [FIRING:1] EcoFlow is offline
Description: Device [[Delta Pro]] has disappeared from the network⚠️ [FIRING:1] EcoFlow detects power outage
Description: Device [[Delta Pro]] detects power outage- ✅ [RESOLVED] EcoFlow is offline
Description: Device [[Delta Pro]] has disappeared from the network - ✅ [RESOLVED] EcoFlow detects power outage
Description: Device [[Delta Pro]] detects power outage
the log messages repeat in the sequence like the default in prometheus.yml:
global:
scrape_interval: 10s # Set the scrape interval to every 10 seconds. Default is every 1 minute.
scrape_timeout: 10s
evaluation_interval: 10s # Evaluate rules every 10 seconds. The default is every 1 minute.
Also the Android App can enable logging again. I have the same issue... only in the periods the app runs there is data.
Hello, the log "Message queue is empty" indicates that there are no messages currently present on the Ecoflow MQTT server.
I don't experience any problems with my personal DELTA 2 and its Wi-Fi Firmware version 1.0.3.18. However, I'm cautious about updating to the latest version because it might introduce an issue
OR
EcoFlow has made changes to their messaging system, where MQTT messages are now sent only when there is an active app connection. Probably, they have implemented a specific API call to enable or disable the sending of MQTT messages.
In order to address or emulate the functionality of the official app, it is necessary to conduct research and understand the specific changes made by EcoFlow.
Same issue for hassio: tolwi/hassio-ecoflow-cloud#57
Same issue for hassio: tolwi/hassio-ecoflow-cloud#57
In general, the solution is to reconnect mqtt client after detecting that the data topic "is empty".
Tricky point is to make an assumption whether the device is online or not in order not to reconnect infinitely when the device is offline.
At the moment, I've simply rebooted the exporter without proceeding to launch the official app :)
At the moment, I've simply rebooted the exporter without proceeding to launch the official app :)
This works for me. If I open the app and then close it - message errors appear. Reboot of the exporter fixes it.
So, if I understand this correctly, a hand-wave-y summary would be that it appears the App (iOS/Android) is clearing the MQTT queue of messages related to the device, and as a result the exporter experiences this issue (as no messages is presumed to be that the device is offline).
Is this a fair assessment of the issue?
@tomswartz07 I don't think so. The reason: even if the app is fully closed or the only connected phone is turned off the exporter still reports no messages for days... until the exporter is restarted - then the messages reappear.
it looks like "ecoflow" is tracking MQTT clients and after the app is closed, they assume that no consumers left, causing them to stop sending messages. This is why reconnecting helps to restore the data flow.
Is it just me or is someone elses instance not properly reconnecting too? I had to leave my systemd restart script in place.
Bought a brand new River 2 and the message queue is also empty even when restarting the script multiple times and/or opening/closing the app.
App shows these versions:
3.1.3.02 (01-07-2024) and WiFi Version 2.1.5.63 (01-07-2024)
This is probably a different problem. As the error from this report only appeared when the app was closed...
Do you get data in the app? Is the river connected via Wi-Fi and connected to the online service?
same here (on River Pro) #67
Exporter restart not helping much (just for a 30s) using 2.0.1 image