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

MaxListenersExceededWarning #9822

Closed
okastl opened this issue Nov 24, 2021 · 25 comments
Closed

MaxListenersExceededWarning #9822

okastl opened this issue Nov 24, 2021 · 25 comments
Labels
problem Something isn't working

Comments

@okastl
Copy link

okastl commented Nov 24, 2021

What happened

If availability check is enabled with a lot of devices, the following warning appears in the log:
(node:23992) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 1001 drain listeners added to [Socket]. Use emitter.setMaxListeners() to increase limit
I am not sure, if this really is a problem, but it sounds scary.

What did you expect to happen

No warning.

How to reproduce it (minimal and precise)

This might be difficult. You need a zigbee network with a lot of devices. Enable availability check. Mine was set to "object" 15/1500 minutes.

Debug info

Zigbee2MQTT version: 1.22.0-dev commit: 3bfc7f3
Adapter hardware: CC26X2R1 (slaesh)
Adapter firmware version: 20210708

@okastl okastl added the problem Something isn't working label Nov 24, 2021
@Koenkk
Copy link
Owner

Koenkk commented Nov 24, 2021

How many devices do you have on your network?

@okastl
Copy link
Author

okastl commented Nov 24, 2021

How many devices do you have on your network?

119

@sjorge
Copy link
Sponsor Contributor

sjorge commented Nov 24, 2021

How many devices do you have on your network?

119

How maybe of those are routers vs end devices?

@okastl
Copy link
Author

okastl commented Nov 24, 2021

How maybe of those are routers vs end devices?

34 end devices
85 routers

@sjorge
Copy link
Sponsor Contributor

sjorge commented Nov 24, 2021

I'm at 44 end, 37 routers I wonder where the cut off is.

@Koenkk
Copy link
Owner

Koenkk commented Nov 24, 2021

Is there some more debug logging around this? I currently cannot find where the amount of listeners increases with the amount of devices? (amount of listeners should be the same on a network with just 1 device)

@okastl
Copy link
Author

okastl commented Nov 25, 2021

Is there some more debug logging around this? I currently cannot find where the amount of listeners increases with the amount of devices? (amount of listeners should be the same on a network with just 1 device)

It happens very soon after startup basically

