Arduino-HomeKit-ESP8266 icon indicating copy to clipboard operation
Arduino-HomeKit-ESP8266 copied to clipboard

Published 20 hours ago • verified publisher icon Mixiaoxiao

Disconnect/WiFi reset on step 2/3

Open BbIKTOP opened this issue 3 years ago • 21 comments

Am I doing something wrong? It connects sometimes, but mostly does not. This is the switch example:

WiFi connecting...
..............................................................
WiFi connected, IP: 172.16.5.184


Started, frequency set to 160
>>> [   7094] HomeKit: Starting server
>>> [   7102] HomeKit: Using existing accessory ID: CD:06:D4:33:B5:5B
>>> [   7109] HomeKit: Preiniting pairing context
>>> [   7113] HomeKit: Using user-specified password: 111-11-111
>>> [   7135] HomeKit: Call s_mp_exptmod in integer.c, original winsize 6
>>> [  13178] HomeKit: Call s_mp_exptmod in integer.c, original winsize 5
>>> [  16263] HomeKit: Preinit pairing context success
>>> [  16268] HomeKit: Configuring MDNS
>>> [  16273] HomeKit: MDNS begin: ESPswitch2, IP: 172.16.5.184
>>> [  16280] HomeKit: Init server over
Free heap: 42208, HomeKit clients: 0
>>> [  19481] HomeKit: WiFi connected, ip: 172.16.5.184, mask: 255.255.0.0, gw: 172.16.1.1
>>> [  19489] HomeKit: Configuring MDNS
>>> [  19493] HomeKit: MDNS restart: ESPswitch2, IP: 172.16.5.184
Free heap: 42880, HomeKit clients: 0
Free heap: 42600, HomeKit clients: 0
>>> [  28587] HomeKit: Got new client: local 172.16.5.184:5556, remote 172.16.5.134:57703
>>> [  28596] HomeKit: [Client 1073683452] Pair Setup Step 1/3
Free heap: 40672, HomeKit clients: 1
>>> [  33498] HomeKit: [Client 1073683452] Pair Setup Step 2/3
>>> [  33509] HomeKit: Call s_mp_exptmod in integer.c, original winsize 6
>>> [  42190] HomeKit: Call s_mp_exptmod in integer.c, original winsize 5
Free heap: 40224, HomeKit clients: 1
>>> [  46569] HomeKit: [Client 1073683452] Disconnected!
>>> [  46574] HomeKit: [Client 1073683452] Closing client connection
>>> [  46580] HomeKit: Free saved_preinit_pairing_context
>>> [  46585] HomeKit: [Client 0] Clear the pairing context
>>> [  46601] HomeKit: Preiniting pairing context
>>> [  46605] HomeKit: Using user-specified password: 111-11-111
>>> [  46626] HomeKit: Call s_mp_exptmod in integer.c, original winsize 6
>>> [  52657] HomeKit: Call s_mp_exptmod in integer.c, original winsize 5
>>> [  55738] HomeKit: Preinit pairing context success
Free heap: 43280, HomeKit clients: 0
>>> [  57912] HomeKit: WiFi connected, ip: 172.16.5.184, mask: 255.255.0.0, gw: 172.16.1.1
>>> [  57921] HomeKit: Configuring MDNS
>>> [  57927] HomeKit: MDNS restart: ESPswitch2, IP: 172.16.5.184
Free heap: 43216, HomeKit clients: 0
Free heap: 42512, HomeKit clients: 0
Free heap: 42728, HomeKit clients: 0

BbIKTOP avatar Mar 15 '21 18:03 BbIKTOP

Yeah same here

mgx0 avatar Mar 22 '21 11:03 mgx0

I suppose i know why lol ) will check and make a pr today or tomorrow

BbIKTOP avatar Mar 22 '21 12:03 BbIKTOP

well I have tried different board and it works well .. but anyway please get back if you have more info

mgx0 avatar Mar 22 '21 12:03 mgx0

Tried 5 or 6 of my 12e/f with no success. The problem is, that wifi disconnects on the key calculations on nonos 8266. Need to add yield in the exptmod and maybe other wolf foos as we discussed it here https://github.com/Yurik72/ESPHap/issues/80

BbIKTOP avatar Mar 22 '21 12:03 BbIKTOP

Btw, what boards did you use for testing? Just wonder why it works with your esps, as i see, it just could not. But maybe it depends on wifi ap settings, dunno. Searched mine and found nothing special

BbIKTOP avatar Mar 22 '21 12:03 BbIKTOP

Hey Viktor,

well, they are all ultra cheap chinese development boards, looks like a NodeMCU v1

but I recommend trying this one, looks like it is alive and in active development: https://github.com/Yurik72/ESPHap on ESP32 it's blazing fast :)

mgx0 avatar Mar 22 '21 13:03 mgx0

Tested the same as well, with the same result. Esp32 is good but i still have a bunch of 12f )) I am aware of esphap, fixed the same problem in it yesterday, now faced memory leak. It is not related to this lib anyway, so we’d better stay focused on this pairing problem ;)

BbIKTOP avatar Mar 22 '21 13:03 BbIKTOP

Try https://github.com/Mixiaoxiao/Arduino-HomeKit-ESP8266/commit/8a8fd7b9afec4a00449da770470012814912d1f9

The idea is from BbIKTOP-issues80

Mixiaoxiao avatar Mar 30 '21 15:03 Mixiaoxiao

Try 8a8fd7b

The idea is from BbIKTOP-issues80

Oh, thank you, man! Still have no time for researches, sorry, it's good that you did it!

BbIKTOP avatar Mar 30 '21 15:03 BbIKTOP

Btw, as you're much more familiar with the code, wouln't you mind to replace wolfssl with bearssl, which is bundled with arduino core/esp8266? It would save a lot of resources.

BbIKTOP avatar Mar 30 '21 23:03 BbIKTOP

@Mixiaoxiao @BbIKTOP I did what was proposed, but still didnt work, please note, that I let only homekit code, but still it has problems

beckmx avatar Apr 01 '21 21:04 beckmx

Tested it again and everything works fine. What exact problem do you have?

BbIKTOP avatar Apr 04 '21 12:04 BbIKTOP

I have the same issue, cannot pair my ESP6288. I added yield() however it does not solve the disconnect behavior …

ManoloWer avatar Jul 14 '21 20:07 ManoloWer

.............................. WiFi connected, IP: 192.168.178.52

