espressif / esp-homekit-sdk

541 stars 98 forks source link

Frequent "Decryption error/Connection lost." in Bridge example on iPhone 14 #104

Open vishalkothari opened 1 year ago

vishalkothari commented 1 year ago

Hello, I am running bridge example with ESP32 WROOM. The code is without any modification except hardcoded wifi configuration. The code works fine when adding to Home app on iPhone 11 and I dont see any errors.

But, I see frequent "Decryption error/Connection lost." errors after adding to Home app on iPhone 14, . These errors are on almost every click of the accessory. Both devices are on same iOS version 16.4.1(a)

Below are the logs with iPhone 14 Home app.

######## Starting Pair Verify ########
Pair Verify M1 Received
Pair Verify M2 Successful
Socket fd: 51; HTTP Request POST /pair-verify
Pair Verify M3 Received
HomeKit Session active
Pair Verify Successful for 04575F40-E6BD-4FED-95B3-2E4787120BD1
Socket fd: 51; HTTP Request GET /accessories
Generating HTTP Response
{"accessories":[{"aid":1,"services":[{"iid":1,"type":"3E","characteristics":[{"iid":2,"type":"14","perms":["pw"],"ev":false,"format":"bool"},{"iid":3,"value":"Espressif","type":"20","perms":["pr"],"ev":false,"format":"string"},{"iid":4,"value":"EspBridge01","type":"21","perms":["pr"],"ev":false,"format":"string"},{"iid":5,"value":"Esp-Bridge","type":"23","perms":["pr"],"ev":false,"format":"string"},{"iid":6,"value":"001122334455","type":"30","perms":["pr"],"ev":false,"format":"string"},{"iid":7,"value":"0.9.0","type":"52","perms":["pr"],"ev":false,"format":"string"},{"iid":10,"value":"RVNQMzJIQVA=","type":"220","perms":["pr"],"ev":false,"format":"data"}]},{"iid":8,"type":"A2","characteristics":[{"iid":9,"value":"1.1.0","type":"37","perms":["pr"],"ev":false,"format":"string"}]}]},{"aid":801,"services":[{"iid":1,"type":"3E","characteristics":[{"iid":2,"type":"14","perms":["pw"],"ev":false,"format":"bool"},{"iid":3,"value":"Espressif","type":"20","perms":["pr"],"ev":false,"format":"string"},{"iid":4,"value":"EspFan01","type":"21","perms":["pr"],"ev":false,"format":"string"},{"iid":5,"value":"ESP-Fan-0","type":"23","perms":["pr"],"ev":false,"format":"string"},{"iid":6,"value":"abcdefg","type":"30","perms":["pr"],"ev":false,"format":"string"},{"iid":7,"value":"0.9.0","type":"52","perms":["pr"],"ev":false,"format":"string"}]},{"iid":8,"type":"40","characteristics":[{"iid":9,"value":false,"type":"25","perms":["pr","pw","ev"],"ev":false,"format":"bool"},{"iid":10,"value":"ESP-Fan-0","type":"23","perms":["pr"],"ev":false,"format":"string"}]}]},{"aid":802,"services":[{"iid":1,"type":"3E","characteristics":[{"iid":2,"type":"14","perms":["pw"],"ev":false,"format":"bool"},{"iid":3,"value":"Espressif","type":"20","perms":["pr"],"ev":false,"format":"string"},{"iid":4,"value":"EspFan01","type":"21","perms":["pr"],"ev":false,"format":"string"},{"iid":5,"value":"ESP-Fan-1","type":"23","perms":["pr"],"ev":false,"format":"string"},{"iid":6,"value":"abcdefg","type":"30","perms":["pr"],"ev":false,"format":"string"},{"iid":7,"value":"0.9.0","type":"52","perms":["pr"],"ev":false,"format":"string"}]},{"iid":8,"type":"40","characteristics":[{"iid":9,"value":false,"type":"25","perms":["pr","pw","ev"],"ev":false,"format":"bool"},{"iid":10,"value":"ESP-Fan-1","type":"23","perms":["pr"],"ev":false,"format":"string"}]}]},{"aid":803,"services":[{"iid":1,"type":"3E","characteristics":[{"iid":2,"type":"14","perms":["pw"],"ev":false,"format":"bool"},{"iid":3,"value":"Espressif","type":"20","perms":["pr"],"ev":false,"format":"string"},{"iid":4,"value":"EspFan01","type":"21","perms":["pr"],"ev":false,"format":"string"},{"iid":5,"value":"ESP-Fan-2","type":"23","perms":["pr"],"ev":false,"format":"string"},{"iid":6,"value":"abcdefg","type":"30","perms":["pr"],"ev":false,"format":"string"},{"iid":7,"value":"0.9.0","type":"52","perms":["pr"],"ev":false,"format":"string"}]},{"iid":8,"type":"40","characteristics":[{"iid":9,"value":false,"type":"25","perms":["pr","pw","ev"],"ev":false,"format":"bool"},{"iid":10,"value":"ESP-Fan-2","type":"23","perms":["pr"],"ev":false,"format":"string"}]}]}]}
Socket fd: 51; HTTP Request PUT /characteristics
Data Received: {"characteristics":[{"aid":802,"iid":9,"ev":true}]}
Events Enabled for aid=802 iid=9
Socket fd: 51; HTTP Request PUT /characteristics
Data Received: {"characteristics":[{"aid":803,"iid":9,"ev":true}]}
Events Enabled for aid=803 iid=9
Socket fd: 51; HTTP Request PUT /characteristics
Data Received: {"characteristics":[{"aid":801,"iid":9,"ev":true}]}
Events Enabled for aid=801 iid=9
Socket fd: 51; HTTP Request GET /characteristics?id=802.9,803.9,801.9
Generating HTTP Response
{"characteristics":[{"aid":802,"iid":9,"value":false},{"aid":803,"iid":9,"value":false},{"aid":801,"iid":9,"value":false}]}
Decryption error/Connection lost. Marking session as invalid
HomeKit Session terminated
Socket fd: 51; HTTP Request POST /pair-verify
######## Starting Pair Verify ########
Socket fd: 51; HTTP Request PUT /characteristics
Data Received: {"characteristics":[{"aid":802,"iid":9,"value":1}]}
I (42612) HAP Bridge: Write called for Accessory ESP-Fan-1
I (42612) HAP Bridge: Received Write. Fan On
Value Changed
Socket fd: 51; HTTP Request PUT /characteristics
Data Received: {"characteristics":[{"aid":802,"iid":9,"value":0}]}
I (43422) HAP Bridge: Write called for Accessory ESP-Fan-1
I (43432) HAP Bridge: Received Write. Fan Off
Value Changed
Decryption error/Connection lost. Marking session as invalid
HomeKit Session terminated

