search

maxileith / homebridge-appletv-enhanced

Homebridge plugin that exposes Apple TVs with features that should be native to Apple HomeKit.
MIT License
188 stars 3 forks source link

Cannot add more than 100 services to a single accessory! #19

Closed ryanmaule closed 1 year ago

ryanmaule commented 1 year ago

Having an issue after pairing the AppleTV - the plugin crashes and enters a restart loop.

Not sure what "Cannot add more than 100 services to a single accessory!" refers to.

Version: homebridge-appletv-enhanced v0.3.1-beta.3

[11/6/2023, 11:42:26 AM] [Apple TV Enhanced] Living Room (9C:3E:53:28:EF:07): Credentials are still valid. Continuing ...
[Apple TV Living Room@@Firmware Revision] Characteristic not in required or optional characteristic section for service Television. Adding anyway.
Error: Cannot add more than 100 services to a single accessory!
    at Accessory.addService (/var/lib/homebridge/node_modules/homebridge/node_modules/hap-nodejs/src/lib/Accessory.ts:564:13)
    at PlatformAccessory.addService (/var/lib/homebridge/node_modules/homebridge/src/platformAccessory.ts:98:41)
    at /var/lib/homebridge/node_modules/homebridge-appletv-enhanced/src/appleTVEnhancedAccessory.ts:403:77
    at Array.forEach (<anonymous>)
    at AppleTVEnhancedAccessory.createInputs (/var/lib/homebridge/node_modules/homebridge-appletv-enhanced/src/appleTVEnhancedAccessory.ts:401:14)
    at AppleTVEnhancedAccessory.startUp (/var/lib/homebridge/node_modules/homebridge-appletv-enhanced/src/appleTVEnhancedAccessory.ts:147:14)
    at processTicksAndRejections (node:internal/process/task_queues:95:5)
[11/6/2023, 11:42:28 AM] [Apple TV Enhanced] Child bridge process ended
[11/6/2023, 11:42:28 AM] [Apple TV Enhanced] Process Ended. Code: 1, Signal: null
[11/6/2023, 11:42:35 AM] [Apple TV Enhanced] Restarting Process...
[11/6/2023, 11:42:36 AM] [Apple TV Enhanced] Launched child bridge with PID 369379
maxileith commented 1 year ago

Hi @ryanmaule ,

quick question. How many Apps do you have installed on your Apple TV? I guess that you have a lot of apps installed ... I never ran into this issue.

maxileith commented 1 year ago

... you don't need to uninstall apps ... just confirm my assumption and I write a fix. If my assumption was wrong, then we will dig into this problem.

ryanmaule commented 1 year ago

Haha - just counted and there's 124 counting Apple stock apps. Kids add stuff and then never play them again, guess it's time to clean up. Hope that helps.

maxileith commented 1 year ago

@ryanmaule yeah that will help, but can you maybe wait a bit with that? Can I write a fix for that that you can then test? I mean if your Apple TV has currently so many apps installed, you are the perfect test candidate ... if that does not bother you :)

ryanmaule commented 1 year ago

Sounds good, I'll hold tight and update when you're ready.

maxileith commented 1 year ago

Ready. Could you please enable debug logging on your homebridge and install v0.3.1-beta.4. Then send all the logs from start of the plugin until you have finished pairing it with your Home app. Please also send the logs if everything was successful.

Thank you in advance.

ryanmaule commented 1 year ago

I think I'm still getting a similar error.

[11/6/2023, 2:05:38 PM] [Apple TV Enhanced] Living Room (9C:3E:53:28:EF:07): Credentials are still valid. Continuing ...
[Apple TV Living Room@@Firmware Revision] Characteristic not in required or optional characteristic section for service Television. Adding anyway.
[Apple TV Living Room@paused@Configured Name] Characteristic not in required or optional characteristic section for service MotionSensor. Adding anyway.
[Apple TV Living Room@playing@Configured Name] Characteristic not in required or optional characteristic section for service MotionSensor. Adding anyway.
[11/6/2023, 2:05:39 PM] [Apple TV Enhanced] Play Room (50:DE:06:9C:BE:67): Apple TV Play Room: Too many attempts. Waiting for 2212 seconds before retrying.
Error: Cannot add more than 100 services to a single accessory!
    at Accessory.addService (/var/lib/homebridge/node_modules/homebridge/node_modules/hap-nodejs/src/lib/Accessory.ts:564:13)
    at PlatformAccessory.addService (/var/lib/homebridge/node_modules/homebridge/src/platformAccessory.ts:98:41)
    at AppleTVEnhancedAccessory.addServiceSave (/var/lib/homebridge/node_modules/homebridge-appletv-enhanced/src/appleTVEnhancedAccessory.ts:925:31)
    at /var/lib/homebridge/node_modules/homebridge-appletv-enhanced/src/appleTVEnhancedAccessory.ts:407:67
    at Array.every (<anonymous>)
    at AppleTVEnhancedAccessory.createInputs (/var/lib/homebridge/node_modules/homebridge-appletv-enhanced/src/appleTVEnhancedAccessory.ts:405:14)
    at AppleTVEnhancedAccessory.startUp (/var/lib/homebridge/node_modules/homebridge-appletv-enhanced/src/appleTVEnhancedAccessory.ts:153:14)
    at processTicksAndRejections (node:internal/process/task_queues:95:5)
maxileith commented 1 year ago

I need the complete debug log. Please enable debug mode in your startup options in the Homebridge settings. Then send the complete logs that were logged by the plugin.

ryanmaule commented 1 year ago

Ok, I'm not sure exactly what parts are helpful since it dumps a lot quickly and each crash causes a restart. Here's a snippet I could get that included the "100 services" error.

[11/6/2023, 2:58:31 PM] [Apple TV Enhanced] Play Room (50:DE:06:9C:BE:67): Apple TV Play Room: Too many attempts. Waiting for 10578 seconds before retrying.
[11/6/2023, 2:58:32 PM] [Apple TV Enhanced] Living Room (9C:3E:53:28:EF:07): Credentials are still valid. Continuing ...
[Apple TV Living Room@@Firmware Revision] Characteristic not in required or optional characteristic section for service Television. Adding anyway.
2023-11-06T19:58:32.125Z HAP-NodeJS:Accessory [Apple TV Living Room] Above characteristic warning was thrown at: unknown
[Apple TV Living Room@paused@Configured Name] Characteristic not in required or optional characteristic section for service MotionSensor. Adding anyway.
2023-11-06T19:58:32.131Z HAP-NodeJS:Accessory [Apple TV Living Room] Above characteristic warning was thrown at: unknown
[Apple TV Living Room@playing@Configured Name] Characteristic not in required or optional characteristic section for service MotionSensor. Adding anyway.
2023-11-06T19:58:32.135Z HAP-NodeJS:Accessory [Apple TV Living Room] Above characteristic warning was thrown at: unknown
Error: Cannot add more than 100 services to a single accessory!
    at Accessory.addService (/var/lib/homebridge/node_modules/homebridge/node_modules/hap-nodejs/src/lib/Accessory.ts:564:13)
    at PlatformAccessory.addService (/var/lib/homebridge/node_modules/homebridge/src/platformAccessory.ts:98:41)
    at AppleTVEnhancedAccessory.addServiceSave (/var/lib/homebridge/node_modules/homebridge-appletv-enhanced/src/appleTVEnhancedAccessory.ts:925:31)
    at /var/lib/homebridge/node_modules/homebridge-appletv-enhanced/src/appleTVEnhancedAccessory.ts:407:67
    at Array.every (<anonymous>)
    at AppleTVEnhancedAccessory.createInputs (/var/lib/homebridge/node_modules/homebridge-appletv-enhanced/src/appleTVEnhancedAccessory.ts:405:14)
    at AppleTVEnhancedAccessory.startUp (/var/lib/homebridge/node_modules/homebridge-appletv-enhanced/src/appleTVEnhancedAccessory.ts:153:14)
    at processTicksAndRejections (node:internal/process/task_queues:95:5)
