Add detailed logging for adapter initialisation.

shimmeringbee · Nov 24, 2021 · df01c96 · df01c96
1 parent f73efc8
commit df01c96
Showing 1 changed file with 18 additions and 1 deletion.
diff --git a/adapter_initialise.go b/adapter_initialise.go
@@ -4,6 +4,7 @@ import (
 	"context"
 	"errors"
 	"fmt"
+	"github.com/shimmeringbee/logwrap"
 	"github.com/shimmeringbee/retry"
 	"github.com/shimmeringbee/zigbee"
 	"golang.org/x/sync/semaphore"
@@ -137,34 +138,43 @@ func (z *ZStack) configureNetwork(ctx context.Context, version Version) error {
 
 	if err := retryFunctions(ctx, []func(context.Context) error{
 		func(invokeCtx context.Context) error {
+			z.logger.LogDebug(ctx, "Adapater Initialisation: Enabling preconfigured keys.")
 			return z.writeNVRAM(invokeCtx, ZCDNVPreCfgKeysEnable{Enabled: 1})
 		},
 		func(invokeCtx context.Context) error {
+			z.logger.LogDebug(ctx, "Adapater Initialisation: Configuring network key.")
 			return z.writeNVRAM(invokeCtx, ZCDNVPreCfgKey{NetworkKey: z.NetworkProperties.NetworkKey})
 		},
 		func(invokeCtx context.Context) error {
+			z.logger.LogDebug(ctx, "Adapater Initialisation: Enable ZDO callbacks.")
 			return z.writeNVRAM(invokeCtx, ZCDNVZDODirectCB{Enabled: 1})
 		},
 		func(invokeCtx context.Context) error {
+			z.logger.LogDebug(ctx, "Adapater Initialisation: Configuring network channel.")
 			return z.writeNVRAM(invokeCtx, ZCDNVChanList{Channels: channelBits})
 		},
 		func(invokeCtx context.Context) error {
+			z.logger.LogDebug(ctx, "Adapater Initialisation: Configuring network PANID.")
 			return z.writeNVRAM(invokeCtx, ZCDNVPANID{PANID: z.NetworkProperties.PANID})
 		},
 		func(invokeCtx context.Context) error {
+			z.logger.LogDebug(ctx, "Adapater Initialisation: Configuring network extended PANID.")
 			return z.writeNVRAM(invokeCtx, ZCDNVExtPANID{ExtendedPANID: z.NetworkProperties.ExtendedPANID})
 		},
 	}); err != nil {
 		return err
 	}
 
 	if !version.IsV3() {
+		z.logger.LogDebug(ctx, "Adapater Initialisation: Not Version 3.X.X.")
 		/* Less than Z-Stack 3.X.X requires the Trust Centre key to be loaded. */
 		return retryFunctions(ctx, []func(context.Context) error{
 			func(invokeCtx context.Context) error {
+				z.logger.LogDebug(ctx, "Adapater Initialisation: Enable default trust center.")
 				return z.writeNVRAM(invokeCtx, ZCDNVUseDefaultTCLK{Enabled: 1})
 			},
 			func(invokeCtx context.Context) error {
+				z.logger.LogDebug(ctx, "Adapater Initialisation: Configuring ZLL trust center key.")
 				return z.writeNVRAM(invokeCtx, ZCDNVTCLKTableStart{
 					Address:        zigbee.IEEEAddress(0xffffffffffffffff),
 					NetworkKey:     zigbee.TCLinkKey,
@@ -175,26 +185,32 @@ func (z *ZStack) configureNetwork(ctx context.Context, version Version) error {
 		})
 	} else {
 		/* Z-Stack 3.X.X requires configuration of Base Device Behaviour. */
+		z.logger.LogDebug(ctx, "Adapater Initialisation: Version 3.X.X.")
 		if err := retryFunctions(ctx, []func(context.Context) error{
 			func(invokeCtx context.Context) error {
+				z.logger.LogDebug(ctx, "Adapater Initialisation: Configure primary channel.")
 				return z.requestResponder.RequestResponse(ctx, APPCNFBDBSetChannelRequest{IsPrimary: true, Channel: channelBits}, &APPCNFBDBSetChannelRequestReply{})
 			},
 			func(invokeCtx context.Context) error {
+				z.logger.LogDebug(ctx, "Adapater Initialisation: Configure secondary channels.")
 				return z.requestResponder.RequestResponse(ctx, APPCNFBDBSetChannelRequest{IsPrimary: false, Channel: [4]byte{}}, &APPCNFBDBSetChannelRequestReply{})
 			},
 			func(invokeCtx context.Context) error {
+				z.logger.LogDebug(ctx, "Adapater Initialisation: Request commissioning.")
 				return z.requestResponder.RequestResponse(ctx, APPCNFBDBStartCommissioningRequest{Mode: 0x04}, &APPCNFBDBStartCommissioningRequestReply{})
 			},
 		}); err != nil {
 			return err
 		}
 
+		z.logger.LogDebug(ctx, "Adapater Initialisation: Waiting for coordinator to start.")
 		if err := z.waitForCoordinatorStart(ctx); err != nil {
 			return err
 		}
 
 		return retryFunctions(ctx, []func(context.Context) error{
 			func(invokeCtx context.Context) error {
+				z.logger.LogDebug(ctx, "Adapater Initialisation: Waiting for commissioning to complete.")
 				return z.requestResponder.RequestResponse(ctx, APPCNFBDBStartCommissioningRequest{Mode: 0x02}, &APPCNFBDBStartCommissioningRequestReply{})
 			},
 		})
@@ -238,7 +254,7 @@ func (z *ZStack) startZigbeeStack(ctx context.Context, version Version) error {
 
 	err, cancel := z.subscriber.Subscribe(&ZDOStateChangeInd{}, func(v interface{}) {
 		stateChange := v.(*ZDOStateChangeInd)
-
+		z.logger.LogDebug(ctx, "Waiting for zigbee stack to start, state change.", logwrap.Datum("State", stateChange.State), logwrap.Datum("DesiredState", DeviceZBCoordinator))
 		if stateChange.State == DeviceZBCoordinator {
 			ch <- true
 		}
@@ -263,6 +279,7 @@ func (z *ZStack) waitForCoordinatorStart(ctx context.Context) error {
 
 	err, cancel := z.subscriber.Subscribe(&ZDOStateChangeInd{}, func(v interface{}) {
 		stateChange := v.(*ZDOStateChangeInd)
+		z.logger.LogDebug(ctx, "Waiting for coordinator start, state change.", logwrap.Datum("State", stateChange.State), logwrap.Datum("DesiredState", DeviceZBCoordinator))
 		if stateChange.State == DeviceZBCoordinator {
 			ch <- true
 		}