MQTT Commands are not executed about otgw-firmware

[jvinckers]

HI,
I have downloaded the image and upgraded the Nodemcu and it works perfect now!
Thank you very much for your quick response!

Regards,
Jur

[rvdbreemen]

Thanks for reporting the issue. Release of this fix will happen soon.

[rvdbreemen]

@jvinckers so I had to look into the code to verify what you see here. So actually there are several things happening. But let me explain the command queue for you.

When you set (send) a command the following happens:

1. the Set command puts adds the command to the queue.
2. Adding a command first checks to see if the command is already in the queue, if so, then overwrite the command in queue.
3. If not found the command in the queue, then add it to the queue (when there is still a free slot)
4. All commands are added with a 20 second delay (so they won't execute instantly)

Then every second the queue handeling is called. That does this:

1. Look into queue slots, and check to see if a command is due to be send
2. If due, then send command over serial, and update the retry by 1 and set next due in 5 seconds
3. If retry > 5, then remove the command from the queue, so a command will never be send more then three times.

When a response is received, and every command should be responded too, then do this:

1. Take the response OTGW, and check to see if the command is in the queue (only command letters are used!)
2. If there is a match, then the command is removed from the queue, no resending needed.

So the current firmware does implement the command queue, every command you send, takes about 20 second to be send. And if no good response is returned, then it will retry it 5 times, then if that fails the command is removed.

The logs you share is not enough for me to see if the queue properly works for you. If you would be so kind to send more logging and and wait 60 seconds after a command is send, send 2 commands spaces say 7 seconds apart. Then you should see the command queue working, first command should be send for the first time after 20 seconds, and then a retry at 25 seconds, then 27 command 2, etc...

Does this explain your logs better?

Let me know what you think, we can lower the "transmission delay" to 0 ms... but so far no one really complained about the delay and it's nice and slow, so behaviour can be observed well in the logs this way. That's actually the only reason for the 20 second delay.

Hope to hear from you, and a confirmation of the proper functioning would be great.

Regards,
Robert

[rvdbreemen]

In the code you can find the following functions:

• void addOTWGcmdtoqueue(const char* buf, int len)
• void handleOTGWqueue()
• void checkOTGWcmdqueue(const char *buf, int len)

It matches the functions I explained above.

[rvdbreemen]

@jvinckers I have one question for you, why is your OTGW sending PR responses? Are you using the PR command over a serial interface (network) by any chance? What is your setup? Please share some information, that way I can understand better what usecases there are with others.

[rvdbreemen]

A debug trace from my dev build:
[08:57:10][ 14176| 11200] handleMQTTca( 57): Message arrived on topic [OTGW/set/otgw-2CF43257D77C/command] = [TT=16.8] (7)
[08:57:10][ 12832| 11200] addOTWGcmdto( 991): CmdQueue: Adding cmd end of queue, slot [0]
[08:57:10][ 12832| 11200] addOTWGcmdto( 994): CmdQueue: Insert queue in slot[0]:[]
[08:57:10][ 12832| 11200] addOTWGcmdto(1007): CmdQueue: Next free queue slot: [1]
[08:57:11][ 14312| 11200] processOTGW (1156): Thermostat [T00110000] [READ_DATA ] [RelModLevel ] hb[ 0] lb[ 0]
[08:57:11][ 13640| 11200] processOTGW (1151): Boiler [BC0110000] [READ_ACK ] [RelModLevel ] RelModLevel = 0.00 %
[08:57:11][ 12968| 11200] sendMQTTData( 284): Sending MQTT: server [192.168.88.254]:[1883] => TopicId [OTGW/value/otgw-2CF43257D77C/RelModLevel] --> Message [0.00]
[08:57:11][ 13640| 11200] handleOTGWqu(1019): CmdQueue: Checking due in queue slot[0]:[20846]<[23113]
[08:57:11][ 12968| 11200] handleOTGWqu(1021): CmdQueue: Queue slot [0] due
[08:57:11][ 12968| 11200] sendOTGW (1097): Sending to Serial [TT=16.8] (7)
[08:57:11][ 12944| 11200] checkOTGWcmd(1059): CmdQueue: Checking if command is in in queue [TT: 16.80] (9)
[08:57:11][ 12944| 11200] checkOTGWcmd(1070): CmdQueue: Checking [TT]==>[0]:[TT=16.8] from queue
[08:57:11][ 12944| 11200] checkOTGWcmd(1073): CmdQueue: Found cmd [TT]==>[0]:[TT=16.8]
[08:57:11][ 12272| 11200] checkOTGWcmd(1076): CmdQueue: Found value [ 16.80]==>[0]:[TT=16.8]
[08:57:11][ 12272| 11200] checkOTGWcmd(1077): CmdQueue: Remove from queue [0]:[TT=16.8] from queue
[08:57:11][ 12944| 11200] checkOTGWcmd(1079): CmdQueue: Moving [1] => [0]

[jvinckers]

Thanx for your reply,
1st about my setup:
I use the NodoShop OTGW with an Nodemcu v2.
Than I use a Ubuntu server running Mosquitto and other services like Apache Postfix etc..
And I have a separate Ubuntu server running Home Assistant. But for testing purposes I have shut down this server to prevent it from interfering the test. (This is where the PR responses initiated from. I think the OpenTherm integration in Home Assistant (via socket connection)).
In the server running Mosquitto I am running a script witch reads the outside temperature every 5 min and sends it via a Socket connection to the Nodemcu. (this works perfect as you can see in the log at timestamp: [00:01:40]
But commands added via MQTT are not processed en stays in the queue even after 20 minutes of waiting.
The 20sec delay is no problem to me.

I have attached the log so your can look into it.
It starts with the incoming MQTT command and it is about 65 sec long. And a snippet about 20 minutes later where you can see the command is still in the queue.
Hopefully you can help me out on this.

otwg.log

[rvdbreemen]

@jvinckers thanks for sharing the log, now that's a very weird condition, as the command is due, but does not execute for some reason. So you are write, this seems to be a bug. I will look in more detail tonight.

[rvdbreemen]

@jvinckers seems that you have hit a bug indeed. I seem to have used now() where I planned to use millis(). Most cases this seems to work, but not always. Thus this is bug in need of fixing. Can you validate my build when I have tested it myself?

[rvdbreemen]

I just uploaded a dev build to the discord, so just pick it up there.
Discord invite: https://discord.gg/zjW3ju7vGQ

[jvinckers]

Also tested in HomeAssistant with a climate card based on the MQTT topics and it is running great!

[rvdbreemen]

Fixed with release v0.8.5