[11/6/2023, 2:58:34 PM] [Apple TV Enhanced] Child bridge process ended
[11/6/2023, 2:58:34 PM] [Apple TV Enhanced] Process Ended. Code: 1, Signal: null
[11/6/2023, 2:58:41 PM] [Apple TV Enhanced] Restarting Process...
[11/6/2023, 2:58:42 PM] [Apple TV Enhanced] Launched child bridge with PID 379454
[11/6/2023, 2:58:42 PM] Registering platform 'homebridge-appletv-enhanced.AppleTVEnhanced'
[11/6/2023, 2:58:42 PM] [Apple TV Enhanced] Loaded homebridge-appletv-enhanced v0.3.1-beta.4 child bridge successfully
[11/6/2023, 2:58:42 PM] Loaded 0 cached accessories from cachedAccessories.0E4494A302CF.
[11/6/2023, 2:58:42 PM] [Apple TV Enhanced] Platform: Finished initializing platform: Apple TV Enhanced
[11/6/2023, 2:58:42 PM] [Apple TV Enhanced] 'linux 5.15.102-1-pve' is supported by the plugin Homebridge Apple TV.
[11/6/2023, 2:58:42 PM] [Apple TV Enhanced] Python check: Starting python check.
[11/6/2023, 2:58:42 PM] [Apple TV Enhanced] Python check: plugin dir exists.
[11/6/2023, 2:58:42 PM] Homebridge v1.7.0 (HAP v0.11.1) (Apple TV Enhanced) is running on port 33865.
[11/6/2023, 2:58:42 PM] [Apple TV Enhanced] Python check: Python 3.9.2 is installed and supported by the plugin.
[11/6/2023, 2:58:42 PM] [Apple TV Enhanced] Python check: Virtual environment already exists.
[11/6/2023, 2:58:42 PM] [Apple TV Enhanced] Python check: Venv is using current system python version (3.9.2).
[11/6/2023, 2:58:53 PM] [Apple TV Enhanced] Python check: Pip is up-to-date
[11/6/2023, 2:58:54 PM] [Apple TV Enhanced] Python check: Python requirements are satisfied.
[11/6/2023, 2:58:54 PM] [Apple TV Enhanced] Python check: Finished
[11/6/2023, 2:58:54 PM] [Apple TV Enhanced] Platform: Starting device discovery ...
[11/6/2023, 2:59:00 PM] [Apple TV Enhanced] Platform: Adding Apple TV Play Room (50:DE:06:9C:BE:67)
[11/6/2023, 2:59:00 PM] [Apple TV Enhanced] Platform: Adding Apple TV Living Room (9C:3E:53:28:EF:07)
[11/6/2023, 2:59:00 PM] [Apple TV Enhanced] Play Room (50:DE:06:9C:BE:67): You need to pair your Apple TV before the plugin can connect to it. Enter the PIN that is currently displayed on the device here: http://192.168.7.138:42068/
maxileith commented 1 year ago

Can you try with v0.3.2-beta.2 again?

ryanmaule commented 1 year ago

I see your nice new status message, but I'm still getting the error that causes a crash loop.

[11/6/2023, 4:29:25 PM] [Apple TV Enhanced] Apple TV Living Room (9C:3E:53:28:EF:07): 
The maximum of 100 on a single accessory is reached. The following services have been added:
- The television service (Apple TV) itself
- 2 motion sensors for device states 
- 0 motion sensors for media types 
- 0 switches for remote keys 
- 96 apps have been added (28 apps could not be added)
It might be a good idea to uninstall unused apps.
  },
  agents: { http: undefined, https: undefined },
  auth: undefined,
  family: undefined,
  beforeRedirect: [Function: dispatchBeforeRedirect],
  beforeRedirects: { proxy: [Function: beforeRedirect] },
  hostname: 'app2.govee.com',
  port: '',
  agent: undefined,
  nativeProtocols: {
    'http:': {
      _connectionListener: [Function: connectionListener],
      METHODS: [Array],
      STATUS_CODES: [Object],
      Agent: [Function],
      ClientRequest: [Function: ClientRequest],
      IncomingMessage: [Function: IncomingMessage],
      OutgoingMessage: [Function: OutgoingMessage],
      Server: [Function: Server],
      ServerResponse: [Function: ServerResponse],
      createServer: [Function: createServer],
      validateHeaderName: [Function: __node_internal_],
      validateHeaderValue: [Function: __node_internal_],
      get: [Function: get],
      request: [Function: request],
      setMaxIdleHTTPParsers: [Function: setMaxIdleHTTPParsers],
      maxHeaderSize: [Getter],
      globalAgent: [Getter/Setter]
    },
    'https:': {
      Agent: [Function: Agent],
      globalAgent: [Agent],
      Server: [Function: Server],
      createServer: [Function: createServer],
      get: [Function: get],
      request: [Function: request]
    }
  }
}
2023-11-06T21:32:24.947Z mqttjs:client _checkPing :: checking ping...
2023-11-06T21:32:24.947Z mqttjs:client _checkPing :: ping response received. Clearing flag and sending `pingreq`
2023-11-06T21:32:24.948Z mqttjs:client _sendPacket :: (app:d1333b5944e2ff5c7a10a82439fb7935) ::  start
2023-11-06T21:32:24.948Z mqttjs:client _writePacket :: packet: { cmd: 'pingreq' }
2023-11-06T21:32:24.948Z mqttjs:client _writePacket :: emitting `packetsend`
2023-11-06T21:32:24.948Z mqttjs:client _writePacket :: writing to stream
2023-11-06T21:32:24.948Z mqtt-packet:writeToStream generate called
2023-11-06T21:32:24.948Z mqtt-packet:writeToStream generate: packet.cmd: pingreq
2023-11-06T21:32:24.948Z mqttjs:client _writePacket :: writeToStream result true
2023-11-06T21:32:24.948Z mqttjs:client _writePacket :: invoking cb
2023-11-06T21:32:24.948Z mqttjs:client noop :: undefined
2023-11-06T21:32:24.982Z mqttjs:client writable stream :: parsing buffer
2023-11-06T21:32:24.982Z mqtt-packet:parser parse: current state: _parseHeader
2023-11-06T21:32:24.982Z mqtt-packet:parser _parseHeader: packet: Packet { cmd: 'pingresp', retain: false, qos: 0, dup: false, length: -1, topic: null, payload: null }
2023-11-06T21:32:24.982Z mqtt-packet:parser parse: state complete. _stateCounter is now: 1
2023-11-06T21:32:24.982Z mqtt-packet:parser parse: packet.length: -1, buffer list length: 1
2023-11-06T21:32:24.982Z mqtt-packet:parser _parseVarByteNum
2023-11-06T21:32:24.982Z mqtt-packet:parser _parseVarByteNum: result: { bytes: 1, value: 0 }
2023-11-06T21:32:24.982Z mqtt-packet:parser _parseLength 0
2023-11-06T21:32:24.982Z mqtt-packet:parser parse: state complete. _stateCounter is now: 2
2023-11-06T21:32:24.982Z mqtt-packet:parser parse: packet.length: 0, buffer list length: 0
2023-11-06T21:32:24.983Z mqtt-packet:parser _parsePayload: payload BufferListStream {
  _bufs: [],
  length: 0,
  _readableState: ReadableState {
    objectMode: false,
    highWaterMark: 16384,
    buffer: BufferList { head: null, tail: null, length: 0 },
    length: 0,
    pipes: null,
    pipesCount: 0,
    flowing: null,
    ended: false,
    endEmitted: false,
    reading: false,
    sync: true,
    needReadable: false,
    emittedReadable: false,
    readableListening: false,
    resumeScheduled: false,
    paused: true,
    emitClose: true,
    autoDestroy: false,
    destroyed: false,
    defaultEncoding: 'utf8',
    awaitDrain: 0,
    readingMore: false,
    decoder: null,
    encoding: null
  },
  readable: true,
  _events: [Object: null prototype] {},
  _eventsCount: 0,
  _maxListeners: undefined,
  _writableState: WritableState {
    objectMode: false,
    highWaterMark: 16384,
    finalCalled: false,
    needDrain: false,
    ending: false,
    ended: false,
    finished: false,
    destroyed: false,
    decodeStrings: true,
    defaultEncoding: 'utf8',
    length: 0,
    writing: false,
    corked: 0,
    sync: true,
    bufferProcessing: false,
    onwrite: [Function (anonymous)],
    writecb: null,
    writelen: 0,
    bufferedRequest: null,
    lastBufferedRequest: null,
    pendingcb: 0,
    prefinished: false,
    errorEmitted: false,
    emitClose: true,
    autoDestroy: false,
    bufferedRequestCount: 0,
    corkedRequestsFree: CorkedRequest {
      next: null,
      entry: null,
      finish: [Function (anonymous)]
    }
  },
  writable: true,
  allowHalfOpen: true,
  [Symbol(kCapture)]: false
}
2023-11-06T21:32:24.983Z mqtt-packet:parser _parsePayload complete result: true
2023-11-06T21:32:24.983Z mqtt-packet:parser parse: state complete. _stateCounter is now: 3
2023-11-06T21:32:24.983Z mqtt-packet:parser parse: packet.length: 0, buffer list length: 0
2023-11-06T21:32:24.983Z mqtt-packet:parser _newPacket
2023-11-06T21:32:24.983Z mqtt-packet:parser _newPacket: parser emit packet: packet.cmd: pingresp, packet.payload: null, packet.length: 0
2023-11-06T21:32:24.983Z mqttjs:client parser :: on packet push to packets array.
2023-11-06T21:32:24.983Z mqtt-packet:parser _newPacket: new packet
2023-11-06T21:32:24.983Z mqtt-packet:parser parse: state complete. _stateCounter is now: 4
2023-11-06T21:32:24.983Z mqtt-packet:parser parse: packet.length: -1, buffer list length: 0
2023-11-06T21:32:24.983Z mqtt-packet:parser parse: exited while loop. packet: -1, buffer list length: 0
2023-11-06T21:32:24.983Z mqttjs:client work :: getting next packet in queue
2023-11-06T21:32:24.983Z mqttjs:client work :: packet pulled from queue
2023-11-06T21:32:24.984Z mqttjs:client _handlePacket :: emitting packetreceive
[11/6/2023, 4:32:25 PM] [Govee] [Soffit Lights] current brightness [50%].
2023-11-06T21:32:25.310Z HAP-NodeJS:EventedHTTPServer:Connection [::ffff:192.168.7.249] Sending HAP event notifications [ { aid: 101, iid: 11, value: 50 } ]
[11/6/2023, 4:32:30 PM] [Apple TV Enhanced] Python check: Pip is up-to-date
[11/6/2023, 4:32:31 PM] [Apple TV Enhanced] Python check: Python requirements are satisfied.
[11/6/2023, 4:32:31 PM] [Apple TV Enhanced] Python check: Finished
[11/6/2023, 4:32:31 PM] [Apple TV Enhanced] Platform: Starting device discovery ...
[11/6/2023, 4:32:37 PM] [Apple TV Enhanced] Platform: Adding Apple TV Play Room (50:DE:06:9C:BE:67)
[11/6/2023, 4:32:37 PM] [Apple TV Enhanced] Platform: Adding Apple TV Living Room (9C:3E:53:28:EF:07)
Error: listen EADDRINUSE: address already in use 0.0.0.0:42068
    at Server.setupListenHandle [as _listen2] (node:net:1817:16)
    at listenInCluster (node:net:1865:12)
    at doListen (node:net:2014:7)
    at processTicksAndRejections (node:internal/process/task_queues:83:21)
[11/6/2023, 4:32:37 PM] [Apple TV Enhanced] Child bridge process ended
[11/6/2023, 4:32:37 PM] [Apple TV Enhanced] Process Ended. Code: 1, Signal: null
[11/6/2023, 4:32:44 PM] [Apple TV Enhanced] Restarting Process...
2023-11-06T21:32:45.122Z engine.io-client:socket socket receive: type "ping", data "undefined"
2023-11-06T21:32:45.127Z engine.io-client:socket writing ping packet - expecting pong within 60000ms
2023-11-06T21:32:45.127Z engine.io-client:socket flushing 1 packets in socket
2023-11-06T21:32:45.159Z engine.io-client:socket socket receive: type "pong", data "undefined"
2023-11-06T21:32:45.324Z ciao:init Loading ciao v1.1.7...
2023-11-06T21:32:45.979Z HAP-NodeJS:Advertiser Initializing HAP-NodeJS v0.11.1 ...
[11/6/2023, 4:32:46 PM] [Apple TV Enhanced] Launched child bridge with PID 383187
[11/6/2023, 4:32:46 PM] Registering platform 'homebridge-appletv-enhanced.AppleTVEnhanced'
[11/6/2023, 4:32:46 PM] [Apple TV Enhanced] Loaded homebridge-appletv-enhanced v0.3.2-beta.2 child bridge successfully
[11/6/2023, 4:32:46 PM] Loaded 0 cached accessories from cachedAccessories.0E4494A302CF.
[11/6/2023, 4:32:46 PM] [Apple TV Enhanced] Platform: Finished initializing platform: Apple TV Enhanced
[11/6/2023, 4:32:46 PM] [Apple TV Enhanced] 'linux 5.15.102-1-pve' is supported by the plugin Homebridge Apple TV Enhanced.
[11/6/2023, 4:32:46 PM] [Apple TV Enhanced] Python check: Starting python check.
[11/6/2023, 4:32:46 PM] [Apple TV Enhanced] Python check: plugin dir exists.
2023-11-06T21:32:46.404Z HAP-NodeJS:Advertiser Detected Avahi over DBus interface running version 'avahi 0.8'.
2023-11-06T21:32:46.408Z HAP-NodeJS:Advertiser Preparing Advertiser for 'Apple TV Enhanced A493' using Avahi backend!
2023-11-06T21:32:46.415Z HAP-NodeJS:EventedHTTPServer Server listening on [::]:33865
2023-11-06T21:32:46.417Z HAP-NodeJS:Advertiser Starting to advertise 'Apple TV Enhanced A493' using Avahi backend!
[11/6/2023, 4:32:46 PM] Homebridge v1.7.0 (HAP v0.11.1) (Apple TV Enhanced) is running on port 33865.
[11/6/2023, 4:32:46 PM] [Apple TV Enhanced] Python check: Python 3.9.2 is installed and supported by the plugin.
[11/6/2023, 4:32:46 PM] [Apple TV Enhanced] Python check: Virtual environment already exists.
[11/6/2023, 4:32:46 PM] [Apple TV Enhanced] Python check: Venv is using current system python version (3.9.2).
2023-11-06T21:32:47.383Z HAP-NodeJS:EventedHTTPServer Currently 1 hap connections open: ::ffff:192.168.7.249:49333
2023-11-06T21:32:51.556Z mqttjs:client _checkPing :: checking ping...
2023-11-06T21:32:51.556Z mqttjs:client _checkPing :: ping response received. Clearing flag and sending `pingreq`
2023-11-06T21:32:51.557Z mqttjs:client _sendPacket :: (app:77decae6b61fa6772a8f2897e5154029) ::  start
2023-11-06T21:32:51.557Z mqttjs:client _writePacket :: packet: { cmd: 'pingreq' }
2023-11-06T21:32:51.557Z mqttjs:client _writePacket :: emitting `packetsend`
2023-11-06T21:32:51.557Z mqttjs:client _writePacket :: writing to stream
2023-11-06T21:32:51.557Z mqtt-packet:writeToStream generate called
2023-11-06T21:32:51.557Z mqtt-packet:writeToStream generate: packet.cmd: pingreq
2023-11-06T21:32:51.557Z mqttjs:client _writePacket :: writeToStream result true
2023-11-06T21:32:51.557Z mqttjs:client _writePacket :: invoking cb
2023-11-06T21:32:51.557Z mqttjs:client noop :: undefined
2023-11-06T21:32:51.593Z mqttjs:client writable stream :: parsing buffer
2023-11-06T21:32:51.593Z mqtt-packet:parser parse: current state: _parseHeader
2023-11-06T21:32:51.594Z mqtt-packet:parser _parseHeader: packet: Packet { cmd: 'pingresp', retain: false, qos: 0, dup: false, length: -1, topic: null, payload: null }
2023-11-06T21:32:51.594Z mqtt-packet:parser parse: state complete. _stateCounter is now: 1
2023-11-06T21:32:51.594Z mqtt-packet:parser parse: packet.length: -1, buffer list length: 1
2023-11-06T21:32:51.594Z mqtt-packet:parser _parseVarByteNum
2023-11-06T21:32:51.594Z mqtt-packet:parser _parseVarByteNum: result: { bytes: 1, value: 0 }
2023-11-06T21:32:51.594Z mqtt-packet:parser _parseLength 0
2023-11-06T21:32:51.594Z mqtt-packet:parser parse: state complete. _stateCounter is now: 2
2023-11-06T21:32:51.594Z mqtt-packet:parser parse: packet.length: 0, buffer list length: 0
2023-11-06T21:32:51.595Z mqtt-packet:parser _parsePayload: payload BufferListStream {
  _bufs: [],
  length: 0,
  _readableState: ReadableState {
    objectMode: false,
    highWaterMark: 16384,
    buffer: BufferList { head: null, tail: null, length: 0 },
    length: 0,
    pipes: null,
    pipesCount: 0,
    flowing: null,
    ended: false,
    endEmitted: false,
    reading: false,
    sync: true,
    needReadable: false,
    emittedReadable: false,
    readableListening: false,
    resumeScheduled: false,
    paused: true,
    emitClose: true,
    autoDestroy: false,
    destroyed: false,
    defaultEncoding: 'utf8',
    awaitDrain: 0,
    readingMore: false,
    decoder: null,
    encoding: null
  },
  readable: true,
  _events: [Object: null prototype] {},
  _eventsCount: 0,
  _maxListeners: undefined,
  _writableState: WritableState {
    objectMode: false,
    highWaterMark: 16384,
    finalCalled: false,
    needDrain: false,
    ending: false,
    ended: false,
    finished: false,
    destroyed: false,
    decodeStrings: true,
    defaultEncoding: 'utf8',
    length: 0,
    writing: false,
    corked: 0,
    sync: true,
    bufferProcessing: false,
    onwrite: [Function (anonymous)],
    writecb: null,
    writelen: 0,
    bufferedRequest: null,
    lastBufferedRequest: null,
    pendingcb: 0,
    prefinished: false,
    errorEmitted: false,
    emitClose: true,
    autoDestroy: false,
    bufferedRequestCount: 0,
    corkedRequestsFree: CorkedRequest {
      next: null,
      entry: null,
      finish: [Function (anonymous)]
    }
  },
  writable: true,
  allowHalfOpen: true,
  [Symbol(kCapture)]: false
}
2023-11-06T21:32:51.595Z mqtt-packet:parser _parsePayload complete result: true
2023-11-06T21:32:51.595Z mqtt-packet:parser parse: state complete. _stateCounter is now: 3
2023-11-06T21:32:51.595Z mqtt-packet:parser parse: packet.length: 0, buffer list length: 0
2023-11-06T21:32:51.595Z mqtt-packet:parser _newPacket
2023-11-06T21:32:51.595Z mqtt-packet:parser _newPacket: parser emit packet: packet.cmd: pingresp, packet.payload: null, packet.length: 0
2023-11-06T21:32:51.595Z mqttjs:client parser :: on packet push to packets array.
2023-11-06T21:32:51.595Z mqtt-packet:parser _newPacket: new packet
2023-11-06T21:32:51.595Z mqtt-packet:parser parse: state complete. _stateCounter is now: 4
2023-11-06T21:32:51.595Z mqtt-packet:parser parse: packet.length: -1, buffer list length: 0
2023-11-06T21:32:51.595Z mqtt-packet:parser parse: exited while loop. packet: -1, buffer list length: 0
2023-11-06T21:32:51.595Z mqttjs:client work :: getting next packet in queue
2023-11-06T21:32:51.595Z mqttjs:client work :: packet pulled from queue
2023-11-06T21:32:51.595Z mqttjs:client _handlePacket :: emitting packetreceive
2023-11-06T21:32:51.621Z mqttjs:client _checkPing :: checking ping...
2023-11-06T21:32:51.621Z mqttjs:client _checkPing :: ping response received. Clearing flag and sending `pingreq`
2023-11-06T21:32:51.621Z mqttjs:client _sendPacket :: (app:210f68297a3e204bb791f557580ee5c5) ::  start
2023-11-06T21:32:51.622Z mqttjs:client _writePacket :: packet: { cmd: 'pingreq' }
2023-11-06T21:32:51.622Z mqttjs:client _writePacket :: emitting `packetsend`
2023-11-06T21:32:51.622Z mqttjs:client _writePacket :: writing to stream
2023-11-06T21:32:51.622Z mqtt-packet:writeToStream generate called
2023-11-06T21:32:51.622Z mqtt-packet:writeToStream generate: packet.cmd: pingreq
2023-11-06T21:32:51.622Z mqttjs:client _writePacket :: writeToStream result true
2023-11-06T21:32:51.622Z mqttjs:client _writePacket :: invoking cb
2023-11-06T21:32:51.622Z mqttjs:client noop :: undefined
2023-11-06T21:32:51.671Z mqttjs:client writable stream :: parsing buffer
2023-11-06T21:32:51.671Z mqtt-packet:parser parse: current state: _parseHeader
2023-11-06T21:32:51.671Z mqtt-packet:parser _parseHeader: packet: Packet { cmd: 'pingresp', retain: false, qos: 0, dup: false, length: -1, topic: null, payload: null }
2023-11-06T21:32:51.671Z mqtt-packet:parser parse: state complete. _stateCounter is now: 1
2023-11-06T21:32:51.671Z mqtt-packet:parser parse: packet.length: -1, buffer list length: 1
2023-11-06T21:32:51.671Z mqtt-packet:parser _parseVarByteNum
2023-11-06T21:32:51.671Z mqtt-packet:parser _parseVarByteNum: result: { bytes: 1, value: 0 }
2023-11-06T21:32:51.671Z mqtt-packet:parser _parseLength 0
2023-11-06T21:32:51.671Z mqtt-packet:parser parse: state complete. _stateCounter is now: 2
2023-11-06T21:32:51.671Z mqtt-packet:parser parse: packet.length: 0, buffer list length: 0
2023-11-06T21:32:51.672Z mqtt-packet:parser _parsePayload: payload BufferListStream {
  _bufs: [],
  length: 0,
  _readableState: ReadableState {
    objectMode: false,
    highWaterMark: 16384,
    buffer: BufferList { head: null, tail: null, length: 0 },
    length: 0,
    pipes: null,
    pipesCount: 0,
    flowing: null,
    ended: false,
    endEmitted: false,
    reading: false,
    sync: true,
    needReadable: false,
    emittedReadable: false,
    readableListening: false,
    resumeScheduled: false,
    paused: true,
    emitClose: true,
    autoDestroy: false,
    destroyed: false,
    defaultEncoding: 'utf8',
    awaitDrain: 0,
    readingMore: false,
    decoder: null,
    encoding: null
  },
  readable: true,
  _events: [Object: null prototype] {},
  _eventsCount: 0,
  _maxListeners: undefined,
  _writableState: WritableState {
    objectMode: false,
    highWaterMark: 16384,
    finalCalled: false,
    needDrain: false,
    ending: false,
    ended: false,
    finished: false,
    destroyed: false,
    decodeStrings: true,
    defaultEncoding: 'utf8',
    length: 0,
    writing: false,
    corked: 0,
    sync: true,
    bufferProcessing: false,
    onwrite: [Function (anonymous)],
    writecb: null,
    writelen: 0,
    bufferedRequest: null,
    lastBufferedRequest: null,
    pendingcb: 0,
    prefinished: false,
    errorEmitted: false,
    emitClose: true,
    autoDestroy: false,
    bufferedRequestCount: 0,
    corkedRequestsFree: CorkedRequest {
      next: null,
      entry: null,
      finish: [Function (anonymous)]
    }
  },
  writable: true,
  allowHalfOpen: true,
  [Symbol(kCapture)]: false
}
2023-11-06T21:32:51.672Z mqtt-packet:parser _parsePayload complete result: true
2023-11-06T21:32:51.672Z mqtt-packet:parser parse: state complete. _stateCounter is now: 3
2023-11-06T21:32:51.672Z mqtt-packet:parser parse: packet.length: 0, buffer list length: 0
2023-11-06T21:32:51.672Z mqtt-packet:parser _newPacket
2023-11-06T21:32:51.672Z mqtt-packet:parser _newPacket: parser emit packet: packet.cmd: pingresp, packet.payload: null, packet.length: 0
2023-11-06T21:32:51.672Z mqttjs:client parser :: on packet push to packets array.
2023-11-06T21:32:51.672Z mqtt-packet:parser _newPacket: new packet
2023-11-06T21:32:51.672Z mqtt-packet:parser parse: state complete. _stateCounter is now: 4
2023-11-06T21:32:51.672Z mqtt-packet:parser parse: packet.length: -1, buffer list length: 0
2023-11-06T21:32:51.672Z mqtt-packet:parser parse: exited while loop. packet: -1, buffer list length: 0
2023-11-06T21:32:51.672Z mqttjs:client work :: getting next packet in queue
2023-11-06T21:32:51.672Z mqttjs:client work :: packet pulled from queue
2023-11-06T21:32:51.672Z mqttjs:client _handlePacket :: emitting packetreceive
2023-11-06T21:32:51.673Z mqttjs:client _checkPing :: checking ping...
2023-11-06T21:32:51.673Z mqttjs:client _checkPing :: ping response received. Clearing flag and sending `pingreq`
2023-11-06T21:32:51.673Z mqttjs:client _sendPacket :: (app:711950501812518eb363a7e683eb45fa) ::  start
2023-11-06T21:32:51.673Z mqttjs:client _writePacket :: packet: { cmd: 'pingreq' }
2023-11-06T21:32:51.673Z mqttjs:client _writePacket :: emitting `packetsend`
2023-11-06T21:32:51.673Z mqttjs:client _writePacket :: writing to stream
2023-11-06T21:32:51.673Z mqtt-packet:writeToStream generate called
2023-11-06T21:32:51.673Z mqtt-packet:writeToStream generate: packet.cmd: pingreq
2023-11-06T21:32:51.673Z mqttjs:client _writePacket :: writeToStream result true
2023-11-06T21:32:51.673Z mqttjs:client _writePacket :: invoking cb
2023-11-06T21:32:51.673Z mqttjs:client noop :: undefined
2023-11-06T21:32:51.703Z mqttjs:client writable stream :: parsing buffer
2023-11-06T21:32:51.703Z mqtt-packet:parser parse: current state: _parseHeader
2023-11-06T21:32:51.703Z mqtt-packet:parser _parseHeader: packet: Packet { cmd: 'pingresp', retain: false, qos: 0, dup: false, length: -1, topic: null, payload: null }
2023-11-06T21:32:51.704Z mqtt-packet:parser parse: state complete. _stateCounter is now: 1
2023-11-06T21:32:51.704Z mqtt-packet:parser parse: packet.length: -1, buffer list length: 1
2023-11-06T21:32:51.704Z mqtt-packet:parser _parseVarByteNum
2023-11-06T21:32:51.704Z mqtt-packet:parser _parseVarByteNum: result: { bytes: 1, value: 0 }
2023-11-06T21:32:51.704Z mqtt-packet:parser _parseLength 0
2023-11-06T21:32:51.704Z mqtt-packet:parser parse: state complete. _stateCounter is now: 2
2023-11-06T21:32:51.704Z mqtt-packet:parser parse: packet.length: 0, buffer list length: 0
2023-11-06T21:32:51.704Z mqtt-packet:parser _parsePayload: payload BufferListStream {
  _bufs: [],
  length: 0,
  _readableState: ReadableState {
    objectMode: false,
    highWaterMark: 16384,
    buffer: BufferList { head: null, tail: null, length: 0 },
    length: 0,
    pipes: null,
    pipesCount: 0,
    flowing: null,
    ended: false,
    endEmitted: false,
    reading: false,
    sync: true,
    needReadable: false,
    emittedReadable: false,
    readableListening: false,
    resumeScheduled: false,
    paused: true,
    emitClose: true,
    autoDestroy: false,
    destroyed: false,
    defaultEncoding: 'utf8',
    awaitDrain: 0,
    readingMore: false,
    decoder: null,
    encoding: null
  },
  readable: true,
  _events: [Object: null prototype] {},
  _eventsCount: 0,
  _maxListeners: undefined,
  _writableState: WritableState {
    objectMode: false,
    highWaterMark: 16384,
    finalCalled: false,
    needDrain: false,
    ending: false,
    ended: false,
    finished: false,
    destroyed: false,
    decodeStrings: true,
    defaultEncoding: 'utf8',
    length: 0,
    writing: false,
    corked: 0,
    sync: true,
    bufferProcessing: false,
    onwrite: [Function (anonymous)],
    writecb: null,
    writelen: 0,
    bufferedRequest: null,
    lastBufferedRequest: null,
    pendingcb: 0,
    prefinished: false,
    errorEmitted: false,
    emitClose: true,
    autoDestroy: false,
    bufferedRequestCount: 0,
    corkedRequestsFree: CorkedRequest {
      next: null,
      entry: null,
      finish: [Function (anonymous)]
    }
  },
  writable: true,
  allowHalfOpen: true,
  [Symbol(kCapture)]: false
}
2023-11-06T21:32:51.704Z mqtt-packet:parser _parsePayload complete result: true
2023-11-06T21:32:51.704Z mqtt-packet:parser parse: state complete. _stateCounter is now: 3
2023-11-06T21:32:51.704Z mqtt-packet:parser parse: packet.length: 0, buffer list length: 0
2023-11-06T21:32:51.704Z mqtt-packet:parser _newPacket
2023-11-06T21:32:51.704Z mqtt-packet:parser _newPacket: parser emit packet: packet.cmd: pingresp, packet.payload: null, packet.length: 0
2023-11-06T21:32:51.704Z mqttjs:client parser :: on packet push to packets array.
2023-11-06T21:32:51.704Z mqtt-packet:parser _newPacket: new packet
2023-11-06T21:32:51.705Z mqtt-packet:parser parse: state complete. _stateCounter is now: 4
2023-11-06T21:32:51.705Z mqtt-packet:parser parse: packet.length: -1, buffer list length: 0
2023-11-06T21:32:51.705Z mqtt-packet:parser parse: exited while loop. packet: -1, buffer list length: 0
2023-11-06T21:32:51.705Z mqttjs:client work :: getting next packet in queue
2023-11-06T21:32:51.705Z mqttjs:client work :: packet pulled from queue
2023-11-06T21:32:51.705Z mqttjs:client _handlePacket :: emitting packetreceive
2023-11-06T21:32:51.713Z mqttjs:client _checkPing :: checking ping...
2023-11-06T21:32:51.713Z mqttjs:client _checkPing :: ping response received. Clearing flag and sending `pingreq`
2023-11-06T21:32:51.713Z mqttjs:client _sendPacket :: (app:1ccf3ae28e1e9223677eb8b3fb6bff63) ::  start
2023-11-06T21:32:51.714Z mqttjs:client _writePacket :: packet: { cmd: 'pingreq' }
2023-11-06T21:32:51.714Z mqttjs:client _writePacket :: emitting `packetsend`
2023-11-06T21:32:51.714Z mqttjs:client _writePacket :: writing to stream
2023-11-06T21:32:51.714Z mqtt-packet:writeToStream generate called
2023-11-06T21:32:51.714Z mqtt-packet:writeToStream generate: packet.cmd: pingreq
2023-11-06T21:32:51.714Z mqttjs:client _writePacket :: writeToStream result true
2023-11-06T21:32:51.714Z mqttjs:client _writePacket :: invoking cb
2023-11-06T21:32:51.714Z mqttjs:client noop :: undefined
2023-11-06T21:32:51.749Z mqttjs:client _checkPing :: checking ping...
2023-11-06T21:32:51.749Z mqttjs:client _checkPing :: ping response received. Clearing flag and sending `pingreq`
2023-11-06T21:32:51.749Z mqttjs:client _sendPacket :: (app:c6a0f5b3b267c72ce5470b603b2bfe52) ::  start
2023-11-06T21:32:51.749Z mqttjs:client _writePacket :: packet: { cmd: 'pingreq' }
2023-11-06T21:32:51.749Z mqttjs:client _writePacket :: emitting `packetsend`
2023-11-06T21:32:51.749Z mqttjs:client _writePacket :: writing to stream
2023-11-06T21:32:51.749Z mqtt-packet:writeToStream generate called
2023-11-06T21:32:51.749Z mqtt-packet:writeToStream generate: packet.cmd: pingreq
2023-11-06T21:32:51.749Z mqttjs:client _writePacket :: writeToStream result true
2023-11-06T21:32:51.749Z mqttjs:client _writePacket :: invoking cb
2023-11-06T21:32:51.749Z mqttjs:client noop :: undefined
2023-11-06T21:32:51.750Z mqttjs:client writable stream :: parsing buffer
2023-11-06T21:32:51.750Z mqtt-packet:parser parse: current state: _parseHeader
2023-11-06T21:32:51.750Z mqtt-packet:parser _parseHeader: packet: Packet { cmd: 'pingresp', retain: false, qos: 0, dup: false, length: -1, topic: null, payload: null }
2023-11-06T21:32:51.750Z mqtt-packet:parser parse: state complete. _stateCounter is now: 1
2023-11-06T21:32:51.750Z mqtt-packet:parser parse: packet.length: -1, buffer list length: 1
2023-11-06T21:32:51.750Z mqtt-packet:parser _parseVarByteNum
2023-11-06T21:32:51.750Z mqtt-packet:parser _parseVarByteNum: result: { bytes: 1, value: 0 }
2023-11-06T21:32:51.751Z mqtt-packet:parser _parseLength 0
2023-11-06T21:32:51.751Z mqtt-packet:parser parse: state complete. _stateCounter is now: 2
2023-11-06T21:32:51.751Z mqtt-packet:parser parse: packet.length: 0, buffer list length: 0
2023-11-06T21:32:51.751Z mqtt-packet:parser _parsePayload: payload BufferListStream {
  _bufs: [],
  length: 0,
  _readableState: ReadableState {
    objectMode: false,
    highWaterMark: 16384,
    buffer: BufferList { head: null, tail: null, length: 0 },
    length: 0,
    pipes: null,
    pipesCount: 0,
    flowing: null,
    ended: false,
    endEmitted: false,
    reading: false,
    sync: true,
    needReadable: false,
    emittedReadable: false,
    readableListening: false,
    resumeScheduled: false,
    paused: true,
    emitClose: true,
    autoDestroy: false,
    destroyed: false,
    defaultEncoding: 'utf8',
    awaitDrain: 0,
    readingMore: false,
    decoder: null,
    encoding: null
  },
  readable: true,
  _events: [Object: null prototype] {},
  _eventsCount: 0,
  _maxListeners: undefined,
  _writableState: WritableState {
    objectMode: false,
    highWaterMark: 16384,
    finalCalled: false,
    needDrain: false,
    ending: false,
    ended: false,
    finished: false,
    destroyed: false,
    decodeStrings: true,
    defaultEncoding: 'utf8',
    length: 0,
    writing: false,
    corked: 0,
    sync: true,
    bufferProcessing: false,
    onwrite: [Function (anonymous)],
    writecb: null,
    writelen: 0,
    bufferedRequest: null,
    lastBufferedRequest: null,
    pendingcb: 0,
    prefinished: false,
    errorEmitted: false,
    emitClose: true,
    autoDestroy: false,
    bufferedRequestCount: 0,
    corkedRequestsFree: CorkedRequest {
      next: null,
      entry: null,
      finish: [Function (anonymous)]
    }
  },
  writable: true,
  allowHalfOpen: true,
  [Symbol(kCapture)]: false
}
2023-11-06T21:32:51.751Z mqtt-packet:parser _parsePayload complete result: true
2023-11-06T21:32:51.751Z mqtt-packet:parser parse: state complete. _stateCounter is now: 3
2023-11-06T21:32:51.751Z mqtt-packet:parser parse: packet.length: 0, buffer list length: 0
2023-11-06T21:32:51.751Z mqtt-packet:parser _newPacket
2023-11-06T21:32:51.751Z mqtt-packet:parser _newPacket: parser emit packet: packet.cmd: pingresp, packet.payload: null, packet.length: 0
2023-11-06T21:32:51.751Z mqttjs:client parser :: on packet push to packets array.
2023-11-06T21:32:51.751Z mqtt-packet:parser _newPacket: new packet
2023-11-06T21:32:51.751Z mqtt-packet:parser parse: state complete. _stateCounter is now: 4
2023-11-06T21:32:51.751Z mqtt-packet:parser parse: packet.length: -1, buffer list length: 0
2023-11-06T21:32:51.751Z mqtt-packet:parser parse: exited while loop. packet: -1, buffer list length: 0
2023-11-06T21:32:51.751Z mqttjs:client work :: getting next packet in queue
2023-11-06T21:32:51.751Z mqttjs:client work :: packet pulled from queue
2023-11-06T21:32:51.751Z mqttjs:client _handlePacket :: emitting packetreceive
2023-11-06T21:32:51.794Z mqttjs:client writable stream :: parsing buffer
2023-11-06T21:32:51.795Z mqtt-packet:parser parse: current state: _parseHeader
2023-11-06T21:32:51.795Z mqtt-packet:parser _parseHeader: packet: Packet { cmd: 'pingresp', retain: false, qos: 0, dup: false, length: -1, topic: null, payload: null }
2023-11-06T21:32:51.795Z mqtt-packet:parser parse: state complete. _stateCounter is now: 1
2023-11-06T21:32:51.795Z mqtt-packet:parser parse: packet.length: -1, buffer list length: 1
2023-11-06T21:32:51.795Z mqtt-packet:parser _parseVarByteNum
2023-11-06T21:32:51.795Z mqtt-packet:parser _parseVarByteNum: result: { bytes: 1, value: 0 }
2023-11-06T21:32:51.795Z mqtt-packet:parser _parseLength 0
2023-11-06T21:32:51.795Z mqtt-packet:parser parse: state complete. _stateCounter is now: 2
2023-11-06T21:32:51.795Z mqtt-packet:parser parse: packet.length: 0, buffer list length: 0
2023-11-06T21:32:51.796Z mqtt-packet:parser _parsePayload: payload BufferListStream {
  _bufs: [],
  length: 0,
  _readableState: ReadableState {
    objectMode: false,
    highWaterMark: 16384,
    buffer: BufferList { head: null, tail: null, length: 0 },
    length: 0,
    pipes: null,
    pipesCount: 0,
    flowing: null,
    ended: false,
    endEmitted: false,
    reading: false,
    sync: true,
    needReadable: false,
    emittedReadable: false,
    readableListening: false,
    resumeScheduled: false,
    paused: true,
    emitClose: true,
    autoDestroy: false,
    destroyed: false,
    defaultEncoding: 'utf8',
    awaitDrain: 0,
    readingMore: false,
    decoder: null,
    encoding: null
  },
  readable: true,
  _events: [Object: null prototype] {},
  _eventsCount: 0,
  _maxListeners: undefined,
  _writableState: WritableState {
    objectMode: false,
    highWaterMark: 16384,
    finalCalled: false,
    needDrain: false,
    ending: false,
    ended: false,
    finished: false,
    destroyed: false,
    decodeStrings: true,
    defaultEncoding: 'utf8',
    length: 0,
    writing: false,
    corked: 0,
    sync: true,
    bufferProcessing: false,
    onwrite: [Function (anonymous)],
    writecb: null,
    writelen: 0,
    bufferedRequest: null,
    lastBufferedRequest: null,
    pendingcb: 0,
    prefinished: false,
    errorEmitted: false,
    emitClose: true,
    autoDestroy: false,
    bufferedRequestCount: 0,
    corkedRequestsFree: CorkedRequest {
      next: null,
      entry: null,
      finish: [Function (anonymous)]
    }
  },
  writable: true,
  allowHalfOpen: true,
  [Symbol(kCapture)]: false
}
2023-11-06T21:32:51.796Z mqtt-packet:parser _parsePayload complete result: true
2023-11-06T21:32:51.796Z mqtt-packet:parser parse: state complete. _stateCounter is now: 3
2023-11-06T21:32:51.796Z mqtt-packet:parser parse: packet.length: 0, buffer list length: 0
2023-11-06T21:32:51.796Z mqtt-packet:parser _newPacket
2023-11-06T21:32:51.796Z mqtt-packet:parser _newPacket: parser emit packet: packet.cmd: pingresp, packet.payload: null, packet.length: 0
2023-11-06T21:32:51.796Z mqttjs:client parser :: on packet push to packets array.
2023-11-06T21:32:51.796Z mqtt-packet:parser _newPacket: new packet
2023-11-06T21:32:51.796Z mqtt-packet:parser parse: state complete. _stateCounter is now: 4
2023-11-06T21:32:51.796Z mqtt-packet:parser parse: packet.length: -1, buffer list length: 0
2023-11-06T21:32:51.796Z mqtt-packet:parser parse: exited while loop. packet: -1, buffer list length: 0
2023-11-06T21:32:51.796Z mqttjs:client work :: getting next packet in queue
2023-11-06T21:32:51.796Z mqttjs:client work :: packet pulled from queue
2023-11-06T21:32:51.796Z mqttjs:client _handlePacket :: emitting packetreceive
2023-11-06T21:32:51.796Z mqttjs:client _checkPing :: checking ping...
2023-11-06T21:32:51.796Z mqttjs:client _checkPing :: ping response received. Clearing flag and sending `pingreq`
2023-11-06T21:32:51.796Z mqttjs:client _sendPacket :: (app:7ff2b6de10a596404f8c098f6b1deafe) ::  start
2023-11-06T21:32:51.797Z mqttjs:client _writePacket :: packet: { cmd: 'pingreq' }
2023-11-06T21:32:51.797Z mqttjs:client _writePacket :: emitting `packetsend`
2023-11-06T21:32:51.797Z mqttjs:client _writePacket :: writing to stream
2023-11-06T21:32:51.797Z mqtt-packet:writeToStream generate called
2023-11-06T21:32:51.797Z mqtt-packet:writeToStream generate: packet.cmd: pingreq
2023-11-06T21:32:51.797Z mqttjs:client _writePacket :: writeToStream result true
2023-11-06T21:32:51.797Z mqttjs:client _writePacket :: invoking cb
2023-11-06T21:32:51.797Z mqttjs:client noop :: undefined
2023-11-06T21:32:51.830Z mqttjs:client writable stream :: parsing buffer
2023-11-06T21:32:51.831Z mqtt-packet:parser parse: current state: _parseHeader
2023-11-06T21:32:51.831Z mqtt-packet:parser _parseHeader: packet: Packet { cmd: 'pingresp', retain: false, qos: 0, dup: false, length: -1, topic: null, payload: null }
2023-11-06T21:32:51.831Z mqtt-packet:parser parse: state complete. _stateCounter is now: 1
2023-11-06T21:32:51.831Z mqtt-packet:parser parse: packet.length: -1, buffer list length: 1
2023-11-06T21:32:51.831Z mqtt-packet:parser _parseVarByteNum
2023-11-06T21:32:51.831Z mqtt-packet:parser _parseVarByteNum: result: { bytes: 1, value: 0 }
2023-11-06T21:32:51.831Z mqtt-packet:parser _parseLength 0
2023-11-06T21:32:51.831Z mqtt-packet:parser parse: state complete. _stateCounter is now: 2
2023-11-06T21:32:51.831Z mqtt-packet:parser parse: packet.length: 0, buffer list length: 0
2023-11-06T21:32:51.832Z mqtt-packet:parser _parsePayload: payload BufferListStream {
  _bufs: [],
  length: 0,
  _readableState: ReadableState {
    objectMode: false,
    highWaterMark: 16384,
    buffer: BufferList { head: null, tail: null, length: 0 },
    length: 0,
    pipes: null,
    pipesCount: 0,
    flowing: null,
    ended: false,
    endEmitted: false,
    reading: false,
    sync: true,
    needReadable: false,
    emittedReadable: false,
    readableListening: false,
    resumeScheduled: false,
    paused: true,
    emitClose: true,
    autoDestroy: false,
    destroyed: false,
    defaultEncoding: 'utf8',
    awaitDrain: 0,
    readingMore: false,
    decoder: null,
    encoding: null
  },
  readable: true,
  _events: [Object: null prototype] {},
  _eventsCount: 0,
  _maxListeners: undefined,
  _writableState: WritableState {
    objectMode: false,
    highWaterMark: 16384,
    finalCalled: false,
    needDrain: false,
    ending: false,
    ended: false,
    finished: false,
    destroyed: false,
    decodeStrings: true,
    defaultEncoding: 'utf8',
    length: 0,
    writing: false,
    corked: 0,
    sync: true,
    bufferProcessing: false,
    onwrite: [Function (anonymous)],
    writecb: null,
    writelen: 0,
    bufferedRequest: null,
    lastBufferedRequest: null,
    pendingcb: 0,
    prefinished: false,
    errorEmitted: false,
    emitClose: true,
    autoDestroy: false,
    bufferedRequestCount: 0,
    corkedRequestsFree: CorkedRequest {
      next: null,
      entry: null,
      finish: [Function (anonymous)]
    }
  },
  writable: true,
  allowHalfOpen: true,
  [Symbol(kCapture)]: false
}
2023-11-06T21:32:51.832Z mqtt-packet:parser _parsePayload complete result: true
2023-11-06T21:32:51.832Z mqtt-packet:parser parse: state complete. _stateCounter is now: 3
2023-11-06T21:32:51.832Z mqtt-packet:parser parse: packet.length: 0, buffer list length: 0
2023-11-06T21:32:51.832Z mqtt-packet:parser _newPacket
2023-11-06T21:32:51.832Z mqtt-packet:parser _newPacket: parser emit packet: packet.cmd: pingresp, packet.payload: null, packet.length: 0
2023-11-06T21:32:51.832Z mqttjs:client parser :: on packet push to packets array.
2023-11-06T21:32:51.832Z mqtt-packet:parser _newPacket: new packet
2023-11-06T21:32:51.832Z mqtt-packet:parser parse: state complete. _stateCounter is now: 4
2023-11-06T21:32:51.832Z mqtt-packet:parser parse: packet.length: -1, buffer list length: 0
2023-11-06T21:32:51.832Z mqtt-packet:parser parse: exited while loop. packet: -1, buffer list length: 0
2023-11-06T21:32:51.832Z mqttjs:client work :: getting next packet in queue
2023-11-06T21:32:51.832Z mqttjs:client work :: packet pulled from queue
2023-11-06T21:32:51.832Z mqttjs:client _handlePacket :: emitting packetreceive
2023-11-06T21:32:54.247Z follow-redirects options {
  maxRedirects: 21,
  maxBodyLength: Infinity,
  protocol: 'https:',
  path: '/device/rest/devices/v1/list',
  method: 'POST',
  headers: [Object: null prototype] {
    Accept: 'application/json, text/plain, */*',
    'Content-Type': 'application/x-www-form-urlencoded',
    Authorization: 'Bearer ',
    appVersion: '5.6.01',
    clientId: '',
    clientType: '1',
    iotVersion: '0',
    timestamp: '',
    'User-Agent': 'GoveeHome/5.6.01 (com.ihoment.GoVeeSensor; build:2; iOS 16.5.0) Alamofire/5.6.4',
    'Accept-Encoding': 'gzip, compress, deflate, br'
  },
  agents: { http: undefined, https: undefined },
  auth: undefined,
  family: undefined,
  beforeRedirect: [Function: dispatchBeforeRedirect],
  beforeRedirects: { proxy: [Function: beforeRedirect] },
  hostname: 'app2.govee.com',
  port: '',
  agent: undefined,
  nativeProtocols: {
    'http:': {
      _connectionListener: [Function: connectionListener],
      METHODS: [Array],
      STATUS_CODES: [Object],
      Agent: [Function],
      ClientRequest: [Function: ClientRequest],
      IncomingMessage: [Function: IncomingMessage],
      OutgoingMessage: [Function: OutgoingMessage],
      Server: [Function: Server],
      ServerResponse: [Function: ServerResponse],
      createServer: [Function: createServer],
      validateHeaderName: [Function: __node_internal_],
      validateHeaderValue: [Function: __node_internal_],
      get: [Function: get],
      request: [Function: request],
      setMaxIdleHTTPParsers: [Function: setMaxIdleHTTPParsers],
      maxHeaderSize: [Getter],
      globalAgent: [Getter/Setter]
    },
    'https:': {
      Agent: [Function: Agent],
      globalAgent: [Agent],
      Server: [Function: Server],
      createServer: [Function: createServer],
      get: [Function: get],
      request: [Function: request]
    }
  }
}
2023-11-06T21:32:54.948Z mqttjs:client _checkPing :: checking ping...
2023-11-06T21:32:54.949Z mqttjs:client _checkPing :: ping response received. Clearing flag and sending `pingreq`
2023-11-06T21:32:54.949Z mqttjs:client _sendPacket :: (app:d1333b5944e2ff5c7a10a82439fb7935) ::  start
2023-11-06T21:32:54.949Z mqttjs:client _writePacket :: packet: { cmd: 'pingreq' }
2023-11-06T21:32:54.949Z mqttjs:client _writePacket :: emitting `packetsend`
2023-11-06T21:32:54.949Z mqttjs:client _writePacket :: writing to stream
2023-11-06T21:32:54.949Z mqtt-packet:writeToStream generate called
2023-11-06T21:32:54.949Z mqtt-packet:writeToStream generate: packet.cmd: pingreq
2023-11-06T21:32:54.949Z mqttjs:client _writePacket :: writeToStream result true
2023-11-06T21:32:54.949Z mqttjs:client _writePacket :: invoking cb
2023-11-06T21:32:54.949Z mqttjs:client noop :: undefined
2023-11-06T21:32:54.982Z mqttjs:client writable stream :: parsing buffer
2023-11-06T21:32:54.982Z mqtt-packet:parser parse: current state: _parseHeader
2023-11-06T21:32:54.982Z mqtt-packet:parser _parseHeader: packet: Packet { cmd: 'pingresp', retain: false, qos: 0, dup: false, length: -1, topic: null, payload: null }
2023-11-06T21:32:54.983Z mqtt-packet:parser parse: state complete. _stateCounter is now: 1
2023-11-06T21:32:54.983Z mqtt-packet:parser parse: packet.length: -1, buffer list length: 1
2023-11-06T21:32:54.983Z mqtt-packet:parser _parseVarByteNum
2023-11-06T21:32:54.983Z mqtt-packet:parser _parseVarByteNum: result: { bytes: 1, value: 0 }
2023-11-06T21:32:54.983Z mqtt-packet:parser _parseLength 0
2023-11-06T21:32:54.983Z mqtt-packet:parser parse: state complete. _stateCounter is now: 2
2023-11-06T21:32:54.983Z mqtt-packet:parser parse: packet.length: 0, buffer list length: 0
2023-11-06T21:32:54.983Z mqtt-packet:parser _parsePayload: payload BufferListStream {
  _bufs: [],
  length: 0,
  _readableState: ReadableState {
    objectMode: false,
    highWaterMark: 16384,
    buffer: BufferList { head: null, tail: null, length: 0 },
    length: 0,
    pipes: null,
    pipesCount: 0,
    flowing: null,
    ended: false,
    endEmitted: false,
    reading: false,
    sync: true,
    needReadable: false,
    emittedReadable: false,
    readableListening: false,
    resumeScheduled: false,
    paused: true,
    emitClose: true,
    autoDestroy: false,
    destroyed: false,
    defaultEncoding: 'utf8',
    awaitDrain: 0,
    readingMore: false,
    decoder: null,
    encoding: null
  },
  readable: true,
  _events: [Object: null prototype] {},
  _eventsCount: 0,
  _maxListeners: undefined,
  _writableState: WritableState {
    objectMode: false,
    highWaterMark: 16384,
    finalCalled: false,
    needDrain: false,
    ending: false,
    ended: false,
    finished: false,
    destroyed: false,
    decodeStrings: true,
    defaultEncoding: 'utf8',
    length: 0,
    writing: false,
    corked: 0,
    sync: true,
    bufferProcessing: false,
    onwrite: [Function (anonymous)],
    writecb: null,
    writelen: 0,
    bufferedRequest: null,
    lastBufferedRequest: null,
    pendingcb: 0,
    prefinished: false,
    errorEmitted: false,
    emitClose: true,
    autoDestroy: false,
    bufferedRequestCount: 0,
    corkedRequestsFree: CorkedRequest {
      next: null,
      entry: null,
      finish: [Function (anonymous)]
    }
  },
  writable: true,
  allowHalfOpen: true,
  [Symbol(kCapture)]: false
}
2023-11-06T21:32:54.983Z mqtt-packet:parser _parsePayload complete result: true
2023-11-06T21:32:54.983Z mqtt-packet:parser parse: state complete. _stateCounter is now: 3
2023-11-06T21:32:54.983Z mqtt-packet:parser parse: packet.length: 0, buffer list length: 0
2023-11-06T21:32:54.983Z mqtt-packet:parser _newPacket
2023-11-06T21:32:54.983Z mqtt-packet:parser _newPacket: parser emit packet: packet.cmd: pingresp, packet.payload: null, packet.length: 0
2023-11-06T21:32:54.983Z mqttjs:client parser :: on packet push to packets array.
2023-11-06T21:32:54.983Z mqtt-packet:parser _newPacket: new packet
2023-11-06T21:32:54.984Z mqtt-packet:parser parse: state complete. _stateCounter is now: 4
2023-11-06T21:32:54.984Z mqtt-packet:parser parse: packet.length: -1, buffer list length: 0
2023-11-06T21:32:54.984Z mqtt-packet:parser parse: exited while loop. packet: -1, buffer list length: 0
2023-11-06T21:32:54.984Z mqttjs:client work :: getting next packet in queue
2023-11-06T21:32:54.984Z mqttjs:client work :: packet pulled from queue
2023-11-06T21:32:54.984Z mqttjs:client _handlePacket :: emitting packetreceive
[11/6/2023, 4:32:57 PM] [Apple TV Enhanced] Python check: Pip is up-to-date
[11/6/2023, 4:32:58 PM] [Apple TV Enhanced] Python check: Python requirements are satisfied.
[11/6/2023, 4:32:58 PM] [Apple TV Enhanced] Python check: Finished
[11/6/2023, 4:32:58 PM] [Apple TV Enhanced] Platform: Starting device discovery ...
[11/6/2023, 4:33:04 PM] [Apple TV Enhanced] Platform: Adding Apple TV Living Room (9C:3E:53:28:EF:07)
[11/6/2023, 4:33:04 PM] [Apple TV Enhanced] Platform: Adding Apple TV Play Room (50:DE:06:9C:BE:67)
[11/6/2023, 4:33:04 PM] [Apple TV Enhanced] Play Room (50:DE:06:9C:BE:67): You need to pair your Apple TV before the plugin can connect to it. Enter the PIN that is currently displayed on the device here: http://192.168.7.138:42068/
[11/6/2023, 4:33:07 PM] [Apple TV Enhanced] Living Room (9C:3E:53:28:EF:07): Credentials are still valid. Continuing ...
[Apple TV Living Room@@Firmware Revision] Characteristic not in required or optional characteristic section for service Television. Adding anyway.
2023-11-06T21:33:07.400Z HAP-NodeJS:Accessory [Apple TV Living Room] Above characteristic warning was thrown at: unknown
[Apple TV Living Room@paused@Configured Name] Characteristic not in required or optional characteristic section for service MotionSensor. Adding anyway.
2023-11-06T21:33:07.406Z HAP-NodeJS:Accessory [Apple TV Living Room] Above characteristic warning was thrown at: unknown
[Apple TV Living Room@playing@Configured Name] Characteristic not in required or optional characteristic section for service MotionSensor. Adding anyway.
2023-11-06T21:33:07.409Z HAP-NodeJS:Accessory [Apple TV Living Room] Above characteristic warning was thrown at: unknown
2023-11-06T21:33:08.128Z HAP-NodeJS:EventedHTTPServer:Connection [::ffff:192.168.7.249] HTTP request: /characteristics?id=1.7
2023-11-06T21:33:08.128Z HAP-NodeJS:HAPServer [0E:CE:5D:87:72:B1] HAP Request: GET /characteristics?id=1.7
2023-11-06T21:33:08.129Z HAP-NodeJS:Accessory [Homebridge 72B1 B900] Got Characteristic "Firmware Revision" value: "1.7.0"
2023-11-06T21:33:08.131Z HAP-NodeJS:EventedHTTPServer:Connection [::ffff:192.168.7.249] HTTP Response is finished
[11/6/2023, 4:33:08 PM] [Apple TV Enhanced] Play Room (50:DE:06:9C:BE:67): Apple TV Play Room: Too many attempts. Waiting for 4902 seconds before retrying.
[11/6/2023, 4:33:09 PM] [Apple TV Enhanced] Apple TV Living Room (9C:3E:53:28:EF:07): 
The maximum of 100 on a single accessory is reached. The following services have been added:
- The television service (Apple TV) itself
- 2 motion sensors for device states 
- 0 motion sensors for media types 
- 0 switches for remote keys 
- 96 apps have been added (28 apps could not be added)
It might be a good idea to uninstall unused apps.
[11/6/2023, 4:33:09 PM] [Apple TV Enhanced] Apple TV Living Room (9C:3E:53:28:EF:07): Finished initializing
Error: Cannot add more than 100 services to a single accessory!
    at Accessory.addService (/var/lib/homebridge/node_modules/homebridge/node_modules/hap-nodejs/src/lib/Accessory.ts:564:13)
    at Accessory.<anonymous> (/var/lib/homebridge/node_modules/homebridge/node_modules/hap-nodejs/src/lib/Accessory.ts:1221:22)
    at step (/var/lib/homebridge/node_modules/homebridge/node_modules/tslib/tslib.js:195:27)
    at Object.next (/var/lib/homebridge/node_modules/homebridge/node_modules/tslib/tslib.js:176:57)
    at /var/lib/homebridge/node_modules/homebridge/node_modules/tslib/tslib.js:169:75
    at new Promise (<anonymous>)
    at Object.__awaiter (/var/lib/homebridge/node_modules/homebridge/node_modules/tslib/tslib.js:165:16)
    at Accessory.publish (/var/lib/homebridge/node_modules/homebridge/node_modules/hap-nodejs/dist/lib/Accessory.js:928:24)
    at BridgeService.handlePublishExternalAccessories (/var/lib/homebridge/node_modules/homebridge/src/bridgeService.ts:456:20)
    at processTicksAndRejections (node:internal/process/task_queues:95:5)