[ 3906] HomeKit: Update the CPU to run at 160MHz [ 3914] HomeKit: Starting server [ 3918] HomeKit: Using existing accessory ID: 72:28:DB:55:6B:C6 [ 3924] HomeKit: Preiniting pairing context [ 3928] HomeKit: Using user-specified password: 111-11-111 [ 3949] HomeKit: Call s_mp_exptmod in integer.c, original winsize 6 [ 10649] HomeKit: Call s_mp_exptmod in integer.c, original winsize 5 [ 14081] HomeKit: Preinit pairing context success [ 14086] HomeKit: Configuring MDNS [ 14091] HomeKit: MDNS begin: Test Sensor, IP: 192.168.178.52 [ 14098] HomeKit: Init server over Current temperature: 29.0 Free heap: 41400, HomeKit clients: 0 [ 18595] HomeKit: Got new client: local 192.168.178.52:5556, remote 192.168.178.59:51341 [ 18616] HomeKit: [Client 1073682708] Pair Setup Step 1/3 Free heap: 40240, HomeKit clients: 1 [ 22051] HomeKit: [Client 1073682708] Pair Setup Step 2/3 [ 22066] HomeKit: Call s_mp_exptmod in integer.c, original winsize 6 [ 42337] HomeKit: Call s_mp_exptmod in integer.c, original winsize 5 !!! [ 52328] HomeKit: [Client 1073682708] The socket is null! (or is closed) Current temperature: 29.0 Free heap: 40424, HomeKit clients: 1 [ 52358] HomeKit: [Client 1073682708] Disconnected! [ 52363] HomeKit: [Client 1073682708] Closing client connection [ 52370] HomeKit: Free saved_preinit_pairing_context [ 52375] HomeKit: [Client 0] Clear the pairing context [ 52390] HomeKit: Preiniting pairing context [ 52395] HomeKit: Using user-specified password: 111-11-111 [ 52428] HomeKit: Call s_mp_exptmod in integer.c, original winsize 6 [ 65915] HomeKit: Call s_mp_exptmod in integer.c, original winsize 5 [ 72785] HomeKit: Preinit pairing context success [ 72793] HomeKit: Got new client: local 192.168.178.52:5556, remote 192.168.178.59:51343 [ 72803] HomeKit: [Client 1073684716] Pair Setup Step 1/3 !!! [ 72809] HomeKit: [Client 1073684716] The socket is null! (or is closed) Current temperature: 24.0 Free heap: 39384, HomeKit clients: 1 [ 72836] HomeKit: Got new client: local 192.168.178.52:5556, remote 192.168.178.59:51344 [ 72846] HomeKit: [Client 1073682596] Pair Setup Step 1/3 [ 72852] HomeKit: [Client 1073682596] Refusing to pair: another pairing in progress [ 72862] HomeKit: [Client 1073684716] Disconnected! [ 72867] HomeKit: [Client 1073684716] Closing client connection [ 72874] HomeKit: Free saved_preinit_pairing_context [ 72879] HomeKit: [Client 0] Clear the pairing context [ 72895] HomeKit: Preiniting pairing context [ 72899] HomeKit: Using user-specified password: 111-11-111 [ 72933] HomeKit: Call s_mp_exptmod in integer.c, original winsize 6 [ 86371] HomeKit: Call s_mp_exptmod in integer.c, original winsize 5 [ 93221] HomeKit: Preinit pairing context success [ 93232] HomeKit: [Client 1073682596] Disconnected! [ 93238] HomeKit: [Client 1073682596] Closing client connection

ManoloWer avatar Jul 15 '21 19:07 ManoloWer

Any ideas... how to proceed after pair setup step 2/3?

ManoloWer avatar Jul 15 '21 19:07 ManoloWer

I made this PR and its been rock-solid for me. Although I only scoped it to LOWMEM, it may be worth putting it in the main code path. PR Request 138

dsbaha avatar Jul 20 '21 16:07 dsbaha

Ok, re-did everything and I could pair with another iOS device successfully (not iOS15!). Thanks for your support!

ManoloWer avatar Jul 26 '21 08:07 ManoloWer

Just tried another board and got same problem. 'yield()' already added and the network should be stable because I tried two positions showing strong wireless connection but still disconnect after step 2/3 for 'The socket is null! (or is closed)'. There must be some trouble during data transfer and I can't find it. Still looking for solution, and thanks for such a wonderful project!

Here's my situation after tried two boards (NodeMCU) several times:

Free heap: 41560, HomeKit clients: 0
Free heap: 41992, HomeKit clients: 0
Free heap: 41832, HomeKit clients: 0
\>>> [  25268] HomeKit: Got new client: local 192.168.5.159:5556, remote 192.168.5.203:58678
\>>> [  25278] HomeKit: [Client 1073681676] Pair Setup Step 1/3
Free heap: 40392, HomeKit clients: 1
\>>> [  30380] HomeKit: [Client 1073681676] Pair Setup Step 2/3
\>>> [  30391] HomeKit: Call s_mp_exptmod in integer.c, original winsize 6
\>>> [  40524] HomeKit: Call s_mp_exptmod in integer.c, original winsize 5
!!! [  45516] HomeKit: [Client 1073681676] The socket is null! (or is closed)
Free heap: 40808, HomeKit clients: 1
\>>> [  45537] HomeKit: [Client 1073681676] Disconnected!
\>>> [  45542] HomeKit: [Client 1073681676] Closing client connection
\>>> [  45548] HomeKit: Free saved_preinit_pairing_context
\>>> [  45553] HomeKit: [Client 0] Clear the pairing context
\>>> [  45568] HomeKit: Preiniting pairing context
\>>> [  45573] HomeKit: Using user-specified password: 114-11-411
\>>> [  45592] HomeKit: Call s_mp_exptmod in integer.c, original winsize 6
\>>> [  52342] HomeKit: Call s_mp_exptmod in integer.c, original winsize 5
\>>> [  55659] HomeKit: Preinit pairing context success
Free heap: 41600, HomeKit clients: 0
\>>> [  60594] HomeKit: Got new client: local 192.168.5.159:5556, remote 192.168.5.203:58679
\>>> [  60604] HomeKit: [Client 1073682388] Pair Setup Step 1/3
Free heap: 40384, HomeKit clients: 1
\>>> [  60706] HomeKit: [Client 1073682388] Pair Setup Step 2/3
\>>> [  60717] HomeKit: Call s_mp_exptmod in integer.c, original winsize 6
\>>> [  70566] HomeKit: Call s_mp_exptmod in integer.c, original winsize 5
!!! [  75504] HomeKit: [Client 1073682388] The socket is null! (or is closed)
Free heap: 40928, HomeKit clients: 1
\>>> [  75525] HomeKit: [Client 1073682388] Disconnected!
\>>> [  75530] HomeKit: [Client 1073682388] Closing client connection
\>>> [  75536] HomeKit: Free saved_preinit_pairing_context
\>>> [  75541] HomeKit: [Client 0] Clear the pairing context
\>>> [  75556] HomeKit: Preiniting pairing context
\>>> [  75561] HomeKit: Using user-specified password: 114-11-411
\>>> [  75580] HomeKit: Call s_mp_exptmod in integer.c, original winsize 6
\>>> [  82328] HomeKit: Call s_mp_exptmod in integer.c, original winsize 5
\>>> [  85746] HomeKit: Preinit pairing context success

BarryAlanPan avatar Aug 02 '21 06:08 BarryAlanPan

Just tried another board and got same problem. 'yield()' already added and the network should be stable because I tried two positions showing strong wireless connection but still disconnect after step 2/3 for 'The socket is null! (or is closed)'. There must be some trouble during data transfer and I can't find it. Still looking for solution, and thanks for such a wonderful project!

Here's my situation after tried two boards (NodeMCU) several times:

Free heap: 41560, HomeKit clients: 0
Free heap: 41992, HomeKit clients: 0
Free heap: 41832, HomeKit clients: 0
\>>> [  25268] HomeKit: Got new client: local 192.168.5.159:5556, remote 192.168.5.203:58678
\>>> [  25278] HomeKit: [Client 1073681676] Pair Setup Step 1/3
Free heap: 40392, HomeKit clients: 1
\>>> [  30380] HomeKit: [Client 1073681676] Pair Setup Step 2/3
\>>> [  30391] HomeKit: Call s_mp_exptmod in integer.c, original winsize 6
\>>> [  40524] HomeKit: Call s_mp_exptmod in integer.c, original winsize 5
!!! [  45516] HomeKit: [Client 1073681676] The socket is null! (or is closed)
Free heap: 40808, HomeKit clients: 1
\>>> [  45537] HomeKit: [Client 1073681676] Disconnected!
\>>> [  45542] HomeKit: [Client 1073681676] Closing client connection
\>>> [  45548] HomeKit: Free saved_preinit_pairing_context
\>>> [  45553] HomeKit: [Client 0] Clear the pairing context
\>>> [  45568] HomeKit: Preiniting pairing context
\>>> [  45573] HomeKit: Using user-specified password: 114-11-411
\>>> [  45592] HomeKit: Call s_mp_exptmod in integer.c, original winsize 6
\>>> [  52342] HomeKit: Call s_mp_exptmod in integer.c, original winsize 5
\>>> [  55659] HomeKit: Preinit pairing context success
Free heap: 41600, HomeKit clients: 0
\>>> [  60594] HomeKit: Got new client: local 192.168.5.159:5556, remote 192.168.5.203:58679
\>>> [  60604] HomeKit: [Client 1073682388] Pair Setup Step 1/3
Free heap: 40384, HomeKit clients: 1
\>>> [  60706] HomeKit: [Client 1073682388] Pair Setup Step 2/3
\>>> [  60717] HomeKit: Call s_mp_exptmod in integer.c, original winsize 6
\>>> [  70566] HomeKit: Call s_mp_exptmod in integer.c, original winsize 5
!!! [  75504] HomeKit: [Client 1073682388] The socket is null! (or is closed)
Free heap: 40928, HomeKit clients: 1
\>>> [  75525] HomeKit: [Client 1073682388] Disconnected!
\>>> [  75530] HomeKit: [Client 1073682388] Closing client connection
\>>> [  75536] HomeKit: Free saved_preinit_pairing_context
\>>> [  75541] HomeKit: [Client 0] Clear the pairing context
\>>> [  75556] HomeKit: Preiniting pairing context
\>>> [  75561] HomeKit: Using user-specified password: 114-11-411
\>>> [  75580] HomeKit: Call s_mp_exptmod in integer.c, original winsize 6
\>>> [  82328] HomeKit: Call s_mp_exptmod in integer.c, original winsize 5
\>>> [  85746] HomeKit: Preinit pairing context success