Any inputs on this will be really appreciated.

shahpiyushv commented 1 year ago

@vishalkothari , do you see any error on the iPhone side? Can you add prints for HAP_EVENT_CTRL_CONNECTED and HAP_EVENT_CTRL_DISCONNECTED and capture the logs again? You can subscribe to these events using esp_event_handler_register(HAP_EVENT, ESP_EVENT_ANY_ID, &hap_event_handler, NULL);. Sample usage can be found in the fan example here.

vishalkothari commented 1 year ago

Hello @shahpiyushv, below are the logs

Socket fd: 51; HTTP Request POST /pair-setup
######## Starting Pair Setup ########
Pair Setup M1 Received
Pair Setup M2 Successful
I (34107) HAP Bridge: Pairing Started
Socket fd: 51; HTTP Request POST /pair-setup
Pair Setup M3 Received
Using pair-setup without MFi.
Pair Setup M4 Successful
Socket fd: 51; HTTP Request POST /pair-setup
Pair Setup M5 Received
Pair Setup Successful for 04575F40-E6BD-4FED-95B3-2E4787120BD1
I (34517) HAP Bridge: Controller 04575F40-E6BD-4FED-95B3-2E4787120BD1 Paired. Controller count: 1
Skipping s# update for Certification requirements.
Re-announcing _hap._tcp mDNS service
Cleaning Pair Setup Context
Socket fd: 51; HTTP Request POST /pair-verify
######## Starting Pair Verify ########
Pair Verify M1 Received
Pair Verify M2 Successful
Socket fd: 51; HTTP Request POST /pair-verify
Pair Verify M3 Received
I (34877) HAP Bridge: Controller 04575F40-E6BD-4FED-95B3-2E4787120BD1 Connected
HomeKit Session active
Pair Verify Successful for 04575F40-E6BD-4FED-95B3-2E4787120BD1
Socket fd: 51; HTTP Request GET /accessories
Generating HTTP Response
{"accessories":[{"aid":1,"services":[{"iid":1,"type":"3E","characteristics":[{"iid":2,"type":"14","perms":["pw"],"ev":false,"format":"bool"},{"iid":3,"value":"Espressif","type":"20","perms":["pr"],"ev":false,"format":"string"},{"iid":4,"value":"EspBridge01","type":"21","perms":["pr"],"ev":false,"format":"string"},{"iid":5,"value":"Esp-Bridge","type":"23","perms":["pr"],"ev":false,"format":"string"},{"iid":6,"value":"001122334455","type":"30","perms":["pr"],"ev":false,"format":"string"},{"iid":7,"value":"0.9.0","type":"52","perms":["pr"],"ev":false,"format":"string"},{"iid":10,"value":"RVNQMzJIQVA=","type":"220","perms":["pr"],"ev":false,"format":"data"}]},{"iid":8,"type":"A2","characteristics":[{"iid":9,"value":"1.1.0","type":"37","perms":["pr"],"ev":false,"format":"string"}]}]},{"aid":801,"services":[{"iid":1,"type":"3E","characteristics":[{"iid":2,"type":"14","perms":["pw"],"ev":false,"format":"bool"},{"iid":3,"value":"Espressif","type":"20","perms":["pr"],"ev":false,"format":"string"},{"iid":4,"value":"EspFan01","type":"21","perms":["pr"],"ev":false,"format":"string"},{"iid":5,"value":"ESP-Fan-0","type":"23","perms":["pr"],"ev":false,"format":"string"},{"iid":6,"value":"abcdefg","type":"30","perms":["pr"],"ev":false,"format":"string"},{"iid":7,"value":"0.9.0","type":"52","perms":["pr"],"ev":false,"format":"string"}]},{"iid":8,"type":"40","characteristics":[{"iid":9,"value":false,"type":"25","perms":["pr","pw","ev"],"ev":false,"format":"bool"},{"iid":10,"value":"ESP-Fan-0","type":"23","perms":["pr"],"ev":false,"format":"string"}]}]},{"aid":802,"services":[{"iid":1,"type":"3E","characteristics":[{"iid":2,"type":"14","perms":["pw"],"ev":false,"format":"bool"},{"iid":3,"value":"Espressif","type":"20","perms":["pr"],"ev":false,"format":"string"},{"iid":4,"value":"EspFan01","type":"21","perms":["pr"],"ev":false,"format":"string"},{"iid":5,"value":"ESP-Fan-1","type":"23","perms":["pr"],"ev":false,"format":"string"},{"iid":6,"value":"abcdefg","type":"30","perms":["pr"],"ev":false,"format":"string"},{"iid":7,"value":"0.9.0","type":"52","perms":["pr"],"ev":false,"format":"string"}]},{"iid":8,"type":"40","characteristics":[{"iid":9,"value":false,"type":"25","perms":["pr","pw","ev"],"ev":false,"format":"bool"},{"iid":10,"value":"ESP-Fan-1","type":"23","perms":["pr"],"ev":false,"format":"string"}]}]},{"aid":803,"services":[{"iid":1,"type":"3E","characteristics":[{"iid":2,"type":"14","perms":["pw"],"ev":false,"format":"bool"},{"iid":3,"value":"Espressif","type":"20","perms":["pr"],"ev":false,"format":"string"},{"iid":4,"value":"EspFan01","type":"21","perms":["pr"],"ev":false,"format":"string"},{"iid":5,"value":"ESP-Fan-2","type":"23","perms":["pr"],"ev":false,"format":"string"},{"iid":6,"value":"abcdefg","type":"30","perms":["pr"],"ev":false,"format":"string"},{"iid":7,"value":"0.9.0","type":"52","perms":["pr"],"ev":false,"format":"string"}]},{"iid":8,"type":"40","characteristics":[{"iid":9,"value":false,"type":"25","perms":["pr","pw","ev"],"ev":false,"format":"bool"},{"iid":10,"value":"ESP-Fan-2","type":"23","perms":["pr"],"ev":false,"format":"string"}]}]}]}
Socket fd: 51; HTTP Request PUT /characteristics
Data Received: {"characteristics":[{"aid":802,"iid":9,"ev":true}]}
Events Enabled for aid=802 iid=9
Socket fd: 51; HTTP Request PUT /characteristics
Data Received: {"characteristics":[{"aid":801,"iid":9,"ev":true}]}
Events Enabled for aid=801 iid=9
Socket fd: 51; HTTP Request PUT /characteristics
Data Received: {"characteristics":[{"aid":803,"iid":9,"ev":true}]}
Events Enabled for aid=803 iid=9
Socket fd: 51; HTTP Request GET /characteristics?id=1.7,1.5
Generating HTTP Response
{"characteristics":[{"aid":1,"iid":7,"value":"0.9.0"},{"aid":1,"iid":5,"value":"Esp-Bridge"}]}
Socket fd: 51; HTTP Request GET /characteristics?id=801.5,801.7
Generating HTTP Response
{"characteristics":[{"aid":801,"iid":5,"value":"ESP-Fan-0"},{"aid":801,"iid":7,"value":"0.9.0"}]}
Socket fd: 51; HTTP Request GET /characteristics?id=801.10
Generating HTTP Response
{"characteristics":[{"aid":801,"iid":10,"value":"ESP-Fan-0"}]}
Socket fd: 51; HTTP Request GET /characteristics?id=802.7,802.5
Generating HTTP Response
{"characteristics":[{"aid":802,"iid":7,"value":"0.9.0"},{"aid":802,"iid":5,"value":"ESP-Fan-1"}]}
Socket fd: 51; HTTP Request GET /characteristics?id=1.5
Generating HTTP Response
{"characteristics":[{"aid":1,"iid":5,"value":"Esp-Bridge"}]}
Socket fd: 51; HTTP Request GET /characteristics?id=802.10
Generating HTTP Response
{"characteristics":[{"aid":802,"iid":10,"value":"ESP-Fan-1"}]}
Socket fd: 51; HTTP Request GET /characteristics?id=803.5,803.7
Generating HTTP Response
{"characteristics":[{"aid":803,"iid":5,"value":"ESP-Fan-2"},{"aid":803,"iid":7,"value":"0.9.0"}]}
Socket fd: 51; HTTP Request GET /characteristics?id=803.10
Generating HTTP Response
{"characteristics":[{"aid":803,"iid":10,"value":"ESP-Fan-2"}]}
Socket fd: 51; HTTP Request GET /characteristics?id=803.10,803.5
Generating HTTP Response
{"characteristics":[{"aid":803,"iid":10,"value":"ESP-Fan-2"},{"aid":803,"iid":5,"value":"ESP-Fan-2"}]}
Socket fd: 51; HTTP Request GET /characteristics?id=802.5,802.10
Generating HTTP Response
{"characteristics":[{"aid":802,"iid":5,"value":"ESP-Fan-1"},{"aid":802,"iid":10,"value":"ESP-Fan-1"}]}
Socket fd: 51; HTTP Request GET /characteristics?id=801.10,801.5
Generating HTTP Response
{"characteristics":[{"aid":801,"iid":10,"value":"ESP-Fan-0"},{"aid":801,"iid":5,"value":"ESP-Fan-0"}]}
Socket fd: 51; HTTP Request GET /characteristics?id=801.9,803.9,802.9
Generating HTTP Response
{"characteristics":[{"aid":801,"iid":9,"value":false},{"aid":803,"iid":9,"value":false},{"aid":802,"iid":9,"value":false}]}
Decryption error/Connection lost. Marking session as invalid
I (42087) HAP Bridge: Controller 04575F40-E6BD-4FED-95B3-2E4787120BD1 Disconnected
HomeKit Session terminated
Socket fd: 51; HTTP Request POST /pair-verify

