Wifi connection loss (possible memory leak?) #844
Comments
|
I encountered the same issue as well. |
|
Can you provide a snapshot of some of the log (level L2) that is printed to the serial monitor showing what occurs during those 7 hours (not the whole 7 hours, just a sample). Is the device fully disconnecting from WiFi, such that it won't respond to a ping, to is it just disconnecting from HomeKit? One way to check is to enable the HomeSpan WebLog. If the WebLog does not respond to HTTP requests, then the device is likely not connected to WiFi at all. |
|
|
And there is absolutely no other information provided in the log files with log level set to 2? The decrease you have shown is very minimal. What version of the Arduino-ESP32 board manager are you using? |
|
I can provide you a full log but I can't test it right now. All I can say is that the board loses wifi connection after some hours. I can't ping the device and, using WebLog, it's not reachable. My full code has many stuff to handle so I simply tried the example 1 untouched and I noticed the free memory decreasing I described in my first post. By the way, I'll provide you a full L2 log as soon as I can. As I said I noticed that memory seems to not increase if none of my Apple devices is connected to wifi. But I'll check this thing in my test. |
|
======================================= <<<<<<<<< 192.168.0.104 <<<<<<<<< PUBKEY(32) 922ED26D3E6B9332A9EDCAB3838FCFD02F90D4A38A519219713774BE8DDAB244
PUBKEY(32) BBBC950A4A427DA3F83D2B1696A942A15BCD2BFDAB667477A2B8BD8514EEAE66 <<<<<<<<< 192.168.0.104 <<<<<<<<< *** Verifying session with Controller ID: F46A3796-43BA-43A9-9CA2-0FE53C87FA72...
STATE(1) 04 *** SESSION VERIFICATION COMPLETE *** <<<< #### 192.168.0.104 #### <<<<
{"accessories":[{"aid":1,"services":[{"iid":1,"type":"3E","characteristics":[{"iid":2,"type":"14","format":"bool","perms":["pw"]}]}]},{"aid":2,"services":[{"iid":1,"type":"3E","characteristics":[{"iid":2,"type":"14","format":"bool","perms":["pw"]},{"iid":3,"type":"23","value":"LED1","format":"string","perms":["pr"]}]},{"iid":4,"type":"43","characteristics":[{"iid":5,"type":"25","value":1,"format":"bool","perms":["pr","pw","ev"]},{"iid":6,"type":"13","value":30,"format":"float","perms":["pr","pw","ev"]},{"iid":7,"type":"2F","value":76,"format":"float","perms":["pr","pw","ev"]},{"iid":8,"type":"8","value":100,"format":"int","minValue":5,"maxValue":100,"minStep":1,"perms":["pr","pw","ev"]}]}]},{"aid":3,"services":[{"iid":1,"type":"3E","characteristics":[{"iid":2,"type":"14","format":"bool","perms":["pw"]},{"iid":3,"type":"23","value":"LED2","format":"string","perms":["pr"]}]},{"iid":4,"type":"43","characteristics":[{"iid":5,"type":"25","value":1,"format":"bool","perms":["pr","pw","ev"]},{"iid":6,"type":"CE","value":500,"format":"uint32","perms":["pr","pw","ev"]},{"iid":7,"type":"8","value":100,"format":"int","perms":["pr","pw","ev"]}]}]},{"aid":4,"services":[{"iid":1,"type":"3E","characteristics":[{"iid":2,"type":"14","format":"bool","perms":["pw"]},{"iid":3,"type":"23","value":"Sensor","format":"string","perms":["pr"]}]},{"iid":4,"type":"8A","characteristics":[{"iid":5,"type":"11","value":21.2402,"format":"float","perms":["pr","ev"]},{"iid":6,"type":"75","value":1,"format":"bool","perms":["pr","ev"]}]},{"iid":7,"type":"82","characteristics":[{"iid":8,"type":"10","value":66.013,"format":"float","perms":["pr","ev"]},{"iid":9,"type":"75","value":1,"format":"bool","perms":["pr","ev"]}]}]},{"aid":5,"services":[{"iid":1,"type":"3E","characteristics":[{"iid":2,"type":"14","format":"bool","perms":["pw"]},{"iid":3,"type":"23","value":"风扇","format":"string","perms":["pr"]}]},{"iid":4,"type":"B7","characteristics":[{"iid":5,"type":"B0","value":0,"format":"uint8","perms":["pr","pw","ev"]},{"iid":6,"type":"29","value":0,"format":"float","minValue":0,"maxValue":100,"minStep":50,"perms":["pr","pw","ev"]}]}]}]} The above is a part of the LOG2. Total Heap: 106552 151536 110580 143288 Lowest stack level: 3756 bytes (loopTask) And this is the info showing in the WebLog of my device, By the way, the device have 4 accessories. And i will test the example 1 later. |
|
All that looks fine. The memory should not continually decrease just by being on. If HomeKit is not sending continuous updates, nothing in HomeSpan actually does anything. And having WiFi on does not drain memory on a cumulative basis. But if HomeKit continually connects and disconnects, this could leave a memory leak. Hence, running just example 1 we need to see if there is some sort of repeated HomeKit connect/disconnect over the course of a few hours that gradually eroded all the memory. |
The num of free memory when lossed the connecting showed at above And the Device is trying to connect to Wi-Fi. but it does not work. LOG2:** Client #1 Connected: (24024 sec) 192.168.0.104 on Socket 3/16 <<<<<<<<< 192.168.0.104 <<<<<<<<<
PUBKEY(32) F6404515CCA4980E248AD6FBD66C95365110FFF6E71C42C3EDD2142E34E48E75 <<<<<<<<< 192.168.0.104 <<<<<<<<< *** Verifying session with Controller ID: F46A3796-43BA-43A9-9CA2-0FE53C87FA72...
STATE(1) 04 *** SESSION VERIFICATION COMPLETE *** <<<< #### 192.168.0.104 #### <<<<
{"accessories":[{"aid":1,"services":[{"iid":1,"type":"3E","characteristics":[{"iid":2,"type":"14","format":"bool","perms":["pw"]}]}]},{"aid":2,"services":[{"iid":1,"type":"3E","characteristics":[{"iid":2,"type":"14","format":"bool","perms":["pw"]},{"iid":3,"type":"23","value":"LED1","format":"string","perms":["pr"]}]},{"iid":4,"type":"43","characteristics":[{"iid":5,"type":"25","value":1,"format":"bool","perms":["pr","pw","ev"]},{"iid":6,"type":"13","value":160,"format":"float","perms":["pr","pw","ev"]},{"iid":7,"type":"2F","value":100,"format":"float","perms":["pr","pw","ev"]},{"iid":8,"type":"8","value":10,"format":"int","minValue":5,"maxValue":100,"minStep":1,"perms":["pr","pw","ev"]}]}]},{"aid":3,"services":[{"iid":1,"type":"3E","characteristics":[{"iid":2,"type":"14","format":"bool","perms":["pw"]},{"iid":3,"type":"23","value":"LED2","format":"string","perms":["pr"]}]},{"iid":4,"type":"43","characteristics":[{"iid":5,"type":"25","value":0,"format":"bool","perms":["pr","pw","ev"]},{"iid":6,"type":"CE","value":500,"format":"uint32","perms":["pr","pw","ev"]},{"iid":7,"type":"8","value":100,"format":"int","perms":["pr","pw","ev"]}]}]},{"aid":4,"services":[{"iid":1,"type":"3E","characteristics":[{"iid":2,"type":"14","format":"bool","perms":["pw"]},{"iid":3,"type":"23","value":"Sensor","format":"string","perms":["pr"]}]},{"iid":4,"type":"8A","characteristics":[{"iid":5,"type":Trying to connect to TP-LINK_2581. Waiting 1 sec... *** Can't connect to TP-LINK_2581. You may type 'W ' to re-configure WiFi, or 'X ' to erase WiFi credentials. Will try connecting again in 60 seconds. |
|
The lack of memory you indicate above is very likely the reason why the WiFi is failing. However, we need to figure out why the memory is eroding. This can either be because of something in your sketch that using memory but not freeing it up, or an edge-case in HomeSpan itself. To determine the cause, you must use example 1 since that is a known sketch. Before pairing example 1, make sure to unpair any existing sketches you used from the Home App and then erase all the stored info on the ESP32 using the 'E' command before you re-pair the sketch with Example 1. Once you verify Example 1 is working as expected, note the memory usage using the 'm' command and set log level to L2. Then monitor the serial log output for the full day until the device fails. You should seed almost nothing in the log file with the exception of some potential periodic calls from HomeKit to the the device to check version numbers (sometimes the Home app does this, other times it does not). What we need to look for are unexpected requests. Assuming you are running a Home Hub (which is required for HomeKit and HomeSpan), you should not see a lot of new Verifications as you see above. Once a connection is completed and verified, it should stay open indefinitely. However, it could be that your router is dropping the connection (or the MDNS records, which is VERY common for some routers), which causes HomeKit to re-connect to the ESP32 with a fresh verification process. I have found the re-verification process has a small memory leak of a few hundred bytes, which eventually is reclaimed. If the Home App tries to re-verify a connection every 20 minutes, you may see a slow drain on the memory, but after a full day it will only be something like 10K. However, if the Home App is re-verifying connections every minute or less, this might explain the issue. That's what we need to find out to identify the problem. |
|
I tried the method you suggested. The free memory is constantly decreasing, and the serial output verifies the message about every 2-5 minutes. 21:31:07 
21:32:15 
As shown in the snapshots, free memory decreased 252 in only 1 minute and 8 seconds. A part of LOG2:** Client #1 Connected: (2010 sec) 192.168.0.100 on Socket 2/16 <<<<<<<<< 192.168.0.100 <<<<<<<<<
PUBKEY(32) 1223B640505D63E86F7A1FAA97C2554FC9CA34A87738A5DCC896AF5FB720A05E <<<<<<<<< 192.168.0.100 <<<<<<<<< *** Verifying session with Controller ID: F46A3796-43BA-43A9-9CA2-0FE53C87FA72...
STATE(1) 04 *** SESSION VERIFICATION COMPLETE *** <<<< #### 192.168.0.100 #### <<<<
{"accessories":[{"aid":1,"services":[{"iid":1,"type":"3E","characteristics":[{"iid":2,"type":"14","format":"bool","perms":["pw"]}]},{"iid":3,"type":"43","characteristics":[{"iid":4,"type":"25","value":0,"format":"bool","perms":["pr","pw","ev"]}]}]}]} <<<< #### 192.168.0.104 #### <<<<
-------- SENT ENCRYPTED! -------- ======================================= <<<<<<<<< 192.168.0.104 <<<<<<<<<
PUBKEY(32) 85E133F270146DE4AD4297D8BC04BEF34E6C3FDC6E0A696C3F5AD0899AF40076 <<<<<<<<< 192.168.0.104 <<<<<<<<< *** Verifying session with Controller ID: F46A3796-43BA-43A9-9CA2-0FE53C87FA72...
STATE(1) 04 *** SESSION VERIFICATION COMPLETE *** <<<< #### 192.168.0.104 #### <<<<
{"accessories":[{"aid":1,"services":[{"iid":1,"type":"3E","characteristics":[{"iid":2,"type":"14","format":"bool","perms":["pw"]}]},{"iid":3,"type":"43","characteristics":[{"iid":4,"type":"25","value":0,"format":"bool","perms":["pr","pw","ev"]}]}]}]} ======================================= <<<<<<<<< 192.168.0.104 <<<<<<<<<
PUBKEY(32) EBD5E27E03E1312B065C896F4FA76A6EF6A2661D3B10281610DFDC78CD5D9767 <<<<<<<<< 192.168.0.104 <<<<<<<<< *** Verifying session with Controller ID: F46A3796-43BA-43A9-9CA2-0FE53C87FA72...
STATE(1) 04 *** SESSION VERIFICATION COMPLETE *** <<<< #### 192.168.0.104 #### <<<<
{"accessories":[{"aid":1,"services":[{"iid":1,"type":"3E","characteristics":[{"iid":2,"type":"14","format":"bool","perms":["pw"]}]},{"iid":3,"type":"43","characteristics":[{"iid":4,"type":"25","value":0,"format":"bool","perms":["pr","pw","ev"]}]}]}]} ======================================= <<<<<<<<< 192.168.0.100 <<<<<<<<<
PUBKEY(32) F00556F77492B029A722FC889BF5AA6F5CADFAF7CB6FBE564EC509FEADC20B0D <<<<<<<<< 192.168.0.100 <<<<<<<<< *** Verifying session with Controller ID: F46A3796-43BA-43A9-9CA2-0FE53C87FA72...
STATE(1) 04 *** SESSION VERIFICATION COMPLETE *** <<<< #### 192.168.0.100 #### <<<<
{"accessories":[{"aid":1,"services":[{"iid":1,"type":"3E","characteristics":[{"iid":2,"type":"14","format":"bool","perms":["pw"]}]},{"iid":3,"type":"43","characteristics":[{"iid":4,"type":"25","value":0,"format":"bool","perms":["pr","pw","ev"]}]}]}]} ======================================= <<<<<<<<< 192.168.0.100 <<<<<<<<<
PUBKEY(32) C3FC485112CC3393F4E57C75A5121658ECDC1BEA644FC968D6240483056E0A5C <<<<<<<<< 192.168.0.100 <<<<<<<<< *** Verifying session with Controller ID: F46A3796-43BA-43A9-9CA2-0FE53C87FA72...
STATE(1) 04 *** SESSION VERIFICATION COMPLETE *** <<<< #### 192.168.0.100 #### <<<<
{"accessories":[{"aid":1,"services":[{"iid":1,"type":"3E","characteristics":[{"iid":2,"type":"14","format":"bool","perms":["pw"]}]},{"iid":3,"type":"43","characteristics":[{"iid":4,"type":"25","value":0,"format":"bool","perms":["pr","pw","ev"]}]}]}]} |
I'm running the test right now but I can see I have lots of verification requests. Is this related to me not using a Home Hub? A Home Hub is only required to communicate with HomeKit from a connection that is external to the local one, is it correct? Or am I missing something? By the way, the board is running example 1 and I will post the full log when wifi fails. I added just a few lines of code just to print the memory usage every 60 seconds in order to not type 'm' every time, so you will see how the memory usage increases over time. But I think we found out it is related to verification process. |
|
I also conducted a similar test. I created two homes, each with a Homespan device. One of them was connected to a HomePod mini. After one night (7-9 hours), the Homespan device connected to the HomePod mini operated normally. However, the Homespan device in the home without the connected HomePod mini showed a Wi-Fi connection in progress LED indicator, but it remained unable to connect. Manual reconnection was required for it to operate normally. |
|
Here's my full log. After less than 4 hours the wifi failed. The log shows many verification requiests, so I think we found the issue. Is it related to the fact that I am not using a Home Hub? |
|
Thanks @VictorrFang, I think this confirms the issue. The problem stems from using HomeSpan without a Home Hub. Though Apple says it is possible to use a HomeKit device without a Home Hub (though with much more limited functionality), it seems Apple changed something in the Home App that causes near-continuous requests for a connection. This should never occur as HomeKit connections are supposed to stay open indefinitely. It used to be that if you did not use a Home Hub the Home App would disconnect after it was closed and only reconnect when opened again. But if you are seeing continued requests for a connection, Apple likely changed something. It is also possible that the problem lies in the particular router being used, but your test strongly suggests that it is the Home App making the requests not the router. I'll update the main HomeSpan page to indicate that a Home Hub is now required for any use of HomeSpan. As for the memory leak itself, Ive been able to debug the issue using my own kit and it seems like the Home App is not properly disconnecting from the ESP32 interface, which leave the socket open. I've looked at the ESP32 code in detail, and though it recognizes the connection has been terminated, it does not seem to reclaim the memory used for the socket. I can check for this and ensure the socket is completely closed whenever HomeSpan detects a connection has abruptly terminated, which I think should solve the memory leakage (though I need to test this to confirm). But regardless, even without the memory problem caused by abrupt disconnects, HomeKit is not supposed to operate with continued requests for a connection, so as noted above, I think this means a Home Hub needs to be used. |
|
Thanks @HomeSpan. If you can solve the memory leakage let us know. I think this should allow to use HomeSpan even without a Home Hub even if the Home app keeps sending continuous requests. |
|
Sure thing - If I can resolve I'll add to next release and preview in the dev branch for you to test. |
For me this issue started when I changed my old iPhone to the new iPhone running IOS 17 because it support new Homekit, my old iPhone was using IOS 15 with old Homekit I didn't get any issue. It seems like this change came with new Homekit on IOS 16. |
|
Are you using a Home Hub? |
yes now I'm using home hub everything is ok, but without home hub even reflesh of accessories take time, you need to close the home app and open it again. old homekit with ios 15 was running good without home hub |
|
Yes, Apple completely changed the way communication works around iOS 16.3 or so. But they changed it for usage with a Home Hub as well as without a Home Hub. So if you did not use a Home Hub you lost a lot of functionality as well as needed to often re-open the Home App to get an update. In addition, there is a memory leak issue, which I've identified and will be fixing for the next release. This leak only impacts the case where you don't use a Home Hub under the new HomeKit architecture (this was not an issue prior to iOS 16). |
Hi,
I have a problem using homespan. After some hours (~7/9 hours) wifi connection is lost. In order to narrow what the problem could be, I tried the example 1 unmodified and the issue persists. From the serial monitor I don't get the "*** WiFi Connection Lost!" message but I can't ping the device and, from the router page, I can't see the device so the connection is actually lost. I also noticed that free heap size decreases over time. I read somewhere in the internet that Wifi library uses heap someway, so could the problem be related to a memory leak somewhere?
During my debug I also noticed that the free heap size decreases when a paired Apple device is connected to wifi: if none of my Apple devices is connected to wifi the free heap size is constant over time.
So my idea is that heap is saturated after some hours causing wifi problems.
I'm currently using homespan 1.9.0, I've also tried version 1.9.0dev but same issue.
Rebooting the device solves the problem. Device runs for some hours and disconnects again.
The text was updated successfully, but these errors were encountered: