Setting values is not consitant

[ithinkido]

Describe the bug
When using the /Set prefix , I am able to set values once. On most occasions , when trying to send a second /Set the BLE side fails. I do have a suspicion that this may be due to the data type formatting ( ??) causing the device to think the message is incomplete, but I am unsure how I can verify this , nor am l I 100% sure if this needs to defined in the config. I have used the same format for sending data as is being reported from the device.

To Reproduce
In essence , this is using a standard /Set command plus the value. I am using the debug console on MQTT under Home Assitant to send the messages.

For testing I am using the same format as the revived packet ( 40,0) to format the data I /Set , ie also (40,0). Looking at the source code from the device, I know the data is sent as a uint16 value .

Configuration and logs
My config file is as follows:

{
    "network": {
        "wifi": {
            "ssid": "xxxxxxxxx",
            "password": "xxxxxxxxxxxx"
        }
    },
    "mqtt": {
        "server": {
            "host": "192.168.1.200",
            "port": 1883,
            "username": "xxxxxxxxx",
            "password": "xxxxxxxxx"
        },
        "publish": {
            "qos": 0,
            "retain": true
        }
    },
    "ble": {
        "whitelist": [
            "xxxxxxxxxxxx"
        ],
        "services": {
            "whitelist": [
                "f6d75f91-5a10-4eba-a233-47d3f26a907f"
            ],
            "definitions": {
                "f6d75f91-5a10-4eba-a233-47d3f26a907f": {
                    "name": "setting"
                }
            }
        },
        "characteristics": {
            "whitelist": [
                "00000001-0000-1000-8000-00805f9b34fb",
                "00000000-0000-1000-8000-00805f9b34fb"
            ],
            "definitions": {
                "00000000-0000-1000-8000-00805f9b34fb": {
                    "name": "save"
                },
                "00000001-0000-1000-8000-00805f9b34fb": {
                    "name": "temp"
                }
            }
        }
    }
}

here is a screen capture of MQTT debug to show the messages and data

Here is the serial log capture of a successful send and a failed send.

failed_Set.txt
success_Set.txt

Additional context
I am happy to provide any further log or info if needed

[shmuelzon]

Hey,

First of all, I'm assuming the characteristic you're writing to is correct and does expect a uint16... A value of 40 as the "SolderingTemp" seems a bit low...
Anyway, in the failed_Set.txt log, the Pinecil has disconnected due to a timeout (reason 0x8) before the write command was sent to it and that's, probably, the reason for the failure and the rest of the following disconnection/cleanup messages.
Regardless, I suggest adding a types field to the temp characteristic so it will be parsed and sent as such and you can send/receive the actual value.

Let me know...

[ithinkido]

