search

maximkulkin / esp-homekit

Apple HomeKit accessory server library for ESP-OPEN-RTOS
MIT License
1.1k stars 168 forks source link

ESP8266 not reachable after MDNS restart #215

Open PascalKu opened 11 months ago

PascalKu commented 11 months ago

Hello,

I have a small ESP8266 device with your HomeKit Library installed and functioning properly. However, I am encountering an issue when the "MDNS restarts." While my ESP remains accessible via ping from another device on the same network, it stops responding in the Apple Home App. It's important to note that the IP address remains unchanged.

Are you familiar with this problem, and if so, do you have any suggestions on how to resolve it? Thank you in advance.

d4rkmen commented 11 months ago

start with dns_sd responses logging after the mdns restart. the homekit uses dns_sd for service discovery. in case your accessory lost discovery broadcast response its removed from connection list (even if the ip and ping are valid)

PascalKu commented 11 months ago

Here you can find the log. I can't see any big issues...?

https://gist.github.com/PascalKu/355fcb75b3177df58fba8d8fdd980dea

CC: @d4rkmen

d4rkmen commented 11 months ago

I was talking about dns_sd tool output with _hap._tcp, not the device itself Its possible to get them on pc (connected to same network) You should get the moment when mdns messages stops coming or delay > 2s or malformed responses Its interesting to get the root of this problem for me, because I have been watching for this project for a while and this problem is common

PascalKu commented 11 months ago

I cant find any "tutorial" on how I can do the debugging.. could you give me more details? I really want to figure out the problem too.

// EDIT: Fail! dns_sd is a tool from Apple and not part of the Arduino stuff.

PascalKu commented 11 months ago

@d4rkmen Here it comes.

18:40:22.092 -> >>> [ 419476] HomeKit: heap: 40664, sockets: 0
18:40:23.179 -> [MDNSResponder] _callProcess (420589, triggered by: 192.168.178.22)
18:40:23.216 -> [MDNSResponder] _parseMessage (Time: 420590 ms, heap: 40664 bytes, from 192.168.178.22(5353), to 224.0.0.251(5353))
18:40:23.216 -> [MDNSResponder] _parseMessage: Done (Succeeded after 5 ms, ate 0 bytes, remaining 40664)
18:40:23.216 -> 
18:40:25.368 -> ip:192.168.178.79,mask:255.255.255.0,gw:192.168.178.1
18:40:25.368 -> >>> [ 422776] HomeKit: WiFi connected, ip: 192.168.178.79, mask: 255.255.255.0, gw: 192.168.178.1
18:40:25.403 -> >>> [ 422788] HomeKit: Configuring MDNS
18:40:25.403 -> [MDNSResponder] _announce: Announcing host LEDPlant (content 0x3)
18:40:25.403 -> [MDNSResponder] _announce: Announcing service LEDPlant.hap.tcp (content 240)
18:40:25.403 -> [MDNSResponder] _sendMDNSMessage_Multicast: Will send to '224.0.0.251'.
18:40:25.403 -> [MDNSResponder] _prepareMDNSMessage
18:40:25.403 -> [MDNSResponder] _prepareMDNSMessage: ID:0 QR:1 OP:0 AA:1 TC:0 RD:0 RA:0 R:0 QD:0 AN:6 NS:0 AR:0
18:40:25.437 -> [MDNSResponder] _writeMDNSAnswer_A (192.168.178.79)
18:40:25.437 -> [MDNSResponder] _writeMDNSAnswer_PTR_IP4 (192.168.178.79)
18:40:25.437 -> [MDNSResponder] _writeMDNSAnswer_PTR_TYPE
18:40:25.437 -> [MDNSResponder] _writeMDNSAnswer_PTR_NAME
18:40:25.437 -> [MDNSResponder] _writeMDNSAnswer_SRV
18:40:25.437 -> [MDNSResponder] _writeMDNSAnswer_TXT
18:40:25.437 -> [MDNSResponder] _allocUDPContext
18:40:25.437 -> >>> [ 422838] HomeKit: MDNS restart: LEDPlant, IP: 192.168.178.79
18:40:25.472 -> [MDNSResponder] _announce: FAILED!
18:40:25.472 -> [MDNSResponder] begin: restarting after interface status changed
18:40:25.472 -> [MDNSResponder] _allocUDPContext
18:40:25.472 -> [MDNSResponder] _updateProbeStatus: Starting host probing...
18:40:25.506 -> [MDNSResponder] _sendHostProbe (LEDPlant, 422890)
18:40:25.506 -> [MDNSResponder] _sendMDNSMessage_Multicast: Will send to '224.0.0.251'.
18:40:25.506 -> [MDNSResponder] _prepareMDNSMessage
18:40:25.506 -> [MDNSResponder] _prepareMDNSMessage: ID:0 QR:0 OP:0 AA:0 TC:0 RD:0 RA:0 R:0 QD:1 AN:0 NS:1 AR:0
18:40:25.506 -> [MDNSResponder] _writeMDNSQuestion
18:40:25.506 -> [MDNSResponder] _writeMDNSAnswer_A (192.168.178.79)
18:40:25.577 -> [MDNSResponder] _sendMDNSMessage_Multicast: FAILED!
18:40:25.577 -> [MDNSResponder] _sendMDNSMessage: FAILED!
18:40:25.577 -> [MDNSResponder] _updateProbeStatus: Did not sent host probe to all links
18:40:25.577 -> 
18:40:25.577 -> [MDNSResponder] _updateProbeStatus: FAILED!
18:40:25.577 -> 
18:40:25.835 -> [MDNSResponder] _sendHostProbe (LEDPlant, 423214)
18:40:25.835 -> [MDNSResponder] _sendMDNSMessage_Multicast: Will send to '224.0.0.251'.
18:40:25.835 -> [MDNSResponder] _prepareMDNSMessage
18:40:25.835 -> [MDNSResponder] _prepareMDNSMessage: ID:0 QR:0 OP:0 AA:0 TC:0 RD:0 RA:0 R:0 QD:1 AN:0 NS:1 AR:0
18:40:25.835 -> [MDNSResponder] _writeMDNSQuestion
18:40:25.835 -> [MDNSResponder] _writeMDNSAnswer_A (192.168.178.79)
18:40:25.835 -> [MDNSResponder] _updateProbeStatus: Did sent host probe to all links 
18:40:25.872 -> 
18:40:26.087 -> [MDNSResponder] _sendHostProbe (LEDPlant, 423492)
18:40:26.087 -> [MDNSResponder] _sendMDNSMessage_Multicast: Will send to '224.0.0.251'.
18:40:26.121 -> [MDNSResponder] _prepareMDNSMessage
18:40:26.121 -> [MDNSResponder] _prepareMDNSMessage: ID:0 QR:0 OP:0 AA:0 TC:0 RD:0 RA:0 R:0 QD:1 AN:0 NS:1 AR:0
18:40:26.121 -> [MDNSResponder] _writeMDNSQuestion
18:40:26.121 -> [MDNSResponder] _writeMDNSAnswer_A (192.168.178.79)
18:40:26.121 -> [MDNSResponder] _updateProbeStatus: Did sent host probe to all links 
18:40:26.121 -> 
18:40:26.371 -> [MDNSResponder] _updateProbeStatus: Done host probing.
18:40:26.371 -> [MDNSResponder] _updateProbeStatus: Prepared host announcing.
18:40:26.371 -> 
18:40:27.092 -> >>> [ 424480] HomeKit: heap: 41272, sockets: 0
18:40:27.380 -> [MDNSResponder] _announce: Announcing host LEDPlant (content 0x3)
18:40:27.380 -> [MDNSResponder] _sendMDNSMessage_Multicast: Will send to '224.0.0.251'.
18:40:27.380 -> [MDNSResponder] _prepareMDNSMessage
18:40:27.380 -> [MDNSResponder] _prepareMDNSMessage: ID:0 QR:1 OP:0 AA:1 TC:0 RD:0 RA:0 R:0 QD:0 AN:2 NS:0 AR:0
18:40:27.380 -> [MDNSResponder] _writeMDNSAnswer_A (192.168.178.79)
18:40:27.417 -> [MDNSResponder] _writeMDNSAnswer_PTR_IP4 (192.168.178.79)
18:40:27.417 -> [MDNSResponder] _updateProbeStatus: Announcing host (1).
18:40:27.417 -> 
18:40:28.183 -> [MDNSResponder] _callProcess (425585, triggered by: 192.168.178.22)
18:40:28.183 -> [MDNSResponder] _parseMessage (Time: 425586 ms, heap: 41136 bytes, from 192.168.178.22(5353), to 224.0.0.251(5353))
18:40:28.219 -> [MDNSResponder] _parseMessage: Done (Succeeded after 5 ms, ate 0 bytes, remaining 41136)
18:40:28.219 -> 
18:40:28.392 -> [MDNSResponder] _announce: Announcing host LEDPlant (content 0x3)
18:40:28.392 -> [MDNSResponder] _sendMDNSMessage_Multicast: Will send to '224.0.0.251'.
18:40:28.427 -> [MDNSResponder] _prepareMDNSMessage
18:40:28.427 -> [MDNSResponder] _prepareMDNSMessage: ID:0 QR:1 OP:0 AA:1 TC:0 RD:0 RA:0 R:0 QD:0 AN:2 NS:0 AR:0
18:40:28.427 -> [MDNSResponder] _writeMDNSAnswer_A (192.168.178.79)
18:40:28.427 -> [MDNSResponder] _writeMDNSAnswer_PTR_IP4 (192.168.178.79)
18:40:28.427 -> [MDNSResponder] _updateProbeStatus: Announcing host (2).
18:40:28.427 -> 
18:40:29.436 -> [MDNSResponder] _announce: Announcing host LEDPlant (content 0x3)
18:40:29.436 -> [MDNSResponder] _sendMDNSMessage_Multicast: Will send to '224.0.0.251'.
18:40:29.436 -> [MDNSResponder] _prepareMDNSMessage
18:40:29.436 -> [MDNSResponder] _prepareMDNSMessage: ID:0 QR:1 OP:0 AA:1 TC:0 RD:0 RA:0 R:0 QD:0 AN:2 NS:0 AR:0
18:40:29.436 -> [MDNSResponder] _writeMDNSAnswer_A (192.168.178.79)
18:40:29.436 -> [MDNSResponder] _writeMDNSAnswer_PTR_IP4 (192.168.178.79)
18:40:29.470 -> [MDNSResponder] _updateProbeStatus: Announcing host (3).
18:40:29.470 -> 
18:40:30.453 -> [MDNSResponder] _announce: Announcing host LEDPlant (content 0x3)
18:40:30.453 -> [MDNSResponder] _sendMDNSMessage_Multicast: Will send to '224.0.0.251'.
18:40:30.453 -> [MDNSResponder] _prepareMDNSMessage
18:40:30.453 -> [MDNSResponder] _prepareMDNSMessage: ID:0 QR:1 OP:0 AA:1 TC:0 RD:0 RA:0 R:0 QD:0 AN:2 NS:0 AR:0
18:40:30.490 -> [MDNSResponder] _writeMDNSAnswer_A (192.168.178.79)
18:40:30.490 -> [MDNSResponder] _writeMDNSAnswer_PTR_IP4 (192.168.178.79)
18:40:30.490 -> [MDNSResponder] _updateProbeStatus: Announcing host (4).
18:40:30.490 -> 
18:40:31.472 -> [MDNSResponder] _announce: Announcing host LEDPlant (content 0x3)
18:40:31.472 -> [MDNSResponder] _sendMDNSMessage_Multicast: Will send to '224.0.0.251'.
18:40:31.510 -> [MDNSResponder] _prepareMDNSMessage
18:40:31.510 -> [MDNSResponder] _prepareMDNSMessage: ID:0 QR:1 OP:0 AA:1 TC:0 RD:0 RA:0 R:0 QD:0 AN:2 NS:0 AR:0
18:40:31.510 -> [MDNSResponder] _writeMDNSAnswer_A (192.168.178.79)
18:40:31.510 -> [MDNSResponder] _writeMDNSAnswer_PTR_IP4 (192.168.178.79)
18:40:31.510 -> [MDNSResponder] _updateProbeStatus: Announcing host (5).
18:40:31.510 -> 
18:40:32.097 -> >>> [ 429483] HomeKit: heap: 41136, sockets: 0
18:40:32.523 -> [MDNSResponder] _announce: Announcing host LEDPlant (content 0x3)
18:40:32.523 -> [MDNSResponder] _sendMDNSMessage_Multicast: Will send to '224.0.0.251'.
18:40:32.523 -> [MDNSResponder] _prepareMDNSMessage
18:40:32.523 -> [MDNSResponder] _prepareMDNSMessage: ID:0 QR:1 OP:0 AA:1 TC:0 RD:0 RA:0 R:0 QD:0 AN:2 NS:0 AR:0
18:40:32.523 -> [MDNSResponder] _writeMDNSAnswer_A (192.168.178.79)
18:40:32.523 -> [MDNSResponder] _writeMDNSAnswer_PTR_IP4 (192.168.178.79)
18:40:32.523 -> [MDNSResponder] _updateProbeStatus: Announcing host (6).
18:40:32.560 -> 
18:40:33.219 -> [MDNSResponder] _callProcess (430623, triggered by: 192.168.178.22)
18:40:33.219 -> [MDNSResponder] _parseMessage (Time: 430624 ms, heap: 41136 bytes, from 192.168.178.22(5353), to 224.0.0.251(5353))
18:40:33.254 -> [MDNSResponder] _parseMessage: Done (Succeeded after 5 ms, ate 0 bytes, remaining 41136)
18:40:33.254 -> 
18:40:33.541 -> [MDNSResponder] _announce: Announcing host LEDPlant (content 0x3)
18:40:33.541 -> [MDNSResponder] _sendMDNSMessage_Multicast: Will send to '224.0.0.251'.
18:40:33.541 -> [MDNSResponder] _prepareMDNSMessage
18:40:33.541 -> [MDNSResponder] _prepareMDNSMessage: ID:0 QR:1 OP:0 AA:1 TC:0 RD:0 RA:0 R:0 QD:0 AN:2 NS:0 AR:0
18:40:33.541 -> [MDNSResponder] _writeMDNSAnswer_A (192.168.178.79)
18:40:33.541 -> [MDNSResponder] _writeMDNSAnswer_PTR_IP4 (192.168.178.79)
18:40:33.578 -> [MDNSResponder] _updateProbeStatus: Announcing host (7).
18:40:33.578 -> 
18:40:34.545 -> [MDNSResponder] _announce: Announcing host LEDPlant (content 0x3)
18:40:34.545 -> [MDNSResponder] _sendMDNSMessage_Multicast: Will send to '224.0.0.251'.
18:40:34.581 -> [MDNSResponder] _prepareMDNSMessage
18:40:34.581 -> [MDNSResponder] _prepareMDNSMessage: ID:0 QR:1 OP:0 AA:1 TC:0 RD:0 RA:0 R:0 QD:0 AN:2 NS:0 AR:0
18:40:34.581 -> [MDNSResponder] _writeMDNSAnswer_A (192.168.178.79)
18:40:34.581 -> [MDNSResponder] _writeMDNSAnswer_PTR_IP4 (192.168.178.79)
18:40:34.581 -> [MDNSResponder] _updateProbeStatus: Done host announcing.
18:40:34.581 -> 
18:40:37.097 -> >>> [ 434488] HomeKit: heap: 41136, sockets: 0
18:40:38.180 -> [MDNSResponder] _callProcess (435590, triggered by: 192.168.178.22)
18:40:38.218 -> [MDNSResponder] _parseMessage (Time: 435591 ms, heap: 41136 bytes, from 192.168.178.22(5353), to 224.0.0.251(5353))
18:40:38.218 -> [MDNSResponder] _parseMessage: Done (Succeeded after 5 ms, ate 0 bytes, remaining 41136)
PascalKu commented 11 months ago

