Log entries seem impossible based on code - no errors but code flow doesn't make sense

🚧 Developers Broken-code
1

2.2.5.119 C4

@bobbyD

I was learning the details of the attached code. Toward that end I added some additional log entries.
For ease of reading the logs, at the entry of every message to parse I log an underline "_"
I also added the code line numbers to the debug description.

When I started to look at the logs in depth I found some entries that didn't follow the code (as I understand it).
Specifically the area circled on the log screenshot.
The _ is logged indicating a new message has entered the Parse code.
Then a line 28 message.
Then another _ is logged. This would mean the " if (description?.startsWith('read attr -')) was false. But the data shows that not to be the case. And if it was simply the if (description?.startsWith('read attr -')) was false then the else at line 41 would fire but it didn't log.

So are the active debug lines 100% correct, OR I'm missing something.

// Zigbee Basic Parse - good for investigating the parsed map information

// 2021-01-27 - successfully parses additionaAttr
metadata
{
definition(name: "Zigbee Basic", namespace: "johnrob", author: "johnr")
{
capability "Actuator"
capability "Sensor"
capability "Configuration"
capability "Temperature Measurement"
capability "PressureMeasurement"
capability "Relative Humidity Measurement"
}
preferences
{
section
{
//input "enableTrace", "bool", title: "Enable trace logging?", description: "Show high-level activities during the operation of the device?", defaultValue: false, required: false, multiple: false
//input "enableDebug", "bool", title: "Enable debug logging?", description: "Show detailed responses to device commands?", defaultValue: false, required: false, multiple: false
}
}
} // --- metadata ---

def parse(String description)
{
log.debug " _"
log.debug " 28 Raw Description#$description"

if (description?.startsWith('read attr -')){
	def descMap = zigbee.parseDescriptionAsMap(description)
	log.debug " 32 descMap#$descMap"

    def otherAttrs =descMap?.additionalAttrs
    log.debug " 35 other Attrs#${otherAttrs}"
    otherAttrs.each{
        log.debug " 37 addAttrs#${it}"
        log.debug " 38 addAttrs_Val#${it.value}"
    }
} else {
    log.debug " 41 no read attr -"
}

} // --- parse ---

image
image1708×566 114 KB

2

There's no guarantee to the "order" of logging, so logging can get jumbled around so the entries don't appear to follow in the right order.

This happens a lot in fast flowing ZigBee networks where you might have multiple instances of a driver running concurrently.

For example if a device sends several attribute reports within a few milliseconds you can get multiple instances of parse() running simultaneously, all vying to write to the log.

Your screenshot shows two instances of parse() running, both log "_" to begin with, each followed by "RawDescription....", then the next log messages from the if() statement are above those ("32 descMap....").

A little further up is another "_" from another parse(), but then you've got "35 other Attrs...." from one of the first parse().

And so on.... hope that explanation makes sense!

1 Like
3

It makes perfect sense. I didn't even consider concurrent instances. Or know there were possible.

Thanks for the info.

John