ESP32 - Not responding

[pbendersky]

I'm hitting the same "No response" error as others when running on an ESP32 device. It was running perfectly for about 6 hours. I left it connected overnight, and in the morning, I get "No response" on all my iOS devices.

The last log I have is:

>>> HomeKit: [Client 55] Update Characteristics
>>> homekit_server_on_update_characteristics: Free heap: 211408
>>> homekit_server_on_update_characteristics: [Client 55] Processing element {
    "aid":  1,
    "iid":  18,
    "ev":   false
}
>>> homekit_server_on_update_characteristics: [Client 55] Processing element {
    "aid":  1,
    "iid":  17,
    "ev":   false
}
>>> homekit_server_on_update_characteristics: [Client 55] Processing element {
    "aid":  1,
    "iid":  16,
    "ev":   false
}
>>> homekit_server_on_update_characteristics: [Client 55] Processing element {
    "aid":  1,
    "iid":  15,
    "ev":   false
}
>>> homekit_server_on_update_characteristics: [Client 55] Processing element {
    "aid":  1,
    "iid":  14,
    "ev":   false
}
>>> homekit_server_on_update_characteristics: [Client 55] Processing element {
    "aid":  1,
    "iid":  13,
    "ev":   false
}
>>> homekit_server_on_update_characteristics: [Client 55] Processing element {
    "aid":  1,
    "iid":  12,
    "ev":   false
}
>>> homekit_server_on_update_characteristics: [Client 55] Processing element {
    "aid":  1,
    "iid":  11,
    "ev":   false
}
>>> homekit_server_on_update_characteristics: [Client 55] Processing element {
    "aid":  1,
    "iid":  10,
    "ev":   false
}
>>> homekit_server_on_update_characteristics: [Client 55] There were no processing errors, sending No Content response
>>> client_send: [Client 55] Sending payload: HTTP/1.1 204 No Content\x0D\x0A\x0D\x0A
>>> homekit_client_process: [Client 55] Finished processing
!!! HomeKit: [Client 56] Error reading data from socket (code 113). Disconnecting
>>> HomeKit: [Client 56] Closing client connection
>>> HomeKit: [Client 55] Closing client connection

Here you can see a successful transaction for Client 55, and then an error for Client 56. After that, it appears to be dead.

If I inspect mDNS, I get the following:

$ dns-sd -B _hap._tcp local
Browsing for _hap._tcp.local
DATE: ---Sun 24 Mar 2019---
 8:35:45.702  ...STARTING...
Timestamp     A/R    Flags  if Domain               Service Type         Instance Name
 8:35:45.703  Add        3   7 local.               _hap._tcp.           Philips hue - 2A6564
 8:35:45.703  Add        3   7 local.               _hap._tcp.           AC Controller-9664
 8:35:45.703  Add        3   7 local.               _hap._tcp.           Homebridge-CAD8
 8:35:45.703  Add        2   7 local.               _hap._tcp.           AC Controller-B7AA

$ dns-sd -L AC\ Controller-B7AA _hap._tcp local
Lookup AC Controller-B7AA._hap._tcp.local
DATE: ---Sun 24 Mar 2019---
 8:39:04.525  ...STARTING...
 8:39:04.526  AC\032Controller-B7AA._hap._tcp.local. can be reached at AC\032Controller-B7AA.local.:5556 (interface 7)
 md=AC-IR pv=1.0 id=B7:AA:28:6E:07:D1 c#=1 s#=1 ff=0 sf=0 ci=21

After I got this error, I reset the WiFi connection from my router, to see what happened. The log showed this:

I (53725449) wifi: state: run -> init (6c0)
I (53725449) wifi: pm stop, total sleep time: 49809654793 us / 53723496973 us

I (53725449) wifi: new:<4,0>, old:<4,0>, ap:<255,255>, sta:<4,0>, prof:1
STA disconnected
I (53725579) wifi: new:<4,0>, old:<4,0>, ap:<255,255>, sta:<4,0>, prof:1
I (53725579) wifi: state: init -> auth (b0)
I (53725579) wifi: state: auth -> assoc (0)
I (53725589) wifi: state: assoc -> run (10)
I (53725609) wifi: connected with SinCable, channel 4, bssid = fc:ec:da:84:03:ca
I (53725609) wifi: pm start, type: 1

I (53727649) event: sta ip: 192.168.1.56, mask: 255.255.255.0, gw: 192.168.1.1
WiFI ready
>>> HomeKit: Starting server
>>> HomeKit: Using existing accessory ID: 96:64:E7:C7:ED:D9
>>> HomeKit: Found admin pairing with 94F4C638-BA4A-41AB-B2E6-15ACAA9D056A, disabling pair setup
>>> HomeKit: Configuring mDNS
>>> homekit_run_server: Staring HTTP server

But even after that (what I understand was a server reset), all Home apps still show "No response".

This seems similar to what was reported in #71. Also worth noting, I have almost the same code running fine in an ESP8266. I'm porting to an ESP32 and only now seeing this errors.

Just to add: even though this error was produced with my code, I got the same behaviour (No response after running for long periods of time) with the led demo project.

[pbendersky]

Adding more details, to see if this helps... I left it running overnight again, and got the same No response on the morning. Before, I had enabled ESP-IDF logging. This are the latest logs I have:

