chore: add HKSV-DEBUG diagnostic logging for issue #3928

Author: bwp91

CHANGELOG.md

@@ -2,6 +2,18 @@
 
 All notable changes to `@homebridge/hap-nodejs` will be documented in this file. This project tries to adhere to [Semantic Versioning](http://semver.org/).
 
+## v2.1.6 (Pending Release)
+
+### Changes
+
+- chore: add HKSV-DEBUG diagnostic logging for issue #3928
+
+### Homebridge Dependencies
+
+- `@homebridge/ciao` @ `v1.3.8`
+- `@homebridge/dbus-native` @ `v0.7.5`
+- `bonjour-hap` @ `v3.10.2`
+
 ## v2.1.5 (2026-05-05)
 
 ### Changes

src/lib/Accessory.ts

@@ -434,7 +434,7 @@ export class Accessory extends EventEmitter {
   /**
    * @private Private API.
    */
-  controllerStorage: ControllerStorage = new ControllerStorage(this);
+  controllerStorage!: ControllerStorage;
   /**
    * @private Private API.
    */
@@ -462,6 +462,8 @@ export class Accessory extends EventEmitter {
     assert(uuid.isValid(UUID), "UUID '" + UUID + "' is not a valid UUID. Try using the provided 'generateUUID' function to create a " +
       "valid UUID from any arbitrary string, like a serial number.");
 
+    this.controllerStorage = new ControllerStorage(this);
+
     // create our initial "Accessory Information" Service that all Accessories are expected to have
     checkName(this.displayName, "Name", displayName);
     this.addService(Service.AccessoryInformation)
@@ -1107,7 +1109,12 @@ export class Accessory extends EventEmitter {
     }
     service.setCharacteristic(Characteristic.Version, CiaoAdvertiser.protocolVersionService);
 
+    console.log("[HKSV-DEBUG] Accessory.publish: name=%s UUID=%s lastKnownUsername=%s info.username=%s willCleanup=%s",
+      this.displayName, this.UUID, this.lastKnownUsername, info.username,
+      !!(this.lastKnownUsername && this.lastKnownUsername !== info.username));
+
     if (this.lastKnownUsername && this.lastKnownUsername !== info.username) { // username changed since last publish
+      console.log("[HKSV-DEBUG] Accessory.publish: WIPING old data for username %s (changed to %s)", this.lastKnownUsername, info.username);
       Accessory.cleanupAccessoryData(this.lastKnownUsername); // delete old Accessory data
     }
 

src/lib/camera/RecordingManagement.ts

@@ -609,6 +609,13 @@ export class RecordingManagement {
 
     const changed = this.selectedConfiguration?.base64 !== value;
 
+    console.log(
+      "[HKSV-DEBUG] handleSelectedCameraRecordingConfigurationWrite: HomeKit pushed selectedConfig (changed=%s, hasStateChangeDelegate=%s, base64Len=%d)",
+      changed,
+      !!this.stateChangeDelegate,
+      typeof value === "string" ? value.length : -1,
+    );
+
     this.selectedConfiguration = {
       parsed: configuration,
       base64: value,
@@ -836,13 +843,24 @@ export class RecordingManagement {
 
     // we only restore the `selectedConfiguration` if our supported configuration hasn't changed.
     const currentConfigurationHash = this.computeConfigurationHash(serialized.configurationHash.algorithm);
+
+    console.log("[HKSV-DEBUG] RecordingManagement.deserialize: hasSavedSelectedConfig=%s, savedHash=%s, currentHash=%s, hashMatch=%s, recordingActive=%s",
+      !!serialized.selectedConfiguration,
+      serialized.configurationHash?.hash?.slice(0, 12),
+      currentConfigurationHash.slice(0, 12),
+      currentConfigurationHash === serialized.configurationHash?.hash,
+      serialized.recordingActive);
+
     if (serialized.selectedConfiguration) {
       if (currentConfigurationHash === serialized.configurationHash.hash) {
         this.selectedConfiguration = {
           base64: serialized.selectedConfiguration,
           parsed: this.parseSelectedConfiguration(serialized.selectedConfiguration),
         };
       } else {
+        console.log(
+          "[HKSV-DEBUG] RecordingManagement.deserialize: DISCARDING saved selectedConfiguration — supportedConfiguration hash changed since last run",
+        );
         changedState = true;
       }
     }
@@ -861,7 +879,10 @@ export class RecordingManagement {
 
     try {
       if (this.selectedConfiguration) {
+        console.log("[HKSV-DEBUG] RecordingManagement.deserialize: REPLAYING updateRecordingConfiguration to delegate");
         this.delegate.updateRecordingConfiguration(this.selectedConfiguration.parsed);
+      } else {
+        console.log("[HKSV-DEBUG] RecordingManagement.deserialize: NOT calling updateRecordingConfiguration (no selectedConfiguration to restore)");
       }
       if (serialized.recordingActive) {
         this.delegate.updateRecordingActive(serialized.recordingActive);

src/lib/model/ControllerStorage.ts

@@ -102,6 +102,9 @@ export class ControllerStorage {
   public trackController(controller: SerializableController): void {
     controller.setupStateChangeDelegate(this.handleStateChange.bind(this, controller)); // setup delegate
 
+    console.log("[HKSV-DEBUG] ControllerStorage.trackController: accUUID=%s ctrlId=%s initialized=%s",
+      this.accessoryUUID, controller.controllerId(), this.initialized);
+
     if (!this.initialized) { // track controller if data isn't loaded yet
       this.trackedControllers.push(controller);
     } else {
@@ -132,6 +135,9 @@ export class ControllerStorage {
     const id = controller.controllerId();
     const serialized = controller.serialize();
 
+    console.log("[HKSV-DEBUG] ControllerStorage.handleStateChange: accUUID=%s ctrlId=%s hasSerialized=%s initialized=%s hasParent=%s",
+      this.accessoryUUID, id, !!serialized, this.initialized, !!this.parent);
+
     if (!serialized) { // can be undefined when controller wishes to delete data
       delete this.controllerData[id];
     } else {
@@ -150,6 +156,8 @@ export class ControllerStorage {
       // run save data "async", as handleStateChange call will probably always be caused by a http request
       // this should improve our response time
       this.enqueueSaveRequest(100);
+    } else {
+      console.log("[HKSV-DEBUG] ControllerStorage.handleStateChange: NOT enqueuing save — storage not yet initialized (acc %s)", this.accessoryUUID);
     }
   }
 
@@ -160,6 +168,10 @@ export class ControllerStorage {
     }
 
     const controllerData = this.controllerData[controller.controllerId()];
+
+    console.log("[HKSV-DEBUG] ControllerStorage.restoreController: accUUID=%s ctrlId=%s hasStoredData=%s",
+      this.accessoryUUID, controller.controllerId(), !!controllerData);
+
     if (controllerData) {
       try {
         controller.deserialize(controllerData.data);
@@ -230,6 +242,14 @@ export class ControllerStorage {
       delete saved.accessories[this.accessoryUUID];
     }
 
+    console.log("[HKSV-DEBUG] ControllerStorage.load: username=%s key=%s fileExisted=%s thisAccUUID=%s ownDataEntries=%s otherAccUUIDsInFile=%j",
+      username,
+      key,
+      !!saved,
+      this.accessoryUUID,
+      ownData ? ownData.length : "none",
+      saved ? Object.keys(saved.accessories) : []);
+
     this.init(ownData);
 
     if (this.linkedAccessories) {
@@ -291,9 +311,15 @@ export class ControllerStorage {
         accessories: accessoryData,
       };
 
+      console.log("[HKSV-DEBUG] ControllerStorage.save: WRITE %s — accUUIDs=%j ctrlIdsPerAcc=%j",
+        key,
+        Object.keys(accessoryData),
+        Object.fromEntries(Object.entries(accessoryData).map(([acc, entries]) => [acc, entries.map(e => e.type)])));
+
       this.fileCreated = true;
       HAPStorage.storage().setItemSync(key, saved);
     } else if (this.fileCreated) {
+      console.log("[HKSV-DEBUG] ControllerStorage.save: REMOVE %s (no controller data left)", key);
       this.fileCreated = false;
       HAPStorage.storage().removeItemSync(key);
     }