This trouble shown in iOS 15. But when it turns to iOS 14, the trouble solved, it's probably Apple's fault.

BarryAlanPan avatar Aug 02 '21 07:08 BarryAlanPan

My yield() patch is only relevant for boards compiled w/ the low_mem option. Maybe modify the patch so it runs on the default options as well?

\>>> [  60717] HomeKit: Call s_mp_exptmod in integer.c, original winsize 6
\>>> [  70566] HomeKit: Call s_mp_exptmod in integer.c, original winsize 5

Look at the time different between the two. I wonder if Apple shortened the timeout time on iOS 15.

dsbaha avatar Aug 06 '21 00:08 dsbaha

It seems to be an iOS 15 problem indeed. No problem pairing with iPadOS 14.2 but iOS 15.0 on iPhone does not work. Logs Attached:

iOS 15 
>>> [ 246078] HomeKit: Got new client: local 192.168.2.64:5556, remote 192.168.2.77:60801
>>> [ 246087] HomeKit: [Client 1073691116] Pair Setup Step 1/3
>>> [ 248175] HomeKit: [Client 1073691116] Pair Setup Step 2/3
>>> [ 248185] HomeKit: Call s_mp_exptmod in integer.c, original winsize 6
>>> [ 256913] HomeKit: Call s_mp_exptmod in integer.c, original winsize 5
!!! [ 261362] HomeKit: [Client 1073691116] The socket is null! (or is closed)
>>> [ 261377] HomeKit: [Client 1073691116] Disconnected!
>>> [ 261382] HomeKit: [Client 1073691116] Closing client connection
>>> [ 261388] HomeKit: Free saved_preinit_pairing_context
>>> [ 261393] HomeKit: [Client 0] Clear the pairing context
>>> [ 261399] HomeKit: Preiniting pairing context
>>> [ 261404] HomeKit: Using user-specified password: 111-11-111
>>> [ 261424] HomeKit: Call s_mp_exptmod in integer.c, original winsize 6
>>> [ 267515] HomeKit: Call s_mp_exptmod in integer.c, original winsize 5
>>> [ 270639] HomeKit: Preinit pairing context success
>>> [ 280793] HomeKit: Got new client: local 192.168.2.64:5556, remote 192.168.2.77:60802
>>> [ 280803] HomeKit: [Client 1073691116] Pair Setup Step 1/3
>>> [ 281015] HomeKit: [Client 1073691116] Pair Setup Step 2/3
>>> [ 281026] HomeKit: Call s_mp_exptmod in integer.c, original winsize 6
>>> [ 289963] HomeKit: Call s_mp_exptmod in integer.c, original winsize 5
!!! [ 294430] HomeKit: [Client 1073691116] The socket is null! (or is closed)
>>> [ 294444] HomeKit: [Client 1073691116] Disconnected!
>>> [ 294449] HomeKit: [Client 1073691116] Closing client connection
>>> [ 294455] HomeKit: Free saved_preinit_pairing_context
>>> [ 294460] HomeKit: [Client 0] Clear the pairing context
>>> [ 294466] HomeKit: Preiniting pairing context
>>> [ 294471] HomeKit: Using user-specified password: 111-11-111
>>> [ 294491] HomeKit: Call s_mp_exptmod in integer.c, original winsize 6
>>> [ 300576] HomeKit: Call s_mp_exptmod in integer.c, original winsize 5
>>> [ 303712] HomeKit: Preinit pairing context success
Then it takes about 20 Seconds before the Home App says "Unable to Add Accessory"
iOS 14.2 on iPad 
>>> [ 496733] HomeKit: Got new client: local 192.168.2.64:5556, remote 192.168.2.79:52722
>>> [ 496743] HomeKit: [Client 1073691140] Pair Setup Step 1/3
>>> [ 499891] HomeKit: [Client 1073691140] Pair Setup Step 2/3
>>> [ 499901] HomeKit: Call s_mp_exptmod in integer.c, original winsize 6
>>> [ 508785] HomeKit: Call s_mp_exptmod in integer.c, original winsize 5
>>> [ 513397] HomeKit: [Client 1073691140] Pair Setup Step 3/3
>>> [ 513425] HomeKit: Call ge_double_scalarmult_vartime_lowmem in ge_low_mem.c
>>> [ 514178] HomeKit: Added pairing with AB628F93-BD6C-498C-8518-F779231F8650
>>> [ 514242] HomeKit: Free saved_preinit_pairing_context
>>> [ 514247] HomeKit: [Client 1073691140] Successfully paired
>>> [ 514290] HomeKit: [Client 1073691140] Disconnected!
>>> [ 514295] HomeKit: [Client 1073691140] Closing client connection
>>> [ 514309] HomeKit: Got new client: local 192.168.2.64:5556, remote 192.168.2.79:52723
>>> [ 514319] HomeKit: [Client 1073684876] Pair Verify Step 1/2
>>> [ 514632] HomeKit: Free heap: 35344
>>> [ 514657] HomeKit: [Client 1073684876] Pair Verify Step 2/2
>>> [ 514664] HomeKit: [Client 1073684876] Found pairing with AB628F93-BD6C-498C-8518-F779231F8650
>>> [ 514685] HomeKit: Call ge_double_scalarmult_vartime_lowmem in ge_low_mem.c
>>> [ 515447] HomeKit: [Client 1073684876] Verification successful, secure session established
>>> [ 515456] HomeKit: Free heap: 36312
>>> [ 515518] HomeKit: [Client 1073684876] Get Accessories
>>> [ 515694] HomeKit: [Client 1073684876] Update Characteristics
>>> [ 515708] HomeKit: [Client 1073684876] Update Characteristics
>>> [ 515722] HomeKit: [Client 1073684876] Update Characteristics
>>> [ 515737] HomeKit: [Client 1073684876] Get Characteristics
>>> [ 517009] HomeKit: Got new client: local 192.168.2.64:5556, remote 192.168.2.77:60807
>>> [ 517019] HomeKit: [Client 1073687148] Pair Verify Step 1/2
>>> [ 517332] HomeKit: Free heap: 33744
>>> [ 517344] HomeKit: [Client 1073687148] Pair Verify Step 2/2
>>> [ 517351] HomeKit: [Client 1073687148] Found pairing with AB628F93-BD6C-498C-8518-F779231F8650
>>> [ 517372] HomeKit: Call ge_double_scalarmult_vartime_lowmem in ge_low_mem.c
>>> [ 518135] HomeKit: [Client 1073687148] Verification successful, secure session established

dunklesToast avatar Aug 14 '21 11:08 dunklesToast