>>> homekit_server_on_update_characteristics: [Client 63] There were no processing errors, sending No Content response
>>> client_send: [Client 63] Sending payload: HTTP/1.1 204 No Content\x0D\x0A\x0D\x0A
>>> homekit_client_process: [Client 63] Finished processing
D (30196803) tcpip_adapter: if0 dhcpc cb
D (30196803) tcpip_adapter: if0 ip unchanged
>>> HomeKit: [Client 63] Closing client connection
D (34740553) phy_init: wifi mac time delta: 51626
D (36473453) phy_init: wifi mac time delta: 39970
D (38824843) phy_init: wifi mac time delta: 50856
D (39083233) phy_init: wifi mac time delta: 96640
D (40260873) tcpip_adapter: if0 dhcpc cb
D (40260873) tcpip_adapter: if0 ip unchanged
D (47644043) phy_init: wifi mac time delta: 44359
D (50324853) tcpip_adapter: if0 dhcpc cb
D (50324853) tcpip_adapter: if0 ip unchanged
!!! HomeKit: [Client 61] Error reading data from socket (code 113). Disconnecting
>>> HomeKit: [Client 61] Closing client connection
D (60388833) tcpip_adapter: if0 dhcpc cb
D (60388833) tcpip_adapter: if0 ip unchanged

[pbendersky]

@maximkulkin please let me know any test that might help pinpoint the error, I'll be glad to run it overnight and capture additional logs.

[pbendersky]

Adding another instance, in case it helps. What I find different in this one, is that Client 63 processes early, then Client 61, and later, both Client 61 and Client 63 get closed at about the same time. The HAP record seems accessible, but telneting to port 5556 fails. I'm still trying to find how to reproduce this intentionally.

First:

>>> homekit_server_on_update_characteristics: [Client 63] There were no processing errors, sending No Content response
>>> client_send: [Client 63] Sending payload: HTTP/1.1 204 No Content\x0D\x0A\x0D\x0A
>>> homekit_client_process: [Client 63] Finished processing

Way later, it failed after this:

>>> homekit_server_on_update_characteristics: [Client 61] There were no processing errors, sending No Content response
>>> client_send: [Client 61] Sending payload: HTTP/1.1 204 No Content\x0D\x0A\x0D\x0A
>>> homekit_client_process: [Client 61] Finished processing
>>> HomeKit: [Client 62] Closing client connection
>>> homekit_client_process: [Client 61] Got 444 incomming data
>>> homekit_client_process: [Client 61] Decrypting data
>>> homekit_client_process: [Client 61] Decrypted 426 bytes, available 0
Decrypted data (426 bytes): "PUT /characteristics HTTP/1.1\x0D\x0AHost: AC\\032Controller-9664._hap._tcp.local\x0D\x0AContent-Length: 291\x0D\x0AContent-Type: application/hap+json\x0D\x0A\x0D\x0A{"characteristics":[{"aid":1,"iid":18,"ev":false},{"aid":1,"iid":17,"ev":false},{"aid":1,"iid":16,"ev":false},{"aid":1,"iid":15,"ev":false},{"aid":1,"iid":14,"ev":false},{"aid":1,"iid":13,"ev":false},{"aid":1,"iid":12,"ev":false},{"aid":1,"iid":11,"ev":false},{"aid":1,"iid":10,"ev":false}]}"
>>> HomeKit: [Client 61] Update Characteristics
>>> homekit_server_on_update_characteristics: Free heap: 198408
>>> homekit_server_on_update_characteristics: [Client 61] Processing element {
    "aid":  1,
    "iid":  18,
    "ev":   false
}
>>> homekit_server_on_update_characteristics: [Client 61] Processing element {
    "aid":  1,
    "iid":  17,
    "ev":   false
}
>>> homekit_server_on_update_characteristics: [Client 61] Processing element {
    "aid":  1,
    "iid":  16,
    "ev":   false
}
>>> homekit_server_on_update_characteristics: [Client 61] Processing element {
    "aid":  1,
    "iid":  15,
    "ev":   false
}
>>> homekit_server_on_update_characteristics: [Client 61] Processing element {
    "aid":  1,
    "iid":  14,
    "ev":   false
}
>>> homekit_server_on_update_characteristics: [Client 61] Processing element {
    "aid":  1,
    "iid":  13,
    "ev":   false
}
>>> homekit_server_on_update_characteristics: [Client 61] Processing element {
    "aid":  1,
    "iid":  12,
    "ev":   false
}
>>> homekit_server_on_update_characteristics: [Client 61] Processing element {
    "aid":  1,
    "iid":  11,
    "ev":   false
}
>>> homekit_server_on_update_characteristics: [Client 61] Processing element {
    "aid":  1,
    "iid":  10,
    "ev":   false
}
>>> homekit_server_on_update_characteristics: [Client 61] There were no processing errors, sending No Content response
>>> client_send: [Client 61] Sending payload: HTTP/1.1 204 No Content\x0D\x0A\x0D\x0A
>>> homekit_client_process: [Client 61] Finished processing
>>> HomeKit: [Client 63] Closing client connection
>>> HomeKit: [Client 61] Closing client connection

The ESP is working (I can ping, and I can reset its network from my WiFi AP), but the server never starts responding again.

[maximkulkin]

The fix is merged, should be fine now.