[Serial] Crash on event processing of bytes

[Amelsfort]

Build: ESP_Easy_mega_20211105_normal_ESP32_4M316k Nov 5 2021

I am currently running ESP Easy to receive serial data from a Teensy-device and setting some dummy devices accordingly. This is data from a devices panel with has some LEDs and a display with an error code. I want to send the status of the LEDs and the code to ESP Easy. This works fine if I send the data all as readable strings and the events are triggered correctly.

But to minimize the amount of data sent, the Teensy sends 'SWG' and then two bytes of data: byte 1: indicating the status of 7 LEDs byte 2: an error code (between 0 and 99) Unfortunately, this causes the ESP to become unresponsive. I can't access the UI anymore and my telnet-monitoring also stops.

I found out that when I disable 'Event processing' of the serial device, it doesn't crash anymore. But I also loose the triggering of my rules.

The rule I created:

on !Serial#SWG* do
    LogEntry,"Serial data received: {%eventvalue%}"
    let,1,{substring:12:13:{%eventvalue%}}
    let,2,{strtol:16:{substring:13:14:{%eventvalue%}}}
    LogEntry,"Code: [var#2]"
endon

The serial device is configured as follows:

Passing the data through also works fine. This is the output of Putty when telnet'ting to the ESP:

SWG`SWGaSWGbSWGcSWGcSWGbSWGaSWG`SWG_SWG^PuTTYSWG]SWG\SW[SWG     ZSWG
                                                                    YSWG
                                                                        XSWG
VSWGUSWGTSWGSSWGRSWGQSWGPSWGOSWGNSWGMSWGLSWGKSWGJSWGISWGSWGGSWGFSWGESWGDSWG CSWG!BSWG"ASWG#@SWG$?SWG%>SWG&=SWG'<SWG(;SWG):SWG*9SWG+8SWG,7SWG-6SWG.5SWG/4SWG03SWG12SWG21SWG30SWG4/SWG5.SWG6-SWG7,SWG8+SWG9*SWG:)SWG;(SWG<'SWG=&SWG>%SWG?$SWG@#SWGA"SWGB!SWGC SWGDSWGESWGFSWGGSWGHWGISWGJSWGKSWGLSWGMSWGNSWG

The issue only occurs when I change the 'Event processing' to 'Generic'. Could this be caused by me sending bytes with values ranging from 0 to 255? And how can I read those bytes? If I send the values as decimals it works, but I would have to add more logic to corretly retrieve the values. 2 bytes is all I need.

[TD-er]

Do you have a rough idea of the number of messages/events to process? Also which log destinations have you set with at least log level "info" ?

The last few days I have been working on improving the rules processing speed and I can give you a test build which does handle rules quite a bit faster. See: https://github.com/letscontrolit/ESPEasy/pull/4004 Still if the serial log (or logging to a syslog service) is enabled, then this may have serious impact on performance.

Please try to enable the timing stats (tools->advanced page) and try to gather some timings from the timing stats page. N.B. the stats are cleared on every load of that page, so better to load the page once after boot and then let it run for a few minutes before loading that page.

[Amelsfort]

I send a message every second. The log settings are: I already disabled serial logging to see if that changes anything, but it made no difference.

I don't think it's caused by timings or performance, since it works fine when I use decimals instead of bytes. I also tried using hex values (as a string), which seems to be working fine as well. Although I sometimes get strange errors:

631680: EVENT: !Serial#SWGa25d
631690: ACT : LogEntry,'First: a2 Second: 5d'
631692: First: a2 Second: 5d
631697: ACT : let,1,{strtol:16:a2}
631700: Calculate: Unknown token input: {strtol:16:a2} = 0

Why would it have an issue with converting 'a2' to a decimal? It does work for some other values:

1105652: EVENT: !Serial#SWG7c83
1105662: ACT : LogEntry,'First: 7c Second: 83'
1105664: First: 7c Second: 83
1105670: ACT : let,1,124
1105678: ACT : let,2,131

The stats: This is with Event Processing set to 'Generic', but when I'm sending hex values instead of bytes. So it's not crashing now.

[TD-er]

Let's put the rules and log next to each other for clarity:

on !Serial#SWG* do
    LogEntry,"Serial data received: {%eventvalue%}"
    let,1,{substring:12:13:{%eventvalue%}}
    let,2,{strtol:16:{substring:13:14:{%eventvalue%}}}
    LogEntry,"Code: [var#2]"
endon

Log:

631680: EVENT: !Serial#SWGa25d
631690: ACT : LogEntry,'First: a2 Second: 5d'
631692: First: a2 Second: 5d
631697: ACT : let,1,{strtol:16:a2}
631700: Calculate: Unknown token input: {strtol:16:a2} = 0

I think you need to make clear this is HEX code. Maybe something like this?

let,1,"0x{substring:12:13:{%eventvalue%}}"

But still, I don't see the eventvalue in the log, so this is something which may not be tested very well with the exclamation mark in front of the event block in the rules. Typical events have the form: foo[#bar]=123,456,789,10 Where there may be 0 ... 4 event values. But here, by using the !, you seem to be having Serial#SWGa25d in the %eventvalue% and string processing in the eventvalues is still experimental (as in, not complete)

I don't see the logentry "Serial data received: {%eventvalue%}" in your logs. Do you have it?

[Amelsfort]

The log was probably not taken with that same rule in place. I added it for the second issue about the conversion of the hex values. Sorry for the confusion.

The eventvalue was indeed one long string. I tried to get separate values, but this was the code I found and I didn't manage to get ESP Easy to recognize the different values. It didn't understand '%eventvalue1%'.

I am currently not at my computer, so there's not much I can check at the moment. I will check later.

[tonhuisman]

didn't understand '%eventvalue1%'.

%eventvalue% is an alias for %eventvalue1%, and there are (currently, but that may change) 4 of these arguments available to the rule, if and when they are provided.

[Amelsfort]

I tried using the trigger without the '!', but that didn't trigger at all.

on !Serial#SWG* do
  LogEntry,"Serial data received: {%eventvalue%}"
  LogEntry,"First: {substring:12:14:{%eventvalue%}}  Second: {substring:14:16:{%eventvalue%}}"
  let,1,{strtol:16:{substring:12:14:{%eventvalue%}}}
  let,2,{strtol:16:{substring:14:16:{%eventvalue%}}}
endon

on Serial#SWG* do
  LogEntry,"Status data received: {%eventvalue%}"
endon

The logs:

221001: EVENT: !Serial#SWGb748
221009: ACT : LogEntry,'Serial data received: {!Serial#SWGb748}'
221013: Serial data received: {!Serial#SWGb748}
221019: ACT : LogEntry,'First: b7 Second: 48'
221021: First: b7 Second: 48
221026: ACT : let,1,{strtol:16:b7}
221030: Calculate: Unknown token input: {strtol:16:b7} = 0
221035: ACT : let,2,72
221986: EVENT: !Serial#SWGb847
221993: ACT : LogEntry,'Serial data received: {!Serial#SWGb847}'
221997: Serial data received: {!Serial#SWGb847}
222003: ACT : LogEntry,'First: b8 Second: 47'
222005: First: b8 Second: 47
222010: ACT : let,1,{strtol:16:b8}
222014: Calculate: Unknown token input: {strtol:16:b8} = 0
222019: ACT : let,2,71

I also tried the second trigger with the device name like on Status#SWG* do. But that also didn't trigger.

Using the separated values also didn't work:

on !Serial#SWG* do
  LogEntry,"Serial data received: {%eventvalue%}"
  LogEntry,"Value 1: {%eventvalue1%}"
  LogEntry,"Value 2: {%eventvalue2%}"
endon

The log:

66983: Serial data received: {!Serial#SWG5f,a0}
66989: ACT : LogEntry,'Value 1: {%eventvalue1%}'
66994: Value 1: {%eventvalue1%}
67000: ACT : LogEntry,'Value 2: {%eventvalue2%}'
67005: Value 2: {%eventvalue2%}

But, on the other hand, converting hex to a decimal like this

let,1,{strtol:16:"0x{substring:12:14:{%eventvalue%}}"}
let,2,{strtol:16:"0x{substring:14:16:{%eventvalue%}}"}

seems to work! That's at least one issue out of the way.

[tonhuisman]

When prefixing the value with 0x you don't need the strtol function, as ESPEasy by default 'understands' the 0x prefixing is a hex value. Saves a few cpu-cycles 😉