Strange rule / items behavior

[Karol]

I’ve such rule:

rule "Sprawdzenie komunikacji via MQTT - Moduł ESP_PScreen - Cron"
  when
    Time cron "0 0/5 * * * ? *" // Co 5m
  then
      logInfo("rules.IB","REGRUN: Sprawdzenie komunikacji via MQTT - Moduł ESP_PScreen - Cron")
      logInfo("rules.IB","Testuję komunikację MQTT dla modułu ESP Ekran projektora (Cron)...")
      ESP_PScreen_TestCom.sendCommand(ON)
end
rule "Sprawdzenie komunikacji via MQTT - Moduł ESP_PScreen - CommCheck"
  when
    Item ESP_PScreen_TestCom changed to ON
  then
    logInfo("rules.IB","REGRUN: Sprawdzenie komunikacji via MQTT - Moduł ESP_PScreen - CommCheck")
    logInfo("rules.IB","Testuję komunikację MQTT dla modułu ESP Ekran projektora...")
    createTimer(now.plusSeconds(ESPTestComDelay), [|
      if(ESP_PScreen_Wej1byTestCom.state == 1) {
        ESP_PScreen_TestCom.sendCommand(OFF)
        createTimer(now.plusSeconds(ESPTestComDelay), [|
          if(ESP_PScreen_Wej1byTestCom.state == 1) {...

and in my logs I can see:

[rules.log] 2020-10-15 10:10:00.005 [INFO ] [ipse.smarthome.model.script.rules.IB] - REGRUN: Sprawdzenie komunikacji via MQTT - Moduł ESP_PScreen - Cron
[rules.log] 2020-10-15 10:10:00.006 [INFO ] [ipse.smarthome.model.script.rules.IB] - Testuję komunikację MQTT dla modułu ESP Ekran projektora (Cron)...

[event.log] 2020-10-15 10:10:00.018 [ome.event.ItemCommandEvent] - Item 'ESP_PScreen_TestCom' received command ON
[event.log] 2020-10-15 10:10:00.044 [nt.ItemStatePredictedEvent] - ESP_PScreen_TestCom predicted to become ON

[rules.log] 2020-10-15 10:10:00.047 [INFO ] [ipse.smarthome.model.script.rules.IB] - REGRUN: Sprawdzenie komunikacji via MQTT - Moduł ESP_PScreen - CommCheck
[rules.log] 2020-10-15 10:10:00.047 [INFO ] [ipse.smarthome.model.script.rules.IB] - Testuję komunikację MQTT dla modułu ESP Ekran projektora...

[event.log] 2020-10-15 10:10:02.959 [vent.ItemStateChangedEvent] - ESP_PScreen_TestCom changed from OFF to ON

[event.log] 2020-10-15 10:10:02.960 [vent.ItemStateChangedEvent] - ESP_PScreen_Wej1byTestCom changed from 0 to 1

[event.log] 2020-10-15 10:10:05.048 [ome.event.ItemCommandEvent] - Item 'ESP_PScreen_TestCom' received command OFF
[event.log] 2020-10-15 10:10:05.053 [nt.ItemStatePredictedEvent] - ESP_PScreen_TestCom predicted to become OFF
[event.log] 2020-10-15 10:10:05.055 [vent.ItemStateChangedEvent] - ESP_PScreen_TestCom changed from ON to OFF

[rules.log] 2020-10-15 10:10:10.049 [INFO ] [ipse.smarthome.model.script.rules.IB] - UWAGA: Wystąpił problem z komunikacją MQTT z modułem ESP Ekran projektora (1; [event.log] ESP_PScreen_Wej1byTestCom.state=1)!

[event.log] 2020-10-15 10:10:10.052 [ome.event.ItemCommandEvent] - Item 'InfoToSend' received command UWAGA: Wystąpił problem z komunikacją MQTT z modułem ESP Ekran projektora (1; ESP_PScreen_Wej1byTestCom.state=1)!
[event.log] 2020-10-15 10:10:10.054 [ome.event.ItemCommandEvent] - Item 'ESP_PScreen_ComErr' received command ON
[event.log] 2020-10-15 10:10:10.054 [ome.event.ItemCommandEvent] - Item 'ESP_PScreen_TestCom' received command OFF
[event.log] 2020-10-15 10:10:10.064 [nt.ItemStatePredictedEvent] - ESP_PScreen_TestCom predicted to become OFF

[event.log] 2020-10-15 10:10:10.070 [vent.ItemStateChangedEvent] - InfoToSend changed from Komunikacja MQTT z modułem ESP Ekran projektora działa poprawnie (1). to UWAGA: Wystąpił problem z komunikacją MQTT z modułem ESP Ekran projektora (1; ESP_PScreen_Wej1byTestCom.state=1)!
[event.log] 2020-10-15 10:10:10.093 [vent.ItemStateChangedEvent] - ESP_PScreen_ComErr changed from OFF to ON
[event.log] 2020-10-15 10:10:11.434 [vent.ItemStateChangedEvent] - ESP_PScreen_Wej1byTestCom changed from 1 to 0

What is strange, that fraze:

[rules.log] 2020-10-15 10:10:00.047 [INFO ] [ipse.smarthome.model.script.rules.IB] - REGRUN: Sprawdzenie komunikacji via MQTT - Moduł ESP_PScreen - CommCheck

appear (more then 2s) before:

[event.log] 2020-10-15 10:10:02.959 [vent.ItemStateChangedEvent] - ESP_PScreen_TestCom changed from OFF to ON

[rossko57]

If this is supposed to be checking if a device responded to a command, you probably want to disable autoupdate on the item

Autoupdate - a primer

I’ve found myself having to investigate and/or explain some of the features of autoupdate over time, and thought an in-depth view would be helpful. These notes apply to openHAB version 2.5 Overview Autoupdate is primarily a “speed up” feature for openHAB Items. Mostly we can ignore it, but sometimes you may get an unwanted or unexpected effect, or you may wish to exercise more control. To fully understand autoupdate, we must understand the difference between command and state of Items. If w…

I have seen MQTT interact oddly with autoupdate in the past, but thought it fixed in OH 2.5