Another problem log

19:09:03.909 -> >>> [ 111446] HomeKit: Got new client: local 192.168.178.79:5556, remote 192.168.178.63:53580
19:09:03.909 -> >>> [ 111464] HomeKit: [Client 1073687268] Pair Verify Step 1/2
19:09:04.403 -> >>> [ 111958] HomeKit: Free heap: 37536
19:09:04.403 -> [MDNSResponder] _callProcess (111966, triggered by: 192.168.178.63)
19:09:04.437 -> [MDNSResponder] _parseMessage (Time: 111968 ms, heap: 37264 bytes, from 192.168.178.63(5353), to 224.0.0.251(5353))
19:09:04.437 -> [MDNSResponder] _parseMessage: Done (Succeeded after 5 ms, ate 0 bytes, remaining 37264)
19:09:04.437 -> 
19:09:04.437 -> [MDNSResponder] _callProcess (111980, triggered by: 192.168.178.63)
19:09:04.437 -> [MDNSResponder] _parseMessage (Time: 111986 ms, heap: 37464 bytes, from 192.168.178.63(5353), to 224.0.0.251(5353))
19:09:04.470 -> [MDNSResponder] _readRRQuestion
19:09:04.470 -> [MDNSResponder] _readRRQuestion iPhone von Pascal._rdlink._tcp.local Type:0x00FF Class:0x0001 Multicast
19:09:04.470 -> [MDNSResponder] _readRRQuestion
19:09:04.470 -> [MDNSResponder] _readRRQuestion iPhone-von-Pascal.local Type:0x00FF Class:0x0001 Multicast
19:09:04.470 -> [MDNSResponder] _readRRAnswer: iPhone von Pascal._rdlink._tcp.local Type:0x0021 Class:0x0001 TTL:120, RDLength:8 SRV Port:49154 iPhone-von-Pascal.local
19:09:04.508 -> [MDNSResponder] _readRRAnswer: iPhone-von-Pascal.local Type:0x001C Class:0x0001 TTL:120, RDLength:16 generic 
19:09:04.508 -> [MDNSResponder] _readRRAnswer: iPhone-von-Pascal.local Type:0x0001 Class:0x0001 TTL:120, RDLength:4 A IP:192.168.178.63
19:09:04.508 -> [MDNSResponder] _readRRAnswer: iPhone-von-Pascal.local Type:0x001C Class:0x0001 TTL:120, RDLength:16 generic 
19:09:04.508 -> [MDNSResponder] _readRRAnswer: -empty- Type:0x0029 Class:0x05A0 TTL:4500, RDLength:18 generic 
19:09:04.545 -> [MDNSResponder] _parseQuery: No reply needed
19:09:04.545 -> [MDNSResponder] _parseMessage: Done (Succeeded after 87 ms, ate 0 bytes, remaining 37464)
19:09:04.545 -> 
19:09:04.657 -> >>> [ 112186] HomeKit: [Client 1073687268] Pair Verify Step 2/2
19:09:04.657 -> >>> [ 112194] HomeKit: [Client 1073687268] Found pairing with D790D8EE-FE00-4984-AD91-87B78DE742EC
19:09:04.694 -> >>> [ 112224] HomeKit: Call ge_double_scalarmult_vartime_lowmem in ge_low_mem.c
19:09:06.117 -> >>> [ 113667] HomeKit: [Client 1073687268] Verification successful, secure session established
19:09:06.117 -> >>> [ 113676] HomeKit: Free heap: 37432
19:09:06.330 -> >>> [ 113871] HomeKit: heap: 37704, sockets: 1
19:09:06.435 -> >>> [ 114000] HomeKit: [Client 1073687268] Get Accessories
19:09:07.279 -> [MDNSResponder] _callProcess (114814, triggered by: 192.168.178.63)
19:09:07.279 -> [MDNSResponder] _parseMessage (Time: 114816 ms, heap: 34232 bytes, from 192.168.178.63(5353), to 224.0.0.251(5353))
19:09:07.279 -> [MDNSResponder] _parseMessage: Done (Succeeded after 4 ms, ate 0 bytes, remaining 34232)
19:09:07.279 -> 
19:09:07.419 -> !!! [ 114957] HomeKit: [Client 1073687268] socket.write, data_size=533, write_size=6
19:09:07.419 -> >>> [ 114965] HomeKit: [Client 1073687268] Closing client connection
19:09:07.745 -> !!! [ 115275] HomeKit: [Client 0] The socket is null! (or is closed)
19:09:07.745 -> !!! [ 115281] HomeKit: [Client 0] The socket is null! (or is closed)
19:09:10.049 -> [MDNSResponder] _callProcess (117581, triggered by: 192.168.178.63)
19:09:10.049 -> [MDNSResponder] _parseMessage (Time: 117583 ms, heap: 36576 bytes, from 192.168.178.63(5353), to 224.0.0.251(5353))
19:09:10.049 -> [MDNSResponder] _parseMessage: Done (Succeeded after 5 ms, ate 0 bytes, remaining 36576)
PascalKu commented 11 months ago

@d4rkmen I've published my code... can u see any problems with it?