Pairing Problem using Light Bulb example

[pierreauclair]

Hi,
First of all, thanks for this amazing job. The documentation is particularly good (which not so frequent), so I very big thumbs up 👍 for your effort.

I'm running the Lightbulb sample on a ESP32 DevKit v1 board with ESP32 WROOM32. The only modifications are :

homeSpan.setStatusPin(2);
homeSpan.setLogLevel(2);

before the homeSpan.begin

The ESP32 is connected to the WiFi but I can not pair it with the HomeKit App. I looked at aladin21 post and used the mdns browser. I can find the device with the following carateristics :

c# = 2
ci = 5
ff = 0
id = 0A:38:C2:D8:D9:C8
md = HomeSpan-ESP32
pv = 1.1
s# = 1
sf = 1
sh = t9Iitg==

I can see the 2 keys exchanges but the Home App tells me the device can not be paired. My iPhone is on the latest iOS version 14.4.

Here is my log content :

************************************************************
Welcome to HomeSpan!
Apple HomeKit for the Espressif ESP-32 WROOM and Arduino IDE
************************************************************

** Please ensure serial monitor is set to transmit <newlines>

Message Logs:     Level 2
Status LED:       Pin 2
Device Control:   Pin 21
HomeSpan Version: 1.1.4
ESP-IDF Version:  v3.2.3-14-gd3e562907
Sketch Compiled:  Feb  4 2021 13:19:24

Device Name:      HomeSpan LightBulb


*** HomeSpan Info ***

+Accessory-1
-->Service AccessoryInformation-1 (3E) 
---->Characteristic Name-2 (23) 
---->Characteristic Manufacturer-3 (20) 
---->Characteristic SerialNumber-4 (30) 
---->Characteristic Model-5 (21) 
---->Characteristic FirmwareRevision-6 (52) 
---->Characteristic Identify-7 (14) 
-->Service HAPProtocolInformation-8 (A2) 
---->Characteristic Version-9 (37) 
-->Service LightBulb-10 (43) 
---->Characteristic On-11 (25) 

Configured as Bridge: NO

Service                         Type         AID  IID  Update  Loop  Button
------------------------------  ----  ----------  ---  ------  ----  ------
AccessoryInformation              3E           1    1      NO    NO      NO
HAPProtocolInformation            A2           1    8      NO    NO      NO
LightBulb                         43           1   10      NO    NO      NO

*** End Info ***

Accessory ID:      0A:38:C2:D8:D9:C8                               LTPK: B35EB1FD0C144C9480390F9C108E57D43D55A46B24EC1D5E6B805B6ECB9C4012
No Paired Controllers

Accessory configuration has changed.  Updating configuration number to 2

HomeSpan LightBulb is READY!

Trying to connect to homenetwork.  Waiting 1 second(s) for response...
[E][WiFiClient.cpp:460] available(): fail on fd 0, errno: 9, "Bad file number"
[E][WiFiClient.cpp:460] available(): fail on fd 0, errno: 9, "Bad file number"
[E][WiFiClient.cpp:460] available(): fail on fd 0, errno: 9, "Bad file number"
[E][WiFiClient.cpp:460] available(): fail on fd 0, errno: 9, "Bad file number"
[E][WiFiClient.cpp:460] available(): fail on fd 0, errno: 9, "Bad file number"
[E][WiFiClient.cpp:460] available(): fail on fd 0, errno: 9, "Bad file number"
[E][WiFiClient.cpp:460] available(): fail on fd 0, errno: 9, "Bad file number"
[E][WiFiClient.cpp:460] available(): fail on fd 0, errno: 9, "Bad file number"
Successfully connected to homenetwork! IP Address: 192.168.3.21

Starting MDNS...

HostName:      HomeSpan-0A38C2D8D9C8.local:80
Display Name:  HomeSpan LightBulb
Model Name:    HomeSpan-ESP32

Starting Web (HTTP) Server supporting up to 8 simultaneous connections...

DEVICE NOT YET PAIRED -- PLEASE PAIR WITH HOMEKIT APP

=======================================
** Client #0 Connected: (25 sec) 192.168.3.193

<<<<<<<<< 192.168.3.193 <<<<<<<<<
POST /pair-setup HTTP/1.1
Host: HomeSpan\032LightBulb._hap._tcp.local
Content-Length: 6
Content-Type: application/pairing+tlv8
------------ END BODY! ------------
STATE(1) 01
METHOD(1) 00
------------ END TLVS! ------------
In Pair Setup...Found <M1>.  Expected <M1>

>>>>>>>>>> 192.168.3.193 >>>>>>>>>>
HTTP/1.1 200 OK
Content-Type: application/pairing+tlv8
Content-Length: 408