[11/6/2023, 4:33:09 PM] [Apple TV Enhanced] Child bridge process ended
[11/6/2023, 4:33:09 PM] [Apple TV Enhanced] Process Ended. Code: 1, Signal: null
2023-11-06T21:33:10.159Z engine.io-client:socket socket receive: type "ping", data "undefined"
2023-11-06T21:33:10.159Z engine.io-client:socket writing ping packet - expecting pong within 60000ms
2023-11-06T21:33:10.160Z engine.io-client:socket flushing 1 packets in socket
2023-11-06T21:33:10.192Z engine.io-client:socket socket receive: type "pong", data "undefined"
maxileith commented 1 year ago

Okay, because I wouldn't believe, I installed myself many apps. It turns out that the limit is 99, not 100. Weird but now it should work in version v0.3.2-beta.5. Can you please confirm if it works on your side as well?

Maybe it has something to do with the Apple TV being an external accessory ...

ryanmaule commented 1 year ago

I think everything is working perfectly now - great work!

Have you considered an option to enable/disable using apps as states for the appletv device? I suppose I can just manually uncheck them all.

maxileith commented 1 year ago

Thank you for the feedback.

Yes, you need to uncheck all apps in the Home app. My credo is to always prefer native HomeKit configuration style over the homebridge configuration if possible. That is why I won't provide a homebridge configuration option for that.

Closing the issue as it seems to be resolved.