Thanks for the suggestions and ideas.
I have updated the config and added types

        "characteristics": {
            "whitelist": [
                "00000001-0000-1000-8000-00805f9b34fb",
                "00000000-0000-1000-8000-00805f9b34fb"
            ],
            "definitions": {
                "00000000-0000-1000-8000-00805f9b34fb": {
                    "name": "save",
                    "types": [
                        "uint16"
                      ]                
                },
                "00000001-0000-1000-8000-00805f9b34fb": {
                    "name": "temp",
                    "types": [
                        "uint16"
                      ] 
                }
            }

Unfortunately, this did not change the behavior.

I am reasonably confident that the value is a uint16 value , and it can be sent more than once via the Nordic BT app using a uint16 value.

Looking through past issues, this one has very similar symptons. Could it be possible that there is some overlap ? Comparing the merged code for the 8bit values, it looks like the code for 16 bit values is correct so i do not quite see what could be going on here,I do find it strange how similar the two issues seem even though the code has been fixed.

[shmuelzon]

I don't think the problem is with the value being sent, though we can add logs for that to make sure.
In the meantime, I have a different hunch. Can you please apply the below patch and let me know if it makes any difference?

diff --git a/main/ble.c b/main/ble.c
index e189601..4056bf1 100644
--- a/main/ble.c
+++ b/main/ble.c
@@ -529,8 +529,8 @@ int ble_characteristic_write(mac_addr_t mac, ble_uuid_t service_uuid,
         goto Exit;

     ble_operation_enqueue(&operation_queue,
-        characteristic->properties & CHAR_PROP_WRITE ?
-        BLE_OPERATION_TYPE_WRITE : BLE_OPERATION_TYPE_WRITE_NR, device,
+        characteristic->properties & CHAR_PROP_WRITE_NR ?
+        BLE_OPERATION_TYPE_WRITE_NR : BLE_OPERATION_TYPE_WRITE, device,
         characteristic, value_len, value);

     ret = 0;

[ithinkido]

Hey,

I tried with the patch. It did not change the issue.
It still seems to fail here first ,
.[0;31mE (89249) BLE: Failed reading characteristic, status = 0x85.[0m
then the device times out.
.[0;32mI (89259) BLE: Connection closed, reason = 0x8.[0m
This usually happens on the second call to send a value , but I have had occasions where it will fail on the first call or, very rarely, manage a successful second call, but fail on any following calls
I would be happy to add any debug lines needed.

[shmuelzon]

When it does succeed, does it actually set the value as expected and you see that reflected on the soldering iron, or does success simply mean that it doesn't disconnect?
This (untested) patch should print the values we're writing over BLE, just to make sure nothing's wrong there:

diff --git a/main/ble.c b/main/ble.c
index e189601..aa8058a 100644
--- a/main/ble.c
+++ b/main/ble.c
@@ -169,11 +169,17 @@ static inline void ble_operation_perform(ble_operation_t *operation)
             operation->characteristic->handle, ESP_GATT_AUTH_REQ_NONE);
         break;
     case BLE_OPERATION_TYPE_WRITE:
+        ESP_LOGI(TAG, "Writing to characteristic: " UUID_FMT,
+            UUID_PARAM(operation->characteristic->uuid));
+        ESP_LOG_BUFFER_HEX(TAG, operation->value, operation->len);
         esp_ble_gattc_write_char(g_gattc_if, operation->device->conn_id,
             operation->characteristic->handle, operation->len, operation->value,
             ESP_GATT_WRITE_TYPE_RSP, ESP_GATT_AUTH_REQ_NONE);
         break;
     case BLE_OPERATION_TYPE_WRITE_NR:
+        ESP_LOGI(TAG, "Writing to (NR) characteristic: " UUID_FMT,
+            UUID_PARAM(operation->characteristic->uuid));
+        ESP_LOG_BUFFER_HEX(TAG, operation->value, operation->len);
         esp_ble_gattc_write_char(g_gattc_if, operation->device->conn_id,
             operation->characteristic->handle, operation->len, operation->value,
             ESP_GATT_WRITE_TYPE_NO_RSP, ESP_GATT_AUTH_REQ_NONE);

I looked a bit at the source code you sent, even if we do send garbage over, it will make sure the value is between the minimum and maximum values, not disconnect.

[ithinkido]

When it does succeed, does it actually set the value as expected and you see that reflected on the soldering iron, or does success simply mean that it doesn't disconnect?

Yes, it does seem to be updating the values on the iron correctly. I am also able to read the changes " live" as published from the iron by subscribing the the xxxxxxxxxxxx/setting/temp MQTT topic.

After adding the last patch, something very interesting, although the patch is only logging the command sent, I am able to get a much better write consistency. I can often write ~ 5-6 times in a row. Before , I was never able to get more than 2 consecutive writes.
From other discussions, I learned that the Pinecil has an approx loop time of about 200ms. Is it possible that this may be somehow responsible for the timeout / disconnect ?

Here are the logs after the patch-

.[0;32mI (635882) BLE2MQTT: Discovered BLE device: xxxxxxxxxxx (RSSI: -77), connecting.[0m
.[0;32mI (638102) BLE2MQTT: Connected to device: xxxxxxxxxxx, scanning.[0m
.[0;32mI (638692) BLE2MQTT: Publishing: xxxxxxxxxxx/setting/save = 0.[0m
.[0;32mI (638742) BLE2MQTT: Publishing: xxxxxxxxxxx/setting/temp = 55.[0m
.[0;32mI (639882) BLE: Writing to (NR) characteristic: 00000001-0000-1000-8000-00805f9b34fb.[0m
.[0;32mI (639882) BLE: 3c 00 .[0m
.[0;32mI (639922) BLE2MQTT: Publishing: xxxxxxxxxxx/setting/temp = 60.[0m
.[0;32mI (646742) BLE: Writing to (NR) characteristic: 00000001-0000-1000-8000-00805f9b34fb.[0m
.[0;32mI (646742) BLE: 46 00 .[0m
.[0;32mI (646832) BLE2MQTT: Publishing: xxxxxxxxxxx/setting/temp = 70.[0m
.[0;32mI (656062) BLE: Writing to (NR) characteristic: 00000001-0000-1000-8000-00805f9b34fb.[0m
.[0;32mI (656062) BLE: 50 00 .[0m
.[0;32mI (656132) BLE2MQTT: Publishing: xxxxxxxxxxx:3a/setting/temp = 80.[0m
.[0;32mI (663032) BLE: Writing to (NR) characteristic: 00000001-0000-1000-8000-00805f9b34fb.[0m
.[0;32mI (663032) BLE: 64 00 .[0m
.[0;32mI (663132) BLE2MQTT: Publishing: xxxxxxxxxxx/setting/temp = 100.[0m
.[0;32mI (670192) BLE: Writing to (NR) characteristic: 00000001-0000-1000-8000-00805f9b34fb.[0m
.[0;32mI (670192) BLE: 78 00 .[0m
.[0;33mW (674232) BT_APPL: gattc_conn_cb: if=1 st=0 id=1 rsn=0x8.[0m
.[0;33mW (674232) BT_HCI: hcif disc complete: hdl 0x0, rsn 0x8.[0m
.[0;31mE (674232) BLE: Failed reading characteristic, status = 0x85.[0m
.[0;32mI (674232) BLE: Connection closed, reason = 0x8.[0m
.[0;32mI (674242) BLE2MQTT: Disconnected from device: xxxxxxxxxxx.[0m
.[0;32mI (675162) BLE2MQTT: Discovered BLE device: xxxxxxxxxxx (RSSI: -65), connecting.[0m
.[0;32mI (675492) BLE2MQTT: Discovered BLE device: 98:06:3c:ea:dd:e9 (RSSI: -94), not connecting.[0m
.[0;32mI (677452) BLE2MQTT: Connected to device: xxxxxxxxxxx, scanning.[0m
.[0;32mI (678022) BLE2MQTT: Publishing: xxxxxxxxxxx/setting/save = 0.[0m
.[0;32mI (678072) BLE2MQTT: Publishing: xxxxxxxxxxx/setting/temp = 55.[0m

[shmuelzon]

When you were using ESPHome before, were you able to consistently set the temperature?

[ithinkido]

Yeah, that is the strange thing - it worked flawlessly there, I even had a slider setup for it in HA which I could adjust as often as I wanted.
The purple line is SET_TEMP

This was the ESphome config that worked . Unfortunately as soon as you tried to add all the other settings ESPhome would crash from heap overflow.
esphome:.YAML.txt
Around L244 is the write SET_TEMP section

[shmuelzon]

Looking a graph, I don't see a correlation between the "Set Temp" and the "Tip Temp". Why is that?

[ithinkido]

Looking a graph, I don't see a correlation between the "Set Temp" and the "Tip Temp". Why is that?

The iron has a auto standby mode which is triggered when there is no motion for a set period. In this mode , it ramps down to a lower temp, and waits for motion to be detected before ramping up the the set temp again. I must have captured the screen shot when it was in standby.
Here is one in active mode