From 3cfc3f68b09700be111b3fd5d3b14049f3fb5b5d Mon Sep 17 00:00:00 2001 From: Darell Tan Date: Thu, 3 Aug 2023 21:32:14 +0800 Subject: [PATCH] Added debug mode for more verbose logging Also had to rename the existing DEBUG consts to DEVMODE, so as to not confuse the two. DEVMODE is meant for developers and cannot be enabled on-the-fly, whereas debug mode is for users to check that the bridge is working, MQTT messages are received etc. Update logging is throttled to avoid spurious messages for uncoalesced MQTT updates and motion sensors. On my network with 10 devices, an update is logged every 1-2 minutes on average. --- bridge.go | 56 +++++++++++++++++++++++++++++++++++----------- cmd/hapz2m/main.go | 2 ++ z2m.go | 7 +++--- 3 files changed, 49 insertions(+), 16 deletions(-) diff --git a/bridge.go b/bridge.go index 783c634..1c70818 100644 --- a/bridge.go +++ b/bridge.go @@ -4,8 +4,13 @@ import ( "github.com/brutella/hap" "github.com/brutella/hap/accessory" + haplog "github.com/brutella/hap/log" + mqtt "github.com/eclipse/paho.mqtt.golang" + "crypto/tls" + "net/url" + "context" "encoding/json" "fmt" @@ -37,7 +42,8 @@ const ( Z2M_LAST_SEEN_TIMEOUT = 24 * time.Hour ) -const BRIDGE_DEBUG = false +// show more messages for developers +const BRIDGE_DEVMODE = false type Bridge struct { // MQTT broker and credentials @@ -45,6 +51,8 @@ type Bridge struct { Username string Password string + DebugMode bool + ctx context.Context bridgeAcc *accessory.Bridge @@ -110,6 +118,10 @@ func (br *Bridge) StartHAP() error { return err } + if br.DebugMode { + haplog.Debug.Enable() + } + err = br.server.ListenAndServe(br.ctx) // disconnect from MQTT @@ -158,6 +170,11 @@ func (br *Bridge) ConnectMQTT() error { log.Printf("subscribed to MQTT topic") }) + opts.SetConnectionAttemptHandler(func(broker *url.URL, cfg *tls.Config) *tls.Config { + log.Printf("connecting to MQTT %s...", broker) + return cfg + }) + br.mqttClient = mqtt.NewClient(opts) if tok := br.mqttClient.Connect(); tok.Wait() && tok.Error() != nil { @@ -183,6 +200,10 @@ func (br *Bridge) loadZ2MState(m *sync.Map) error { } for k, v := range stateMap { + if BRIDGE_DEVMODE { + log.Printf("%s %s\n", k, v) + } + // add a last_seen timestamp for saved states without one var devState map[string]any err = json.Unmarshal(v, &devState) @@ -263,8 +284,6 @@ func (br *Bridge) saveZ2MState() error { func (br *Bridge) handleMqttMessage(_ mqtt.Client, msg mqtt.Message) { topic, payload := msg.Topic(), msg.Payload() - //log.Printf("received %s %s", topic, payload) - // check for topic prefix and remove it l := len(MQTT_TOPIC_PREFIX) if len(topic) <= l || topic[:l] != MQTT_TOPIC_PREFIX { @@ -288,12 +307,18 @@ func (br *Bridge) handleMqttMessage(_ mqtt.Client, msg mqtt.Message) { // spawn a goroutine to handle message, since mutex might block go func() { + if br.DebugMode { + log.Printf("received %s: %s", topic, payload) + } + br.hapInitMutex.RLock() defer br.hapInitMutex.RUnlock() + isBridgeTopic := strings.HasPrefix(topic, "bridge/") + // check if HAP bridge device has been initialized if !br.hapInitDone { - if strings.HasPrefix(topic, "bridge/") { + if isBridgeTopic { // need to look out for bridge/devices for intiial setup if topic == "bridge/devices" { err := br.AddDevicesFromJSON(payload) @@ -332,7 +357,7 @@ func (br *Bridge) handleMqttMessage(_ mqtt.Client, msg mqtt.Message) { log.Printf("queueing updates for %s", topic) br.pendingUpdates.Store(topic, payload) } - } else { + } else if !isBridgeTopic { br.UpdateAccessoryState(topic, payload) } }() @@ -456,14 +481,16 @@ func (br *Bridge) UpdateZ2MState(dev *Device, mapping *ExposeMapping, newVal any ctx, cancel := context.WithTimeout(br.ctx, Z2M_UPDATE_TIMEOUT) defer cancel() - log.Printf("updating Z2M state %q -> %+v", prop, expVal) + if br.DebugMode { + log.Printf("updating Z2M state %q -> %+v", prop, expVal) + } br.PublishState(dev, map[string]any{prop: expVal}) wait: for { select { case updatedVal := <-ch: - if BRIDGE_DEBUG { + if BRIDGE_DEVMODE { log.Printf("received value %q (expected %q) for %s", updatedVal, expVal, key) } if updatedVal == expVal || @@ -507,8 +534,8 @@ func (br *Bridge) PublishState(dev *Device, payload map[string]any) error { return err } - if BRIDGE_DEBUG { - log.Printf("publishing %q payload %s", topic, jsonPayload) + if br.DebugMode { + log.Printf("publishing %s: %s", topic, jsonPayload) } br.mqttClient.Publish(topic, 0, false, jsonPayload) @@ -519,12 +546,15 @@ func (br *Bridge) PublishState(dev *Device, payload map[string]any) error { func (br *Bridge) UpdateAccessoryState(devName string, payload []byte) { dev := br.devices[devName] if dev == nil { + if br.DebugMode || BRIDGE_DEVMODE { + log.Printf("unknown device %q", devName) + } + // skip unknown device - //log.Printf("unknown device %q", devName) return } - if BRIDGE_DEBUG { + if br.DebugMode || time.Since(dev.LastSeen) > 30*time.Second { log.Printf("received update for device %q", devName) } @@ -567,7 +597,7 @@ func (br *Bridge) UpdateAccessoryState(devName string, payload []byte) { if mapping.ExposesEntry.IsSettable() { updateKey := makeUpdateKey(dev.Device, mapping) if ch, waiting := br.updateListeners.Load(updateKey); waiting { - if BRIDGE_DEBUG { + if BRIDGE_DEVMODE { log.Printf("sending new value for %q via chan", updateKey) } select { @@ -582,7 +612,7 @@ func (br *Bridge) UpdateAccessoryState(devName string, payload []byte) { } // update value into Characteristic - if BRIDGE_DEBUG { + if BRIDGE_DEVMODE { log.Printf("updating %q to %+v", prop, newVal) } _, errCode := mapping.SetCharacteristicValue(newVal) diff --git a/cmd/hapz2m/main.go b/cmd/hapz2m/main.go index 8497558..c084122 100644 --- a/cmd/hapz2m/main.go +++ b/cmd/hapz2m/main.go @@ -26,6 +26,7 @@ var ( var ( configFile = flag.String("config", "/etc/hapz2m.conf", "config file") dbPath = flag.String("db", "/var/lib/hapz2m", "db path") + debugMode = flag.Bool("debug", false, "enable debug messages") ) type config struct { @@ -70,6 +71,7 @@ func main() { br.Server = cfg.Server br.Username = cfg.Username br.Password = cfg.Password + br.DebugMode = *debugMode err = br.ConnectMQTT() if err != nil { diff --git a/z2m.go b/z2m.go index 552bcb0..7aeaa86 100644 --- a/z2m.go +++ b/z2m.go @@ -13,7 +13,8 @@ import ( "github.com/brutella/hap/service" ) -const Z2M_DEBUG = false +// show more messages for developers +const Z2M_DEVMODE = false // exposed properties to ignore var IgnoreProperties = map[string]bool{ @@ -47,7 +48,7 @@ func createAccessory(dev *Device) (*accessory.A, []*ExposeMapping, error) { return nil, nil, ErrMalfomedDevice } - if Z2M_DEBUG { + if Z2M_DEVMODE { fmt.Printf("%s %s %d\n", dev.Definition.Model, dev.Definition.Vendor, dev.NetworkAddress) for _, exp := range dev.Definition.Exposes { ignored := "" @@ -90,7 +91,7 @@ func createAccessory(dev *Device) (*accessory.A, []*ExposeMapping, error) { panic(err) } - if Z2M_DEBUG { + if Z2M_DEVMODE { f := runtime.FuncForPC(reflect.ValueOf(createFunc).Pointer()) fmt.Printf("----- %s -----\n", f.Name())