I have tried enabling keep alive by CONFIG_HAP_SESSION_KEEP_ALIVE_ENABLE=y and that did not help I also tried lightbulb example and that worked fine and I did not see any errors.

vishalkothari commented 1 year ago

Digging further into this, esp_hap_network_io.c > hap_decrypt_data > read_fn(frame->data, 2, context) returns zero which leads to the error. Any clues on why that may be happening for bridge example?

shahpiyushv commented 1 year ago

@vishalkothari Decryption error also occurs when the iOS breaks the connection. From the logs it is not clear what the reason could be. However, just curious to know why your aid numbers have gone into 100s. I see them as 801, 802, and so on.

vishalkothari commented 1 year ago

I am not sure how the aid attribute is created. I added 3 accessories to the bridge. Below is the code. Also, I tried homespan framework and the connection seemed to be stable.

for (uint8_t i = 0; i < NUM_BRIDGED_ACCESSORIES; i++) {
        char accessory_name[12] = {0};
        sprintf(accessory_name, "ESP-Fan-%d", i);

        hap_acc_cfg_t bridge_cfg = {
            .name = accessory_name,
            .manufacturer = "Espressif",
            .model = "EspFan01",
            .serial_num = "abcdefg",
            .fw_rev = "0.9.0",
            .hw_rev = NULL,
            .pv = "1.1.0",
            .identify_routine = accessory_identify,
            .cid = HAP_CID_BRIDGE,
        };
        /* Create accessory object */
        accessory = hap_acc_create(&bridge_cfg);

        /* Create the Fan Service. Include the "name" since this is a user visible service  */
        service = hap_serv_fan_create(false);
        hap_serv_add_char(service, hap_char_name_create(accessory_name));

        /* Set the Accessory name as the Private data for the service,
         * so that the correct accessory can be identified in the
         * write callback
         */
        hap_serv_set_priv(service, strdup(accessory_name));

        /* Set the write callback for the service */
        hap_serv_set_write_cb(service, fan_write);

        /* Add the Fan Service to the Accessory Object */
        hap_acc_add_serv(accessory, service);

        /* Add the Accessory to the HomeKit Database */
        hap_add_bridged_accessory(accessory, hap_get_unique_aid(accessory_name));
    }
