Question Regarding timing of events in logs

[2.3.2.118] [C7]

I have a Temperature / Humidity sensor that sends out Temperature and Humidity in separate messages.

In the log below the parsing of Temperature is "data Units C"
And the parsing of Humidity is "data Units %"

If I take the log timing literally it shows sometimes the both "raw" messages are received before either message is parsed.

I'm assuming there is a buffer for inputted messages and/or the timing on the logs is not perfect.

Is this normal or could be something wrong I should look into?

BTW the driver is pretty simple:

  • Receive a message
  • Parse it
  • send event

A link to or snippet of the code may help people help you with what is happening. I take it from your post that you developed / are developing the driver?

Thank you for looking...

Below is the current code. There are issues with the MaxMin code but the basic parse code could be taken from almost any sensor (so I think).

My question is: are the logs indicating something is unstable in the timing or is that just how it is.

metadata {

    definition(name: "SHT30 Zigbee Test 4.2", namespace: "johnrob", author: "johnr")
    {
        capability "Actuator"
        capability "Sensor"
        capability "Initialize"			// runs at restart!

        capability "TemperatureMeasurement"
        capability "RelativeHumidityMeasurement"

        attribute "DewPoint", "string"

        fingerprint profileId: "0104", inClusters: "0000", outClusters: "0000, 0B05, 0006"     // per PTVO firmware.

    }
    preferences{
        input name: "logEnable", type: "bool", title: "Enable debug logging", defaultValue: false
        input name: "logTrace", type: "bool", title: "Enable trace logging", defaultValue: false
        input name: "unitsDegC", type: "enum", title: "Temperature Units", options: ["1":"°C","0":"°F"], defaultValue: 1, required: false
    }
} //  --- metadata ---


def parse(String description){

    if (logEnable)  log.info "  Raw Description=  $description"

    if (description?.startsWith('read attr -')){        // in testing all messages are 'read attr -''

        def descMap = zigbee.parseDescriptionAsMap(description)
     //   if (logEnable) log.info ("   descMap=  $descMap")

        if (descMap.cluster == "000C" && descMap.attrId == "0055"){     // zigbee spec 0x000C= read analog cluster  0x0055 = present value
                                                                        // in our testing all messages are 000C and 0055
            SHThexData = descMap.value
            float SensorValue = ConvertHexToFloat(SHThexData)
            def otherAttrs = descMap?.additionalAttrs
            otherAttrs.each{
                SHTunitaddress = it.value
            }
            def (SHTunits, SHTaddress) = SHTunitaddress.tokenize( ',' )   //   <--- units and I2C address
    if (logEnable) log.info " data Units  ${SHTunits}"
            if (SHTunits == "C"){
                if (tempUnits == "0"){
                    fSensorValue = celsiusToFahrenheit(SensorValue)
                    fSensorValue = Math.round(fSensorValue*10)/10  
                    updateMaxMin(fSensorValue)
                    sendEvent(name: "temperature", value: fSensorValue , unit:"F", isStateChange: true)
                }
                else {

                	cSensorValue = Math.round(SensorValue*10)/10
                	updateMaxMin(cSensorValue)
                    sendEvent(name: "temperature", value: cSensorValue , unit:"C", isStateChange: true)
                }
            }
            if (SHTunits == "%"){
                intermediate = SensorValue
            	hSensorValue = Math.round(SensorValue/10)*10
                sendEvent(name: "humidity", value: hSensorValue, unit:"%", isStateChange: true)
            }
			//log.info (" xxxxx deviceValue  ${device.currentValue("temperature")} ")

/*            
            // --- DewPoint --------------------------------------------------------------------
         //  Td = T - ((100 - RH)/5)  where T and Td are in °C
            if (logEnable) log.info (" SensorValue ${SensorValue}")
            if (logEnable) log.info (" intermediate  ${intermediate}")
            
      		float cDewPoint = SensorValue + ((100 - intermediate)/5)
            cDewPoint = Math.round(cDewPoint)
         	if (tempUnits == "0"){			//°F
            	fDewPoint = celsiusToFahrenheit(cDewPoint)
            	sendEvent(name:"DewPoint", value: fDewPoint, displayed:true, isStateChange: true)
                if (logEnable) log.info ("   DewPoint -> sendEvent")
         	}else{
         		sendEvent(name:"DewPoint", value: cDewPoint, displayed:true, isStateChange: true)
         	}
         // --- DewPoint --------------------------------------------------------------------
*/
        } // --- if cluster ---
    } // --- if "read attr" ---

} // --- parse ---

// -_-_ methods _-_-_-_-_-_-_-_-_-_-_-_-_-_-_-_-_-_-_-_-_-_-_-_-_-_-_-_-_-_-_-_-_-_-_-_-_-_-_-_-_-_-_-_-_-_-_-_-_-_-_-_-_-_-_-_

def ConvertHexToFloat(hexValue){
    HexValueStr = hexValue.toString()
    int intBits = Long.valueOf(HexValueStr, 16).intValue();
    float floatValue = Float.intBitsToFloat(intBits);
}

def initialize(){
    if (logTrace)  log.info "  running Intitialize...."
	unschedule("clearMaxMin")
	schedule("0 58 23 1/1 * ? *", clearMaxMin)    // execute handlerMethod every day at 23:58.
	Runin (240, clearMaxMin)
}

def clearMaxMin(){
	state.Max = SensorValue
	state.Min = SensorValue
}

def updateMaxMin(updateValue){
    if (logTrace) log.info " in updateMaxMin $updateValue  "
   	if(updateValue > state.Max)	state.Max = updateValue
    if(updateValue < state.Min) state.Min = updateValue
}

Without knowing for sure, I expect the code can be processing two (or more) messages at the same time, so you could get the logs interleaved for the two instances of the code that are processing each message. So as long as it is not causing you any issues I think it should be fine.

1 Like