�[32mZigbee2MQTT:info �[39m 2021-11-24 14:51:01: Connected to MQTT server
�[32mZigbee2MQTT:info �[39m 2021-11-24 14:51:01: MQTT publish: topic 'zigbee2mqtt/bridge/state', payload 'online'

is then followed by many, many Received MQTT message. Probably "retained" topics present in the MQTT broker, like this:

�[34mZigbee2MQTT:debug�[39m 2021-11-24 14:51:05: Received MQTT message on 'zigbee2mqtt/Galerie1' with data '{"brightness":100,"color_mode":"color_temp","color_temp":400,"last_seen":1637761781656,"linkquality":51,"state":"OFF","update":{"state":"idle"},"update_available":false}'
�[34mZigbee2MQTT:debug�[39m 2021-11-24 14:51:05: Received MQTT message on 'zigbee2mqtt/Galerie1/availability' with data 'online'
�[34mZigbee2MQTT:debug�[39m 2021-11-24 14:51:05: Received MQTT message on 'zigbee2mqtt/Galerie2' with data '{"brightness":100,"color_mode":"color_temp","color_temp":400,"last_seen":1637761781678,"linkquality":87,"state":"OFF","update":{"state":"idle"},"update_available":false}'
�[34mZigbee2MQTT:debug�[39m 2021-11-24 14:51:05: Received MQTT message on 'zigbee2mqtt/Galerie2/availability' with data 'online'
�[34mZigbee2MQTT:debug�[39m 2021-11-24 14:51:05: Received MQTT message on 'zigbee2mqtt/Galerie3' with data '{"brightness":100,"color_mode":"color_temp","color_temp":400,"last_seen":1637761781079,"linkquality":87,"state":"OFF","update":{"state":"idle"},"update_available":false}'
�[34mZigbee2MQTT:debug�[39m 2021-11-24 14:51:05: Received MQTT message on 'zigbee2mqtt/Galerie3/availability' with data 'online'

Then follows the MaxListenersExceededWarning.

I'll attach an excerpt from the log, maybe you see more.

log1.zip

Koenkk added a commit that referenced this issue Nov 25, 2021
@Koenkk
Copy link
Owner

Koenkk commented Nov 25, 2021

Could you check if the issue is fixed now?

Changes will be available in the dev branch in a few hours from now. (https://www.zigbee2mqtt.io/advanced/more/switch-to-dev-branch.html)

@okastl
Copy link
Author

okastl commented Nov 25, 2021

Could you check if the issue is fixed now?

Unfortunately, no.:
(node:17603) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 1001 drain listeners added to [Socket]. Use emitter.setMaxListeners() to increase limit

I did some more testing, and the message does even appear, if I disable availability check, so it seems to be unrelated to availability.

I used 1.22.0-dev commit: 51321af, which should include the change.

@Koenkk
Copy link
Owner

Koenkk commented Nov 26, 2021

Is it fixed when adding:

advanced:
  legacy_api: false

to your configuration.yaml?

@okastl
Copy link
Author

okastl commented Nov 26, 2021

Is it fixed when adding:

advanced:
  legacy_api: false

to your configuration.yaml?

No, legacy_api is already set to false. Here are my advanced settings (without network key / pan id), maybe this is helpful:

advanced:
  homeassistant_legacy_entity_attributes: false
  homeassistant_legacy_triggers: false
  legacy_api: false
  last_seen: epoch
  ikea_ota_use_test_url: false
  channel: 25
  cache_state: true
  cache_state_persistent: true
  cache_state_send_on_startup: true
  log_level: debug
  log_directory: data/log/%TIMESTAMP%
  log_file: log.txt
  log_rotation: true
  log_output:
    - console
    - file
  log_symlink_current: true
  rtscts: false
  log_syslog:
    app_name: Zigbee2MQTT
    eol: /n
    host: localhost
    localhost: localhost
    path: /dev/log
    pid: process.pid
    port: 123
    protocol: tcp4
    type: '5424'
  adapter_delay: 0

@w3host
Copy link

w3host commented Nov 26, 2021

I have same warning message at every zigbee2mqtt restart:

npm[20594]: (node:20594) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 1001 drain listeners added to [Socket]. Use emitter.setMaxListeners() to increase limit

111 device
21 end devices
90 routers

availability check: disabled
Zigbee2MQTT version: 1.22.0
Adapter hardware: CC26X2R (Electrolama zzh!)
Adapter firmware version: 20210708

@Koenkk
Copy link
Owner

Koenkk commented Nov 27, 2021

@okastl could you share me your data/database.db and configuration.yaml so that I can reproduce the issue locally?

Koenkk added a commit that referenced this issue Nov 27, 2021
@okastl
Copy link
Author

okastl commented Nov 27, 2021

@okastl could you share me your data/database.db and configuration.yaml so that I can reproduce the issue locally?

Sure. What are the security risks, if I remove network key, pan_id and ext_pan_id and post it here?

@Koenkk
Copy link
Owner

Koenkk commented Nov 28, 2021

You can randomise the networkkey, and panids.

@okastl
Copy link
Author

okastl commented Nov 28, 2021

You can randomise the networkkey, and panids.

Done. I hope, it helps.
I have added extensions & converters, in case they are causing trouble.

@Koenkk
Copy link
Owner

Koenkk commented Nov 28, 2021

For some reason I do not get the error, found this post https://stackoverflow.com/a/55983212 which should help us to determine which event listener throws this error.

Could you add process.on('warning', e => console.warn(e.stack)); as the first line for index.js(https://github.com/Koenkk/zigbee2mqtt/blob/master/index.js) and provide me the logging again?

@okastl
Copy link
Author

okastl commented Nov 28, 2021

I believe this is, what you want:

�[34mZigbee2MQTT:debug�[39m 2021-11-28 21:58:51: Received MQTT message on 'zigbee2mqtt/LaraKellerDecke2/availability' with data 'online'
(node:23154) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 1001 drain listeners added to [Socket]. Use emitter.setMaxListeners() to increase limit
(Use `node --trace-warnings ...` to show where the warning was created)
MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 1001 drain listeners added to [Socket]. Use emitter.setMaxListeners() to increase limit
    at _addListener (events.js:475:17)
    at Socket.addListener (events.js:497:10)
    at Socket.Readable.on (internal/streams/readable.js:853:35)
    at Socket.once (events.js:541:8)
    at sendPacket (/opt/zigbee2mqtt/node_modules/mqtt/lib/client.js:100:19)
    at MqttClient._sendPacket (/opt/zigbee2mqtt/node_modules/mqtt/lib/client.js:1069:7)
    at MqttClient.publish (/opt/zigbee2mqtt/node_modules/mqtt/lib/client.js:542:14)
    at /opt/zigbee2mqtt/lib/mqtt.ts:151:25
    at new Promise (<anonymous>)
    at MQTT.publish (/opt/zigbee2mqtt/lib/mqtt.ts:150:16)
2021-11-28T20:58:51.190Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,5,69,196,88,121,1,18,31,169]
2021-11-28T20:58:51.191Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,5,69,196,88,121,1,18,31,169]
2021-11-28T20:58:51.191Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 5 - 2 - 5 - 196 - [88,121,1,18,31] - 169
2021-11-28T20:58:51.192Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- ZDO - srcRtgInd - {"dstaddr":31064,"relaycount":1,"relaylist":[7954]}
2021-11-28T20:58:51.192Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext []

Koenkk added a commit that referenced this issue Nov 29, 2021
@Koenkk
Copy link
Owner

Koenkk commented Nov 29, 2021

Should be fixed now, can you confirm?

Changes will be available in the dev branch in a few hours from now. (https://www.zigbee2mqtt.io/advanced/more/switch-to-dev-branch.html)

@okastl
Copy link
Author

okastl commented Nov 29, 2021

Should be fixed now, can you confirm?

I'll test tonight, once the family is asleep

@okastl
Copy link
Author

okastl commented Nov 29, 2021

Should be fixed now, can you confirm?

Unfortunately not. Using 1.22.0-dev commit: 290a031:

�[34mZigbee2MQTT:debug�[39m 2021-11-29 22:47:41: Received MQTT message on 'zigbee2mqtt/LaraSonne/availability' with data 'online'
�[34mZigbee2MQTT:debug�[39m 2021-11-29 22:47:41: Received MQTT message on 'zigbee2mqtt/LaraStrahler1' with data '{"brightness":254,"color":{"h":0,"hue":0,"s":100,"saturation":100,"x":0.7006,"y":0.2993},"color_mode":"xy","color_temp":160,"color_temp_startup":370,"last_seen":1638221927714,"linkquality":null,"power_on_behavior":"previous","state":"OFF"}'
(node:10059) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 1001 drain listeners added to [Socket]. Use emitter.setMaxListeners() to increase limit
(Use `node --trace-warnings ...` to show where the warning was created)
MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 1001 drain listeners added to [Socket]. Use emitter.setMaxListeners() to increase limit
    at _addListener (events.js:475:17)
    at Socket.addListener (events.js:497:10)
    at Socket.Readable.on (internal/streams/readable.js:853:35)
    at Socket.once (events.js:541:8)
    at sendPacket (/opt/zigbee2mqtt/node_modules/mqtt/lib/client.js:100:19)
    at MqttClient._sendPacket (/opt/zigbee2mqtt/node_modules/mqtt/lib/client.js:1069:7)
    at MqttClient.publish (/opt/zigbee2mqtt/node_modules/mqtt/lib/client.js:542:14)
    at /opt/zigbee2mqtt/lib/mqtt.ts:152:25
    at new Promise (<anonymous>)
    at MQTT.publish (/opt/zigbee2mqtt/lib/mqtt.ts:151:16)
2021-11-29T21:47:41.235Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,32,68,129,0,0,25,0,183,98,1,13,0,69,0,37,62,14,0,0,12,1,88,1,0,101,18,13,49,103,21,10,33,18,31,27,37,254,32,68,129,0,0,25,0,171,133,1,13,0,69,0,169,214,14,0,0,12,1,82,1,0,16,18,13,17,1,0,0,0,149,133,28,167,254,3,69,196,142,193,0,205,254,32,68,129,0,0,25,0,142,193,1,13,0,81,0,47,66,15,0,0,12,1,183,1,0,101,18,13,49,103,21,10,33,142,193,29,119,254,5,69,196,212,96,1,119,77,11,254,32,68,129,0,0,25,0,83,243,1,13,0,51,0,10,125,15,0,0,12,1,18,1,0,101,18,13,49,103,21,10,33,83,243,29,170,254,28,68,129,0,0,4,11,212,96,1,1,0,60,0,14,129,15,0,0,8,24,27,10,5,5,33,230,0,119,77,28,62,254,28,68,129,0,0,4,11,163,174,1,1,0,57,0,140,147,15,0,0,8,24,19,10,5,5,33,226,0,163,174,29,40,254,32,68,129,0,0,25,0,171,133,1,13,0,69,0,229,92,16,0,0,12,1,82,1,0,16,18,13,17,1,0,0,0,149,133,28,127,254,32,68,129,0,0,25,0,216,21,1,13,0,81,0,123,208,16,0,0,12,1,235,1,0,16,18,13,17,1,0,0,0,142,193,28,124]
2021-11-29T21:47:41.235Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,32,68,129,0,0,25,0,183,98,1,13,0,69,0,37,62,14,0,0,12,1,88,1,0,101,18,13,49,103,21,10,33,18,31,27,37,254,32,68,129,0,0,25,0,171,133,1,13,0,69,0,169,214,14,0,0,12,1,82,1,0,16,18,13,17,1,0,0,0,149,133,28,167,254,3,69,196,142,193,0,205,254,32,68,129,0,0,25,0,142,193,1,13,0,81,0,47,66,15,0,0,12,1,183,1,0,101,18,13,49,103,21,10,33,142,193,29,119,254,5,69,196,212,96,1,119,77,11,254,32,68,129,0,0,25,0,83,243,1,13,0,51,0,10,125,15,0,0,12,1,18,1,0,101,18,13,49,103,21,10,33,83,243,29,170,254,28,68,129,0,0,4,11,212,96,1,1,0,60,0,14,129,15,0,0,8,24,27,10,5,5,33,230,0,119,77,28,62,254,28,68,129,0,0,4,11,163,174,1,1,0,57,0,140,147,15,0,0,8,24,19,10,5,5,33,226,0,163,174,29,40,254,32,68,129,0,0,25,0,171,133,1,13,0,69,0,229,92,16,0,0,12,1,82,1,0,16,18,13,17,1,0,0,0,149,133,28,127,254,32,68,129,0,0,25,0,216,21,1,13,0,81,0,123,208,16,0,0,12,1,235,1,0,16,18,13,17,1,0,0,0,142,193,28,124]
2021-11-29T21:47:41.236Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 32 - 2 - 4 - 129 - [0,0,25,0,183,98,1,13,0,69,0,37,62,14,0,0,12,1,88,1,0,101,18,13,49,103,21,10,33,18,31,27] - 37

@w3host
Copy link

w3host commented Nov 30, 2021

It seems zigbee2mqtt trying to publish all device state too frequently as here:
https://stackoverflow.com/questions/62493731/nodejs-mqtt-publshing-at-1ms-frequency-causes-eventemitter-memory-leak

I always receive this WARNING message after all device state publishing when I restart it.

@Koenkk
Copy link
Owner

Koenkk commented Nov 30, 2021

Did another attempt based on mqttjs/MQTT.js#589 , can you check if it works?

Changes will be available in the dev branch in a few hours from now. (https://www.zigbee2mqtt.io/advanced/more/switch-to-dev-branch.html)

Koenkk added a commit that referenced this issue Nov 30, 2021
@w3host
Copy link

w3host commented Nov 30, 2021

Thanks for the fix. It is working for me no warning message...

@okastl
Copy link
Author

okastl commented Nov 30, 2021

Did another attempt based on mqttjs/MQTT.js#589 , can you check if it works?

Works fine, thank you!

@okastl okastl closed this as completed Nov 30, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
problem Something isn't working
Projects
None yet
Development

No branches or pull requests

4 participants