shahpiyushv commented 1 year ago

This code itself looks fine to me. The HomeKit SDK assigns same aid if the accessory name is same. So, that going beyond 800 is strange. Meanwhile, what do you see on the phone apps when this error occurs?

vishalkothari commented 1 year ago

Homeapp shows device online and then when clicking on a device, it shows "Connecting" and performs no action. This action continues frequently in a loop.

shahpiyushv commented 1 year ago

@vishalkothari , considering that you see the issue only on iPhone 14, but not on iPhone 11, it seems quite unlikely that there would be anything wrong on the firmware side. Have you tried updating to iOS 16.5?

qlwz commented 9 months ago

iphone13 16.6.1 use examples/bridge like

######## Starting Pair Verify ######## Pair Verify M1 Received Pair Verify M2 Successful Pair Verify M3 Received HomeKit Session active Pair Verify Successful for 0B9ADF46-C311-487C-8B60-6A2C7AA77F39 I (52930) HAP Bridge: Write called for Accessory ESP-Fan-0 I (52930) HAP Bridge: Received Write. Fan On I (53150) HAP Bridge: Write called for Accessory ESP-Fan-0 I (53150) HAP Bridge: Received Write. Fan Off Decryption error/Connection lost. Marking session as invalid HomeKit Session terminated ######## Starting Pair Verify ######## Pair Verify M1 Received Pair Verify M2 Successful Pair Verify M3 Received HomeKit Session active Pair Verify Successful for 0B9ADF46-C311-487C-8B60-6A2C7AA77F39 Decryption error/Connection lost. Marking session as invalid HomeKit Session terminated ######## Starting Pair Verify ######## Pair Verify M1 Received Pair Verify M2 Successful Pair Verify M3 Received HomeKit Session active Pair Verify Successful for 0B9ADF46-C311-487C-8B60-6A2C7AA77F39 I (157290) HAP Bridge: Write called for Accessory ESP-Fan-0 I (157290) HAP Bridge: Received Write. Fan On I (157910) HAP Bridge: Write called for Accessory ESP-Fan-0 I (157910) HAP Bridge: Received Write. Fan Off I (158620) HAP Bridge: Write called for Accessory ESP-Fan-0 I (158620) HAP Bridge: Received Write. Fan On Decryption error/Connection lost. Marking session as invalid HomeKit Session terminated ######## Starting Pair Verify ######## Pair Verify M1 Received Pair Verify M2 Successful Pair Verify M3 Received HomeKit Session active Pair Verify Successful for 0B9ADF46-C311-487C-8B60-6A2C7AA77F39 I (169200) HAP Bridge: Write called for Accessory ESP-Fan-0 I (169200) HAP Bridge: Received Write. Fan Off I (169220) HAP Bridge: Write called for Accessory ESP-Fan-0 I (169220) HAP Bridge: Received Write. Fan On Decryption error/Connection lost. Marking session as invalid HomeKit Session terminated ######## Starting Pair Verify ######## Pair Verify M1 Received Pair Verify M2 Successful Pair Verify M3 Received HomeKit Session active Pair Verify Successful for 0B9ADF46-C311-487C-8B60-6A2C7AA77F39 Decryption error/Connection lost. Marking session as invalid HomeKit Session terminated ######## Starting Pair Verify ######## Pair Verify M1 Received Pair Verify M2 Successful Pair Verify M3 Received HomeKit Session active Pair Verify Successful for 0B9ADF46-C311-487C-8B60-6A2C7AA77F39 Decryption error/Connection lost. Marking session as invalid HomeKit Session terminated ######## Starting Pair Verify ######## Pair Verify M1 Received Pair Verify M2 Successful Pair Verify M3 Received HomeKit Session active Pair Verify Successful for 0B9ADF46-C311-487C-8B60-6A2C7AA77F39 Decryption error/Connection lost. Marking session as invalid HomeKit Session terminated ######## Starting Pair Verify ######## Pair Verify M1 Received Pair Verify M2 Successful Pair Verify M3 Received HomeKit Session active Pair Verify Successful for 0B9ADF46-C311-487C-8B60-6A2C7AA77F39 Decryption error/Connection lost. Marking session as invalid HomeKit Session terminated ######## Starting Pair Verify ######## Pair Verify M1 Received Pair Verify M2 Successful Pair Verify M3 Received HomeKit Session active Pair Verify Successful for 0B9ADF46-C311-487C-8B60-6A2C7AA77F39

qlwz commented 9 months ago

I don't have atv or homepod。 ipad 16.3.1 no problem, ios 12 no problem。 It’s no problem if it’s not a bridge device

hassbian-ABC commented 9 months ago

iPhone13, ios16.6, If the home hub is not connected, the bridge device notification will become invalid,but Aqara is normal

habablaxe commented 8 months ago

@shahpiyushv

iPhone 8, ios 16.7.1 Bridge example. The code is without any modification Same problem: Decryption error/Connection lost. Marking session as invalid HomeKit Session terminated

any ideas or solution?