Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

availability=offline after 5 minutes #4261

Closed
Erelen-Laiquendi opened this issue Sep 3, 2020 · 22 comments
Closed

availability=offline after 5 minutes #4261

Erelen-Laiquendi opened this issue Sep 3, 2020 · 22 comments
Labels
stale Stale issues

Comments

@Erelen-Laiquendi
Copy link

Erelen-Laiquendi commented Sep 3, 2020

Bug Report

What happened

When z2m start, it publish availability=online for all devices:

info  2020-09-03 23:38:11: MQTT publish: topic 'zigbee2mqtt/Room Climate/availability', payload 'online'
info  2020-09-03 23:38:11: MQTT publish: topic 'zigbee2mqtt/Kitchen Light/availability', payload 'online'
info  2020-09-03 23:38:11: MQTT publish: topic 'zigbee2mqtt/Kitchen Motion/availability', payload 'online'
info  2020-09-03 23:38:11: MQTT publish: topic 'zigbee2mqtt/Balcony Illuminance/availability', payload 'online'
info  2020-09-03 23:38:11: MQTT publish: topic 'zigbee2mqtt/Bathroom Climate/availability', payload 'online'
...

But exactly after 5 minutes, it publish offline for near all barrety powered devices:

info  2020-09-03 23:43:11: MQTT publish: topic 'zigbee2mqtt/Room Climate/availability', payload 'offline'
info  2020-09-03 23:43:11: MQTT publish: topic 'zigbee2mqtt/Kitchen Motion/availability', payload 'offline'
info  2020-09-03 23:43:11: MQTT publish: topic 'zigbee2mqtt/Room2 Workstation Motion/availability', payload 'offline'
info  2020-09-03 23:43:11: MQTT publish: topic 'zigbee2mqtt/Home Door/availability', payload 'offline'
info  2020-09-03 23:43:11: MQTT publish: topic 'zigbee2mqtt/Room2 Climate/availability', payload 'offline'
...

I know about Availability - Non-pingable devices. But why dows this happen in 5 minutes after every z2m restart? How I can prevent this?

What did you expect to happen

Battery devices become unavailable, when no message has been received from them for 25 hours. But not every z2m restart.

How to reproduce it (minimal and precise)

Set availability_timeout and restart z2m, I think.

Debug Info

Zigbee2MQTT version: 1.14.4 (HA addon)
Adapter hardware: cc2530 (gban)
Adapter firmware version: CC2530_SOURCE_ROUTING_20190619

@Koenkk
Copy link
Owner

Koenkk commented Sep 4, 2020

Can you provide your configuration.yaml?

@Erelen-Laiquendi
Copy link
Author

data_path: /share/zigbee2mqtt
devices: devices.yaml
groups: groups.yaml
homeassistant: true
permit_join: false
mqtt:
  base_topic: zigbee2mqtt
  server: 'mqtt://core-mosquitto'
  user: zigbee2mqtt
  password: '!secret addon_mqtt_zigbee_pass'
serial:
  port: >-
    /dev/serial/by-id/usb-Silicon_Labs_CP2102_USB_to_UART_Bridge_Controller_0001-if00-port0
advanced:
  rtscts: false
  pan_id: '!secret addon_zigbee2mqtt_pan_id'
  channel: '!secret addon_zigbee2mqtt_channel'
  network_key: []
  network_key_string: '!secret addon_zigbee2mqtt_network_key'
  availability_blacklist: []
  availability_timeout: 300
  report: true
ban: []
whitelist: []
queue: {}
socat:
  enabled: false
  master: 'pty,raw,echo=0,link=/dev/ttyZ2M,mode=777'
  slave: 'tcp-listen:8485,keepalive,nodelay,reuseaddr,keepidle=1,keepintvl=1,keepcnt=5'
  restartdelay: 1
  initialdelay: 1
  options: '-d -d'
  log: false

@Koenkk
Copy link
Owner

Koenkk commented Sep 5, 2020

  • Do they come available again when they are sending a message?
  • Can you share your data/database.db, what are the lastSeen properties of the unavailable devices, this shouldn't be more than 25 hours ago.

@Erelen-Laiquendi
Copy link
Author

Erelen-Laiquendi commented Sep 5, 2020

Yes, all devices come available after first message.

In database.db all lastSeen is from old (several days) to very old (more than 2 monthes - looks like timestamp of joining).
In what moment lastSeen in database.db is updating?

https://files.melda.ru/hidden/z2m/database_2020-09-05_23-49.db
(all this devices, except 0x00158d00054f522b, is really works every day)

@Koenkk
Copy link
Owner

Koenkk commented Sep 5, 2020