STATE(1) 02
PUBKEY(384) 161A3FF0E5521C7DF35F2BD1575F43EEE936A59FCB8737A47C7FECB03345D1D6579495C452B34ED83942340FE12889C41255BEBF686EF014CBB07CAFE57F414733A89F492EAE6A4CF15FA4D47FAF572A9E4D7E0EEA9BAAC87FA46A358ABED268CC393EB443799210E7CBBE8AC224183817B7A7E23748AC8A11C703C7D9AFC97E6406DF267A509E12B274621D908AE2012F51DA22C0B7CED571F9E52FC94E820D0E2A78DCDD51FF9470F43B7375EC0DD3E36A6018379BC1B3CABC235918234F3FD767C394305BD952EBB250C5CE006B79579BF3D114F26A076EB6175BCA506B17037C9E991CEAC8477E6460E61D50EA045694879D92CC6B12C36FB1FE23678F9F730CA0585E6E55932407161DD4648BEACFBDE5E1B13C5AB8A5BE90EBB630CD253A315CDB8768F9C7770CC231B748B1967F573FB10EF3D90348AED3EF2C71B7D85A16B1ADFE78FE01422FBE284103299EC1D9E67B365EBB553811E6F71C01CD28391D1266DADC31E47D5E3524AFC768D0B51CE61F59726B1A01FCF43DF7AFF0CD
SALT(15) F8C43D9F8D5942FE38F302A2B1EA13
------------ SENT! --------------

=======================================
** Client #0 Connected: (47 sec) 192.168.3.193

<<<<<<<<< 192.168.3.193 <<<<<<<<<
POST /pair-setup HTTP/1.1
Host: HomeSpan\032LightBulb._hap._tcp.local
Content-Length: 6
Content-Type: application/pairing+tlv8
------------ END BODY! ------------
STATE(1) 01
METHOD(1) 00
------------ END TLVS! ------------
In Pair Setup...Found <M1>.  Expected <M1>

>>>>>>>>>> 192.168.3.193 >>>>>>>>>>
HTTP/1.1 200 OK
Content-Type: application/pairing+tlv8
Content-Length: 408

STATE(1) 02
PUBKEY(384) C66B3C4D0F65604D65075074DC3CD4BEDD60E2F800DE9089AA4D039106B659ECDE1A076122221DBD81CC75EDA88AD3AED9F6B7AAB08900E2427AE9A3435985A1EFF9922BF4D97DEAF57D952C1D970E2918094470F5454F2461BD03578D99CAA636B72FBC891D2B555E9B422DC7D75D4E8EAE540ADA56AF859E347A09B068E5D83A4BFA725F17A91FF265FAEDF595CAB196628166F8C9200AF4CABFB3CB61198F172EFA59F051082C6E418405A9B3EE7335A9A8A0AFBA0C03BBA3A08C7DD8013A5068D9D93C94E0706436095D8ADAC4952CA4026C027F3E2654C93BD642C736C86A9C65FC99CC279BD7F9EF39D8F469D378DEAF81206719032995FF685E764882B9FBBE89C00297A834CB971D31E2FE846F086AE4E65113F9969CD9AE944DB29DBD6643DC5C41ED341DFA802F9E9C314F6136F4BAA08F80C5A268BFF7CF12CC525C845852D3762B37B2B41C9C8B08519A1C54EA61DD461354645E195FC52C7A4E10D2061F4466C87B89A08121388C52BFADD1369CAD4B3334C40B901218DBD67E
SALT(15) F8C43D9F8D5942FE38F302A2B1EA13
------------ SENT! --------------

Any idea ?

Many thanks for your help.

[HomeSpan]

It appears that the Home App is not receiving responses from HomeSpan to its <M1> pairing request. After sending <M1> the next request from the Home App should be <M3>, rather than a repeated <M1> request. The errors being reported from WiFiClient.cpp suggest that this is a WiFi problem as opposed to a pairing problem -- you should definitely not be receiving these errors (they are not HomeSpan errors, but produced by ESP32 code itself). I'll see if I can track down what this error means, but in the interim, can you try changing the statusPin to something else? What is the specific ESP32 board you are using (the manufacturer)?

[HomeSpan]

Update and Solution: I realized that you must have compiled with the Debug Level set to "Errors." When I do so, I get the same error messages from WiFiClient, but yet I can pair correctly. So this problem has nothing to do with the WiFi report of errors - sorry to lead us down the wrong path.

However, I did finally notice in your log output that the SALT chosen by HomeSpan is only 15 bytes. This can only happen if the initial byte is zero, and there's a 1 in 256 chance that this will occur. My guess is HomeKit needs the initial zero, which is something I can explore and fix in the code in the next patch release.

In the interim, you can solve this by typing 'E' into the Arduino Serial Monitor. This erases the NVS which causes HomeSpan to generate a new SALT, which hopefully will be 16 bytes (less than 0.5% chance that it will be 15 bytes again). Note you'll have to also re-type your WiFi credentials after executing the 'E' command since those will have been erased as well. Please let me know if this solves the problem.

[pierreauclair]

Hi, Thank you very much.
It worked fine. I must be very unlucky, good for me that I did not try the lottery ;-)
Thanks again.

[HomeSpan]

Really glad it's working. I was able to reproduce the problem and fix the issue. The fix will be part of next patch release (1.1.5)