When a message is received from a device and you stop Zigbee2MQTT, is the lastSeen for that device updated? (to almost the current time)

@Erelen-Laiquendi
Copy link
Author

Erelen-Laiquendi commented Sep 5, 2020

  • Near midnight (GMT+3) I restarted z2m (just after dumping database.db - see link in in my previous comment) .
  • After 5 minutes all battery devices, as usual become offline
  • In next hour (until now) all battery device one by one send mesaages and become online
  • Now, I stop z2m and get actual database.db

Current database.db is binary equal to 1 hour old database.db (from link in my previous comment). With all old lastSeen - up to several monthes old for all perfectly wokring devices.

@Erelen-Laiquendi
Copy link
Author

Erelen-Laiquendi commented Sep 5, 2020

1:12 - stop z2m and make database.db dump (lastSeen in this dump, as earlier, is very old)
1:19 - start z2m
1:24 - battery devices become offline
1:24 - 2:12 - all devices send messages and become online
2:12 - 2:14 - join new device (0x00158d0002b810ab)
2:15 - send 'zigbee2mqtt/bridge/config/devices/get' request - in reply all devices has good, actual lastSeen (not more than 1 hour old).
2:17 - stop z2m and make new database.db dump

You can view diff between database.db dumps.
In last dump:

  1. some devices changed their attributes.
  2. there is one new device
  3. absolutely all lastSeen is equal to first dump :(

Full z2m log of this experiment.

@Koenkk
Copy link
Owner

Koenkk commented Sep 7, 2020

In /opt/zigbee2mqtt/node_modules/zigbee-herdsman/dist/controller/model/devices.js can you change:

    updateLastSeen() {
        this._lastSeen = Date.now();
    }

to

    updateLastSeen() {
        this._lastSeen = Date.now();
       console.log("Change lastSeen of " + this.ieeeAddr + " to " + this._lastSeen);
    }

Do the logged lastSeen matched the one in data/database.db after stopping Zigbee2MQTT?

@Erelen-Laiquendi
Copy link
Author

Erelen-Laiquendi commented Sep 8, 2020

It's look like everything is ok in herdsman, but z2m addon do not update database.db at all, when stopping addon from HA.

Experiment:

z2m stopped, "last modified" timestamp of database.db - 0:05, and there is many very old lastSeen in it.

0:16 - run z2m by HA supervisor web-interface.
database.db last_mod timestamp is updated to 0:16, but content is same to database.db-0:05

0:16-0:44 - near all devices send message and become online
database.db last_mod is still 0:16, and content is same

0:47 - go into addon_7ad98f9c_zigbee2mqtt container and kill "node index.js" process
z2m automatically restarts, database.db updates: last_mod is 0:47 and (!) it has new, actual lastSeen (within last 30 minutes) for all devices (first time at all - there is no 2 month old lastSeen in database.db).

0:47-1:12 - near all devices send message (and zigbee2mqtt/bridge/config/devices/get reports actual lastSeen)
database.db last_mod is still 0:47, and content is same

1:13 - stop z2m by HA supervisor web-interface
database.db last_mod is still 0:47, and content is same - no updates from 0:47 (and all lastSeen in 0:16-0:44, but not in 0:47-1:12).

@Koenkk
Copy link
Owner

Koenkk commented Sep 9, 2020

Could you provide the log from the hassio page when stopping the zigbee2mqtt addon. Based on your report I conclude that the database is not updated when Zigbee2MQTT stops (which should be the case)

@Erelen-Laiquendi
Copy link
Author

20-09-09 17:41:46 INFO (SyncWorker_1) [supervisor.docker.interface] Stop addon_7ad98f9c_zigbee2mqtt application
20-09-09 17:41:50 INFO (SyncWorker_1) [supervisor.docker.interface] Clean addon_7ad98f9c_zigbee2mqtt application

That's all :(

@Koenkk
Copy link
Owner

Koenkk commented Sep 9, 2020

With #4261 (comment) , do you see the Change lastSeen of message in the log when a device sends something? If so I can add more so we can debug further.

@Erelen-Laiquendi
Copy link
Author

Yes, I see Change lastSeen of.

My way to do it it HA OS: root, go into z2m docker container, change file, and restart z2m by killing node index.js process. If I restart addon - container re-created with release files (not my modified). And on this way I see, that on "my" restart (killing node index.js process) database.db updates. But if I stop addon - no.

If your know better way to modify z2m addon on HA OS - please, tell me :)

@Koenkk
Copy link
Owner

Koenkk commented Sep 11, 2020

Good, in /opt/zigbee2mqtt/node_modules/zigbee-herdsman/dist/controller/controller.js can you change the stop function to:

stop() {
    return __awaiter(this, void 0, void 0, function* () {
        console.log("START STOP");
        for (const device of model_1.Device.all()) {
            device.save();
        }
        for (const group of group_1.default.all()) {
            group.save();
        }
        // Unregister adapter events
        this.adapter.removeAllListeners(adapter_1.Events.Events.deviceJoined);
        this.adapter.removeAllListeners(adapter_1.Events.Events.zclData);
        this.adapter.removeAllListeners(adapter_1.Events.Events.rawData);
        this.adapter.removeAllListeners(adapter_1.Events.Events.disconnected);
        this.adapter.removeAllListeners(adapter_1.Events.Events.deviceAnnounce);
        this.adapter.removeAllListeners(adapter_1.Events.Events.deviceLeave);
        yield this.permitJoin(false);
        clearInterval(this.backupTimer);
        yield this.backup();
        yield this.adapter.stop();
        console.log("FINSIHED STOP");
    });
}

@Erelen-Laiquendi
Copy link
Author

Docker log, when stopping addon:

...
Zigbee2MQTT:info  2020-09-12 01:38:27: MQTT publish: topic 'zigbee2mqtt/Bathroom Lights ZigBee', payload '{"brightness":254,"color":{"hue":112,"saturation":100,"x":0.2126,"y":0.6365},"color_temp":370,"state":"ON"}'
Zigbee2MQTT:info  2020-09-12 01:38:27: MQTT publish: topic 'zigbee2mqtt/Bathroom Light 1', payload '{"brightness":254,"color":{"hue":112,"saturation":100,"x":0.2126,"y":0.6365},"color_temp":370,"linkquality":39,"state":"ON"}'
[cont-finish.d] executing container finish scripts...
[cont-finish.d] done.
[s6-finish] waiting for services.
Zigbee2MQTT:info  2020-09-12 01:38:27: MQTT publish: topic 'zigbee2mqtt/Mosquito Killer', payload '{"current":0.01,"linkquality":171,"power":0,"state":"OFF","voltage":243.5}'
[s6-finish] sending all processes the TERM signal.

Docker log, when killing node index.js:

...
Zigbee2MQTT:info  2020-09-12 01:36:32: MQTT publish: topic 'zigbee2mqtt/Bathroom Light 3/availability', payload 'offline'
Zigbee2MQTT:info  2020-09-12 01:36:32: MQTT publish: topic 'zigbee2mqtt/Bathroom Light 4/availability', payload 'offline'
Zigbee2MQTT:info  2020-09-12 01:36:32: MQTT publish: topic 'zigbee2mqtt/bridge/state', payload 'offline'
Zigbee2MQTT:info  2020-09-12 01:36:32: Disconnecting from MQTT server
START STOP
FINSIHED STOP
Zigbee2MQTT:info  2020-09-12 01:36:32: zigbee-herdsman stopped
2020-09-12T01:36:33: PM2 log: App [npm:0] exited with code [0] via signal [SIGINT]
2020-09-12T01:36:33: PM2 log: App [npm:0] starting in -fork mode-
2020-09-12T01:36:33: PM2 log: App [npm:0] online
> zigbee2mqtt@1.14.4 start /zigbee2mqtt-1.14.4
> node index.js
Zigbee2MQTT:info  2020-09-12 01:36:41: Logging to console and directory: '/share/zigbee2mqtt/log/2020-09-12.01-36-41' filename: log.txt
Zigbee2MQTT:info  2020-09-12 01:36:43: Starting Zigbee2MQTT version 1.14.4 (commit #unknown)
Zigbee2MQTT:info  2020-09-12 01:36:43: Starting zigbee-herdsman...
Zigbee2MQTT:info  2020-09-12 01:36:46: zigbee-herdsman started
Zigbee2MQTT:info  2020-09-12 01:36:46: Coordinator firmware version: '{"meta":{"maintrel":3,"majorrel":2,"minorrel":6,"product":0,"revision":20190619,"transportrev":2},"type":"zStack12"}'
Zigbee2MQTT:info  2020-09-12 01:36:46: Currently 45 devices are joined:
...

@Koenkk
Copy link
Owner

Koenkk commented Sep 12, 2020

So it seems we found our issue, when stopping the addon zigbee2mqtt is immediately terminated.

Can you add some logging to /opt/index.js:

function handleQuit() {
    console.log('HANDLE QUIT!!');
    if (!stopping) {
        stopping = true;
        controller.stop();
    }
}

@Erelen-Laiquendi
Copy link
Author

Docker log, when stopping addon:

...
Zigbee2MQTT:info  2020-09-13 23:18:03: MQTT publish: topic 'zigbee2mqtt/Mosquito Killer', payload '{"current":0.01,"linkquality":179,"power":0,"state":"OFF","voltage":242}'
Zigbee2MQTT:info  2020-09-13 23:18:03: MQTT publish: topic 'zigbee2mqtt/BlitzWolf Plug', payload '{"current":0.04,"energy":1.01,"linkquality":65,"power":4,"state":"ON","voltage":249}'
[cont-finish.d] executing container finish scripts...
[cont-finish.d] done.
[s6-finish] waiting for services.
[s6-finish] sending all processes the TERM signal.

Docker log, when killing node index.js:

...
Zigbee2MQTT:info  2020-09-13 23:21:54: MQTT publish: topic 'zigbee2mqtt/Mosquito Killer', payload '{"current":0.01,"linkquality":182,"power":0,"state":"OFF","voltage":241.9}'
Zigbee2MQTT:info  2020-09-13 23:21:54: MQTT publish: topic 'zigbee2mqtt/BlitzWolf Plug', payload '{"current":0.04,"energy":1.01,"linkquality":67,"power":4,"state":"ON","voltage":250}'
HANDLE QUIT!!
Zigbee2MQTT:info  2020-09-13 23:21:56: MQTT publish: topic 'zigbee2mqtt/Room Climate/availability', payload 'offline'
Zigbee2MQTT:info  2020-09-13 23:21:56: MQTT publish: topic 'zigbee2mqtt/Kitchen Light/availability', payload 'offline'
<...all devices to offline...>
Zigbee2MQTT:info  2020-09-13 23:21:56: MQTT publish: topic 'zigbee2mqtt/Bathroom Light 4/availability', payload 'offline'
Zigbee2MQTT:info  2020-09-13 23:21:56: MQTT publish: topic 'zigbee2mqtt/bridge/state', payload 'offline'
Zigbee2MQTT:info  2020-09-13 23:21:56: Disconnecting from MQTT server
Zigbee2MQTT:info  2020-09-13 23:21:57: zigbee-herdsman stopped
2020-09-13T23:21:57: PM2 log: App [npm:0] exited with code [0] via signal [SIGINT]
2020-09-13T23:21:57: PM2 log: App [npm:0] starting in -fork mode-
2020-09-13T23:21:57: PM2 log: App [npm:0] online
> zigbee2mqtt@1.14.4 start /zigbee2mqtt-1.14.4
> node index.js
Zigbee2MQTT:info  2020-09-13 23:22:03: Logging to console and directory: '/share/zigbee2mqtt/log/2020-09-13.23-22-03' filename: log.txt
Zigbee2MQTT:info  2020-09-13 23:22:05: Starting Zigbee2MQTT version 1.14.4 (commit #unknown)
Zigbee2MQTT:info  2020-09-13 23:22:05: Starting zigbee-herdsman...
...

@Koenkk
Copy link
Owner

Koenkk commented Sep 14, 2020

@danielwelch it seems that with npm start the SIGTERM signal is not properly forwarded, reading https://lisk.io/blog/development/why-we-stopped-using-npm-start-child-processes suggest to use node directly. Can you try changing https://github.com/danielwelch/hassio-zigbee2mqtt/blob/727077936583dd7c05b9a8bc4e00eabf832d35ad/zigbee2mqtt/run.sh#L47 to ZIGBEE2MQTT_DATA="$DATA_PATH" pm2-runtime start node -- index.js ?

@Erelen-Laiquendi
Copy link
Author

Erelen-Laiquendi commented Sep 14, 2020

@Koenkk, but what about any unexpected z2m stop? (any RPi crash: by power or any other)
Maybe it's a good practice to save database.db with actual lastSeen every 6-12 hours?

Koenkk added a commit to Koenkk/zigbee-herdsman that referenced this issue Sep 15, 2020
@Koenkk
Copy link
Owner

Koenkk commented Sep 15, 2020

Good point! Will now save every hour which should solve your problem.

Changes will be available in the latest dev branch in a few hours (https://www.zigbee2mqtt.io/how_tos/how-to-switch-to-dev-branch.html)

@Erelen-Laiquendi
Copy link
Author

I can confirm: edge addon now saves database.db every hour with actual lastSeen.

@github-actions
Copy link
Contributor

This issue is stale because it has been open 30 days with no activity. Remove stale label or comment or this will be closed in 7 days

@github-actions github-actions bot added the stale Stale issues label Oct 17, 2020
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
stale Stale issues
Projects
None yet
Development

No branches or pull requests

2 participants