esp-idf
esp-idf copied to clipboard
espressif
[mesh] ESP32S3 v4.4 Fail to connect to WIFI when moving to dynamic root (IDFGH-12011)
Answers checklist.
- [X] I have read the documentation ESP-IDF Programming Guide and the issue is not addressed there.
- [X] I have updated my IDF branch (master or release) to the latest version and checked that the issue is present there.
- [X] I have searched the issue tracker for a similar issue and not found a similar issue.
General issue report
Hello @zhangyanjiaoesp ,
as you might remember our system moves between fixed root and dynamic root depending on WIFI connectivity.
One thing we noticed is the following:
- if i start a device and wifi is up i see this
I (10647) mesh: [SCAN][ch:1]AP:3, other(ID:0, RD:0), MAP:0, idle:0, candidate:1, root:0, topMAP:0[c:0,i:1][d6:92:7d:c3:02:1e]router found<>
I (10649) mesh: 1330[SCAN]init rc[7c:df:a1:ff:a5:15,-38], mine:0, voter:0
I (10656) mesh: [SCAN:10/10]rc[128][7c:df:a1:ff:a5:15,-38], self[7c:df:a1:ff:a5:14,-38,reason:0,votes:1,idle][mine:1,voter:1(1.00)percent:1.00][128,1,7c:df:a1:ff:a5:15]
I (10671) mesh: [DONE]connect to router:KI, channel:1, rssi:-38, d6:92:7d:c3:02:1e[layer:0, assoc:0], my_vote_num:1/voter_num:1, rc[7c:df:a1:ff:a5:15/-38/1]
- after few seconds the device is connected and running with wifi.
Instaead, if i move to LTE (fixed root) and then switch on the WIFI after a while, I see the following
I (545720) mesh: [SCAN][ch:0]AP:11, other(ID:0, RD:0), MAP:0, idle:0, candidate:0, root:0, topMAP:0[c:0,i:0][00:00:00:00:00:00]<>
I (545721) mesh: [FAIL][31]root:0, fail:31, normal:0, <pre>backoff:0
It takes minutes for the device to be able to reconnect to the wifi once i switched it back on. it usually needs to reach fail:60 to then become rootless and finally reconnect.
We trigger the connection in the second scenario by simply doing:
- periodically do a wifi scan
- if the wanted wifi is found do:
ESP_ERROR_CHECK_WITHOUT_ABORT(esp_mesh_set_type(MESH_IDLE));
esp_mesh_fix_root(false);
esp_mesh_set_router(&self->mesh_router);
esp_mesh_set_self_organized(true, true);
I don't understand why this should trigger such a long search process vs the search process of a just woken up device. Are we missing some command?
Thanks
@KonssnoK when the device is just woken up, there is no mesh network, it will connect to the mesh network when it finds a suitable parent. But when the device has joined the mesh network, sometimes the parent node will disappear and recover in a short time. In order to maintain the original network structure as much as possible, the device will generally scan the parent node on the original channel for a period of time, and only when it is finally confirmed that the parent node can no longer connect, it will look for other appropriate parents in all channels.
mmm @zhangyanjiaoesp i think this is not what we are referring to.
We have:
- device boots alone (no other devices to do the mesh)
- device connects to WIFI immediately
- device is of course ROOT
- device loses WIFI
- device connects to LTE -> Our netif interface is a PPP one. The STA is periodically scanning for networks!
- 5 minutes pass
- device (ROOT) sees again the WIFI router to which it was connected (not a mesh station, a router)
- device (ROOT) takes minutes to reconnect to the router
mmm @zhangyanjiaoesp i think this is not what we are referring to.
We have:
- device boots alone (no other devices to do the mesh)
- device connects to WIFI immediately
- device is of course ROOT
- device loses WIFI
- device connects to LTE -> Our netif interface is a PPP one. The STA is periodically scanning for networks!
- 5 minutes pass
- device (ROOT) sees again the WIFI router to which it was connected (not a mesh station, a router)
- device (ROOT) takes minutes to reconnect to the router
Now I understand what you're talking about, can you provide the logs from the root sees again the router to the root reconnects to the router, it may help to analysis the reason.
@zhangyanjiaoesp attached a first log, i will generate another with more delay esp_wifi_reconnection.txt
@KonssnoK Is this phenomenon (device (ROOT) takes minutes to reconnect to the router) always present? Can you provide me with a demo for testing?
@KonssnoK Is this phenomenon (device (ROOT) takes minutes to reconnect to the router) always present? Can you provide me with a demo for testing?
not always. what i see is that normally the device (which was ROOT) will perform a full scan up to 60 times. Once it reaches 60 retries it will start scanning wifi normally. Problem is that these 60 times scans sometimes take a very long time.
I will try to reproduce it in a small project in the next days
Hi @KonssnoK, could you please share your updates on this issue? Thanks. Would we keep this issue open?
yes, the issue should stay open, the time of scanning is way longer after a disconnection than after a boot. Sorry not many other updates since we are quite busy with other issues :(
Example of device not trying to connect to wifi after moving to dynamic root
W (632724) mesh_hand: Triggering DYNAMIC MESH handover
I (632724) mesh: [IO]enable self-organizing, search parent<reconnect>
I (632734) mesh: mesh_schedule.c 2533 null args
I (632734) mesh: [IO]enable self-organizing, search parent<adaptive>
W (632744) mesh_hand: scan_done: found 0, fixed_root 0, has_parent 0, forced 0
I (632744) mesh: <MESH_NWK_SCAN_REQ_PASSIVE>unexpected, unprocessed previous scan by parent selection
W (632754) mesh_hand: Found IDLE devices and no good connection. Wait.
I (632764) mesh_main: <MESH_EVENT_ROOT_FIXED>not fixed
W (632774) mesh_hand: Triggering DYNAMIC MESH handover
I (632774) mesh: <WIFI_EVENT_SCAN_DONE>status:fail, num:0, id:204
W (632784) wifi:scan number is 0
I (632784) mesh: [SCAN][ch:0]AP:0, other(ID:0, RD:0), MAP:0, idle:0, candidate:0, root:0, topMAP:0[c:0,i:0][00:00:00:00:00:00]<>
I (632794) mesh: [FAIL][1]root:0, fail:1, normal:0, <pre>backoff:0
E (633414) ping_sock: send error=0
W (636414) ping: From 8.8.8.8 icmp_seq=159 timeout
E (637414) ping_sock: send error=0
I (637444) mesh: [SCAN][ch:0]AP:43, other(ID:0, RD:0), MAP:3, idle:3, candidate:0, root:0, topMAP:0[c:0,i:0][00:00:00:00:00:00]<>
I (637444) mesh: [FAIL][2]root:0, fail:2, normal:0, <pre>backoff:0
W (640414) ping: From 8.8.8.8 icmp_seq=160 timeout
E (641414) ping_sock: send error=0
I (642084) mesh: [SCAN][ch:0]AP:43, other(ID:0, RD:0), MAP:3, idle:3, candidate:0, root:0, topMAP:0[c:0,i:0][00:00:00:00:00:00]<>
I (642084) mesh: [FAIL][3]root:0, fail:3, normal:0, <pre>backoff:0
W (644414) ping: From 8.8.8.8 icmp_seq=161 timeout
I (644754) mesh: [SCAN][ch:0]AP:31, other(ID:0, RD:0), MAP:2, idle:2, candidate:0, root:0, topMAP:0[c:0,i:0][00:00:00:00:00:00]<>
I (644754) mesh: [FAIL][4]root:0, fail:4, normal:0, <pre>backoff:0
E (645414) ping_sock: send error=0
W (648414) ping: From 8.8.8.8 icmp_seq=162 timeout
I (649394) mesh: [SCAN][ch:0]AP:39, other(ID:0, RD:0), MAP:3, idle:3, candidate:0, root:0, topMAP:0[c:0,i:0][00:00:00:00:00:00]<>
I (649404) mesh: [FAIL][5]root:0, fail:5, normal:0, <pre>backoff:0
E (649414) ping_sock: send error=0
W (652414) ping: From 8.8.8.8 icmp_seq=163 timeout
E (653414) ping_sock: send error=0
I (654044) mesh: [SCAN][ch:0]AP:44, other(ID:0, RD:0), MAP:2, idle:2, candidate:0, root:0, topMAP:0[c:0,i:0][00:00:00:00:00:00]<>
I (654044) mesh: [FAIL][6]root:0, fail:6, normal:0, <pre>backoff:0
W (656414) ping: From 8.8.8.8 icmp_seq=164 timeout
I (656714) mesh: [SCAN][ch:0]AP:38, other(ID:0, RD:0), MAP:2, idle:2, candidate:0, root:0, topMAP:0[c:0,i:0][00:00:00:00:00:00]<>
I (656714) mesh: [FAIL][7]root:0, fail:7, normal:0, <pre>backoff:0
E (657414) ping_sock: send error=0
W (660414) ping: From 8.8.8.8 icmp_seq=165 timeout
I (661354) mesh: [SCAN][ch:0]AP:47, other(ID:0, RD:0), MAP:3, idle:3, candidate:0, root:0, topMAP:0[c:0,i:0][00:00:00:00:00:00]<>
I (661354) mesh: [FAIL][8]root:0, fail:8, normal:0, <pre>backoff:0
E (661414) ping_sock: send error=0
W (664414) ping: From 8.8.8.8 icmp_seq=166 timeout
E (665414) ping_sock: send error=0
I (665994) mesh: [SCAN][ch:0]AP:43, other(ID:0, RD:0), MAP:2, idle:2, candidate:0, root:0, topMAP:0[c:0,i:0][00:00:00:00:00:00]<>
I (665994) mesh: [FAIL][9]root:0, fail:9, normal:0, <pre>backoff:0
W (668414) ping: From 8.8.8.8 icmp_seq=167 timeout
I (668664) mesh: [SCAN][ch:0]AP:41, other(ID:0, RD:0), MAP:2, idle:2, candidate:0, root:0, topMAP:0[c:0,i:0][00:00:00:00:00:00]<>
I (668674) mesh: [FAIL][10]root:0, fail:10, normal:0, <pre>backoff:0
E (669414) ping_sock: send error=0
W (672414) ping: From 8.8.8.8 icmp_seq=168 timeout
I (673314) mesh: [SCAN][ch:0]AP:48, other(ID:0, RD:0), MAP:3, idle:3, candidate:0, root:0, topMAP:0[c:0,i:0][00:00:00:00:00:00]<>
I (673314) mesh: [FAIL][11]root:0, fail:11, normal:0, <pre>backoff:0
E (673414) ping_sock: send error=0
W (676414) ping: From 8.8.8.8 icmp_seq=169 timeout
E (677414) ping_sock: send error=0
I (677954) mesh: [SCAN][ch:0]AP:50, other(ID:0, RD:0), MAP:1, idle:1, candidate:0, root:0, topMAP:0[c:0,i:0][00:00:00:00:00:00]<>
I (677954) mesh: [FAIL][12]root:0, fail:12, normal:0, <pre>backoff:0
W (680414) ping: From 8.8.8.8 icmp_seq=170 timeout
I (680624) mesh: [SCAN][ch:0]AP:41, other(ID:0, RD:0), MAP:3, idle:3, candidate:0, root:0, topMAP:0[c:0,i:0][00:00:00:00:00:00]<>
I (680624) mesh: [FAIL][13]root:0, fail:13, normal:0, <pre>backoff:0
E (681414) ping_sock: send error=0
W (684414) ping: From 8.8.8.8 icmp_seq=171 timeout
I (685264) mesh: [SCAN][ch:0]AP:47, other(ID:0, RD:0), MAP:2, idle:2, candidate:0, root:0, topMAP:0[c:0,i:0][00:00:00:00:00:00]<>
I (685274) mesh: [FAIL][14]root:0, fail:14, normal:0, <pre>backoff:0
E (685414) ping_sock: send error=0
W (688414) ping: From 8.8.8.8 icmp_seq=172 timeout
E (689414) ping_sock: send error=0
I (689914) mesh: [SCAN][ch:0]AP:46, other(ID:0, RD:0), MAP:2, idle:2, candidate:0, root:0, topMAP:0[c:0,i:0][00:00:00:00:00:00]<>
I (689914) mesh: [FAIL][15]root:0, fail:15, normal:0, <pre>backoff:0
W (692414) ping: From 8.8.8.8 icmp_seq=173 timeout
I (692584) mesh: [SCAN][ch:0]AP:38, other(ID:0, RD:0), MAP:2, idle:2, candidate:0, root:0, topMAP:0[c:0,i:0][00:00:00:00:00:00]<>
I (692584) mesh: [FAIL][16]root:0, fail:16, normal:0, <pre>backoff:0
E (693414) ping_sock: send error=0
W (696414) ping: From 8.8.8.8 icmp_seq=174 timeout
I (697224) mesh: [SCAN][ch:0]AP:43, other(ID:0, RD:0), MAP:1, idle:1, candidate:0, root:0, topMAP:0[c:0,i:0][00:00:00:00:00:00]<>
I (697224) mesh: [FAIL][17]root:0, fail:17, normal:0, <pre>backoff:0
E (697414) ping_sock: send error=0
W (700414) ping: From 8.8.8.8 icmp_seq=175 timeout
E (701414) ping_sock: send error=0
I (701864) mesh: [SCAN][ch:0]AP:50, other(ID:0, RD:0), MAP:2, idle:2, candidate:0, root:0, topMAP:0[c:0,i:0][00:00:00:00:00:00]<>
I (701864) mesh: [FAIL][18]root:0, fail:18, normal:0, <pre>backoff:0
W (704414) ping: From 8.8.8.8 icmp_seq=176 timeout
I (704534) mesh: [SCAN][ch:0]AP:39, other(ID:0, RD:0), MAP:3, idle:3, candidate:0, root:0, topMAP:0[c:0,i:0][00:00:00:00:00:00]<>
I (704534) mesh: [FAIL][19]root:0, fail:19, normal:0, <pre>backoff:0
E (705414) ping_sock: send error=0
W (708414) ping: From 8.8.8.8 icmp_seq=177 timeout
I (709184) mesh: [SCAN][ch:0]AP:53, other(ID:0, RD:0), MAP:2, idle:2, candidate:0, root:0, topMAP:0[c:0,i:0][00:00:00:00:00:00]<>
I (709184) mesh: [FAIL][20]root:0, fail:20, normal:0, <pre>backoff:0
E (709414) ping_sock: send error=0
W (712414) ping: From 8.8.8.8 icmp_seq=178 timeout
E (713414) ping_sock: send error=0
I (713824) mesh: [SCAN][ch:0]AP:45, other(ID:0, RD:0), MAP:0, idle:0, candidate:0, root:0, topMAP:0[c:0,i:0][00:00:00:00:00:00]<>
I (713824) mesh: [FAIL][21]root:0, fail:21, normal:0, <pre>backoff:0
W (716414) ping: From 8.8.8.8 icmp_seq=179 timeout
I (716494) mesh: [SCAN][ch:0]AP:44, other(ID:0, RD:0), MAP:3, idle:3, candidate:0, root:0, topMAP:0[c:0,i:0][00:00:00:00:00:00]<>
I (716494) mesh: [FAIL][22]root:0, fail:22, normal:0, <pre>backoff:0
E (717414) ping_sock: send error=0
W (720414) ping: From 8.8.8.8 icmp_seq=180 timeout
I (721134) mesh: [SCAN][ch:0]AP:50, other(ID:0, RD:0), MAP:3, idle:3, candidate:0, root:0, topMAP:0[c:0,i:0][00:00:00:00:00:00]<>
I (721134) mesh: [FAIL][23]root:0, fail:23, normal:0, <pre>backoff:0
E (721414) ping_sock: send error=0
W (724414) ping: From 8.8.8.8 icmp_seq=181 timeout
E (725414) ping_sock: send error=0
I (725784) mesh: [SCAN][ch:0]AP:47, other(ID:0, RD:0), MAP:0, idle:0, candidate:0, root:0, topMAP:0[c:0,i:0][00:00:00:00:00:00]<>
I (725784) mesh: [FAIL][24]root:0, fail:24, normal:0, <pre>backoff:0
W (728414) ping: From 8.8.8.8 icmp_seq=182 timeout
I (728454) mesh: [SCAN][ch:0]AP:37, other(ID:0, RD:0), MAP:2, idle:2, candidate:0, root:0, topMAP:0[c:0,i:0][00:00:00:00:00:00]<>
I (728454) mesh: [FAIL][25]root:0, fail:25, normal:0, <pre>backoff:0
E (729414) ping_sock: send error=0
W (732414) ping: From 8.8.8.8 icmp_seq=183 timeout
I (733094) mesh: [SCAN][ch:0]AP:45, other(ID:0, RD:0), MAP:1, idle:1, candidate:0, root:0, topMAP:0[c:0,i:0][00:00:00:00:00:00]<>
I (733094) mesh: [FAIL][26]root:0, fail:26, normal:0, <pre>backoff:0
E (733414) ping_sock: send error=0
W (736414) ping: From 8.8.8.8 icmp_seq=184 timeout
E (737414) ping_sock: send error=0
I (737734) mesh: [SCAN][ch:0]AP:45, other(ID:0, RD:0), MAP:3, idle:3, candidate:0, root:0, topMAP:0[c:0,i:0][00:00:00:00:00:00]<>
I (737734) mesh: [FAIL][27]root:0, fail:27, normal:0, <pre>backoff:0
I (740404) mesh: [SCAN][ch:0]AP:39, other(ID:0, RD:0), MAP:2, idle:2, candidate:0, root:0, topMAP:0[c:0,i:0][00:00:00:00:00:00]<>
I (740404) mesh: [FAIL][28]root:0, fail:28, normal:0, <pre>backoff:0
W (740414) ping: From 8.8.8.8 icmp_seq=185 timeout
E (741414) ping_sock: send error=0
W (744414) ping: From 8.8.8.8 icmp_seq=186 timeout
I (745044) mesh: [SCAN][ch:0]AP:44, other(ID:0, RD:0), MAP:1, idle:1, candidate:0, root:0, topMAP:0[c:0,i:0][00:00:00:00:00:00]<>
I (745054) mesh: [FAIL][29]root:0, fail:29, normal:0, <pre>backoff:0
E (745414) ping_sock: send error=0
W (748414) ping: From 8.8.8.8 icmp_seq=187 timeout
E (749414) ping_sock: send error=0
I (749694) mesh: [SCAN][ch:0]AP:44, other(ID:0, RD:0), MAP:1, idle:1, candidate:0, root:0, topMAP:0[c:0,i:0][00:00:00:00:00:00]<>
I (749694) mesh: [FAIL][30]root:0, fail:30, normal:0, <pre>backoff:0
I (752364) mesh: [SCAN][ch:0]AP:38, other(ID:0, RD:0), MAP:3, idle:3, candidate:0, root:0, topMAP:0[c:0,i:0][00:00:00:00:00:00]<>
I (752364) mesh: [FAIL][31]root:0, fail:31, normal:0, <pre>backoff:0
W (752414) ping: From 8.8.8.8 icmp_seq=188 timeout
E (753414) ping_sock: send error=0
W (756414) ping: From 8.8.8.8 icmp_seq=189 timeout
I (757004) mesh: [SCAN][ch:0]AP:47, other(ID:0, RD:0), MAP:3, idle:3, candidate:0, root:0, topMAP:0[c:0,i:0][00:00:00:00:00:00]<>
I (757004) mesh: [FAIL][32]root:0, fail:32, normal:0, <pre>backoff:0
E (757414) ping_sock: send error=0
W (760414) ping: From 8.8.8.8 icmp_seq=190 timeout
E (761414) ping_sock: send error=0
I (761644) mesh: [SCAN][ch:0]AP:45, other(ID:0, RD:0), MAP:2, idle:2, candidate:0, root:0, topMAP:0[c:0,i:0][00:00:00:00:00:00]<>
I (761654) mesh: [FAIL][33]root:0, fail:33, normal:0, <pre>backoff:0
I (764314) mesh: [SCAN][ch:0]AP:42, other(ID:0, RD:0), MAP:3, idle:3, candidate:0, root:0, topMAP:0[c:0,i:0][00:00:00:00:00:00]<>
I (764324) mesh: [FAIL][34]root:0, fail:34, normal:0, <pre>backoff:0
W (764414) ping: From 8.8.8.8 icmp_seq=191 timeout
E (765414) ping_sock: send error=0
W (768414) ping: From 8.8.8.8 icmp_seq=192 timeout
I (768964) mesh: [SCAN][ch:0]AP:47, other(ID:0, RD:0), MAP:3, idle:3, candidate:0, root:0, topMAP:0[c:0,i:0][00:00:00:00:00:00]<>
I (768964) mesh: [FAIL][35]root:0, fail:35, normal:0, <pre>backoff:0
E (769414) ping_sock: send error=0
W (772414) ping: From 8.8.8.8 icmp_seq=193 timeout
E (773414) ping_sock: send error=0
I (773604) mesh: [SCAN][ch:0]AP:47, other(ID:0, RD:0), MAP:1, idle:1, candidate:0, root:0, topMAP:0[c:0,i:0][00:00:00:00:00:00]<>
I (773604) mesh: [FAIL][36]root:0, fail:36, normal:0, <pre>backoff:0
I (776274) mesh: [SCAN][ch:0]AP:40, other(ID:0, RD:0), MAP:2, idle:2, candidate:0, root:0, topMAP:0[c:0,i:0][00:00:00:00:00:00]<>
I (776274) mesh: [FAIL][37]root:0, fail:37, normal:0, <pre>backoff:0
W (776414) ping: From 8.8.8.8 icmp_seq=194 timeout
E (777414) ping_sock: send error=0
W (780414) ping: From 8.8.8.8 icmp_seq=195 timeout
I (780914) mesh: [SCAN][ch:0]AP:44, other(ID:0, RD:0), MAP:1, idle:1, candidate:0, root:0, topMAP:0[c:0,i:0][00:00:00:00:00:00]<>
I (780924) mesh: [FAIL][38]root:0, fail:38, normal:0, <pre>backoff:0
E (781414) ping_sock: send error=0
W (784414) ping: From 8.8.8.8 icmp_seq=196 timeout
E (785414) ping_sock: send error=0
I (785564) mesh: [SCAN][ch:0]AP:40, other(ID:0, RD:0), MAP:1, idle:1, candidate:0, root:0, topMAP:0[c:0,i:0][00:00:00:00:00:00]<>
I (785564) mesh: [FAIL][39]root:0, fail:39, normal:0, <pre>backoff:0
I (788234) mesh: [SCAN][ch:0]AP:36, other(ID:0, RD:0), MAP:1, idle:1, candidate:0, root:0, topMAP:0[c:0,i:0][00:00:00:00:00:00]<>
I (788234) mesh: [FAIL][40]root:0, fail:40, normal:0, <pre>backoff:0
W (788414) ping: From 8.8.8.8 icmp_seq=197 timeout
E (789414) ping_sock: send error=0
W (792414) ping: From 8.8.8.8 icmp_seq=198 timeout
I (792874) mesh: [SCAN][ch:0]AP:43, other(ID:0, RD:0), MAP:2, idle:2, candidate:0, root:0, topMAP:0[c:0,i:0][00:00:00:00:00:00]<>
I (792874) mesh: [FAIL][41]root:0, fail:41, normal:0, <pre>backoff:0
E (793414) ping_sock: send error=0
W (796414) ping: From 8.8.8.8 icmp_seq=199 timeout
E (797414) ping_sock: send error=0
I (797514) mesh: [SCAN][ch:0]AP:45, other(ID:0, RD:0), MAP:2, idle:2, candidate:0, root:0, topMAP:0[c:0,i:0][00:00:00:00:00:00]<>
I (797514) mesh: [FAIL][42]root:0, fail:42, normal:0, <pre>backoff:0
I (800184) mesh: [SCAN][ch:0]AP:36, other(ID:0, RD:0), MAP:2, idle:2, candidate:0, root:0, topMAP:0[c:0,i:0][00:00:00:00:00:00]<>
I (800184) mesh: [FAIL][43]root:0, fail:43, normal:0, <pre>backoff:0
W (800414) ping: From 8.8.8.8 icmp_seq=200 timeout
E (801414) ping_sock: send error=0
W (804414) ping: From 8.8.8.8 icmp_seq=201 timeout
I (804824) mesh: [SCAN][ch:0]AP:41, other(ID:0, RD:0), MAP:2, idle:2, candidate:0, root:0, topMAP:0[c:0,i:0][00:00:00:00:00:00]<>
I (804834) mesh: [FAIL][44]root:0, fail:44, normal:0, <pre>backoff:0
E (805414) ping_sock: send error=0
W (808414) ping: From 8.8.8.8 icmp_seq=202 timeout
E (809414) ping_sock: send error=0
I (809474) mesh: [SCAN][ch:0]AP:43, other(ID:0, RD:0), MAP:3, idle:3, candidate:0, root:0, topMAP:0[c:0,i:0][00:00:00:00:00:00]<>
I (809474) mesh: [FAIL][45]root:0, fail:45, normal:0, <pre>backoff:0
I (812144) mesh: [SCAN][ch:0]AP:40, other(ID:0, RD:0), MAP:3, idle:3, candidate:0, root:0, topMAP:0[c:0,i:0][00:00:00:00:00:00]<>
I (812144) mesh: [FAIL][46]root:0, fail:46, normal:0, <pre>backoff:0
W (812414) ping: From 8.8.8.8 icmp_seq=203 timeout
E (813414) ping_sock: send error=0
W (816414) ping: From 8.8.8.8 icmp_seq=204 timeout
I (816784) mesh: [SCAN][ch:0]AP:46, other(ID:0, RD:0), MAP:3, idle:3, candidate:0, root:0, topMAP:0[c:0,i:0][00:00:00:00:00:00]<>
I (816784) mesh: [FAIL][47]root:0, fail:47, normal:0, <pre>backoff:0
E (817414) ping_sock: send error=0
W (820414) ping: From 8.8.8.8 icmp_seq=205 timeout
E (821414) ping_sock: send error=0
I (821424) mesh: [SCAN][ch:0]AP:38, other(ID:0, RD:0), MAP:0, idle:0, candidate:0, root:0, topMAP:0[c:0,i:0][00:00:00:00:00:00]<>
I (821424) mesh: [FAIL][48]root:0, fail:48, normal:0, <pre>backoff:0
I (824094) mesh: [SCAN][ch:0]AP:36, other(ID:0, RD:0), MAP:2, idle:2, candidate:0, root:0, topMAP:0[c:0,i:0][00:00:00:00:00:00]<>
I (824094) mesh: [FAIL][49]root:0, fail:49, normal:0, <pre>backoff:0
W (824414) ping: From 8.8.8.8 icmp_seq=206 timeout
E (825414) ping_sock: send error=0
W (828414) ping: From 8.8.8.8 icmp_seq=207 timeout
I (828744) mesh: [SCAN][ch:0]AP:40, other(ID:0, RD:0), MAP:1, idle:1, candidate:0, root:0, topMAP:0[c:0,i:0][00:00:00:00:00:00]<>
I (828744) mesh: [FAIL][50]root:0, fail:50, normal:0, <pre>backoff:0
E (829414) ping_sock: send error=0
W (832414) ping: From 8.8.8.8 icmp_seq=208 timeout
I (833384) mesh: [SCAN][ch:0]AP:44, other(ID:0, RD:0), MAP:2, idle:2, candidate:0, root:0, topMAP:0[c:0,i:0][00:00:00:00:00:00]<>
I (833384) mesh: [FAIL][51]root:0, fail:51, normal:0, <pre>backoff:0
E (833414) ping_sock: send error=0
I (836054) mesh: [SCAN][ch:0]AP:38, other(ID:0, RD:0), MAP:2, idle:2, candidate:0, root:0, topMAP:0[c:0,i:0][00:00:00:00:00:00]<>
I (836054) mesh: [FAIL][52]root:0, fail:52, normal:0, <pre>backoff:0
W (836414) ping: From 8.8.8.8 icmp_seq=209 timeout
E (837414) ping_sock: send error=0
W (840414) ping: From 8.8.8.8 icmp_seq=210 timeout
I (840694) mesh: [SCAN][ch:0]AP:47, other(ID:0, RD:0), MAP:2, idle:2, candidate:0, root:0, topMAP:0[c:0,i:0][00:00:00:00:00:00]<>
I (840694) mesh: [FAIL][53]root:0, fail:53, normal:0, <pre>backoff:0
E (841414) ping_sock: send error=0
W (844414) ping: From 8.8.8.8 icmp_seq=211 timeout
I (845344) mesh: [SCAN][ch:0]AP:43, other(ID:0, RD:0), MAP:2, idle:2, candidate:0, root:0, topMAP:0[c:0,i:0][00:00:00:00:00:00]<>
I (845344) mesh: [FAIL][54]root:0, fail:54, normal:0, <pre>backoff:0
E (845414) ping_sock: send error=0
I (848004) mesh: [SCAN][ch:0]AP:35, other(ID:0, RD:0), MAP:2, idle:2, candidate:0, root:0, topMAP:0[c:0,i:0][00:00:00:00:00:00]<>
I (848014) mesh: [FAIL][55]root:0, fail:55, normal:0, <pre>backoff:0
W (848414) ping: From 8.8.8.8 icmp_seq=212 timeout
E (849414) ping_sock: send error=0
W (852414) ping: From 8.8.8.8 icmp_seq=213 timeout
I (852654) mesh: [SCAN][ch:0]AP:40, other(ID:0, RD:0), MAP:3, idle:3, candidate:0, root:0, topMAP:0[c:0,i:0][00:00:00:00:00:00]<>
I (852654) mesh: [FAIL][56]root:0, fail:56, normal:0, <pre>backoff:0
E (853414) ping_sock: send error=0
W (856414) ping: From 8.8.8.8 icmp_seq=214 timeout
I (857294) mesh: [SCAN][ch:0]AP:40, other(ID:0, RD:0), MAP:2, idle:2, candidate:0, root:0, topMAP:0[c:0,i:0][00:00:00:00:00:00]<>
I (857294) mesh: [FAIL][57]root:0, fail:57, normal:0, <pre>backoff:0
E (857414) ping_sock: send error=0
I (859964) mesh: [SCAN][ch:0]AP:34, other(ID:0, RD:0), MAP:3, idle:3, candidate:0, root:0, topMAP:0[c:0,i:0][00:00:00:00:00:00]<>
I (859964) mesh: [FAIL][58]root:0, fail:58, normal:0, <pre>backoff:0
W (860414) ping: From 8.8.8.8 icmp_seq=215 timeout
E (861414) ping_sock: send error=0
W (864414) ping: From 8.8.8.8 icmp_seq=216 timeout
I (864604) mesh: [SCAN][ch:0]AP:44, other(ID:0, RD:0), MAP:2, idle:2, candidate:0, root:0, topMAP:0[c:0,i:0][00:00:00:00:00:00]<>
I (864604) mesh: [FAIL][59]root:0, fail:59, normal:0, <pre>backoff:0
E (865414) ping_sock: send error=0
W (868414) ping: From 8.8.8.8 icmp_seq=217 timeout
@zhangyanjiaoesp while checking the other ticket I'm still seeing this:
we are moving to 5.3 and still see the same issue.
Once the device moves from fixed root to dynamic root it takes minutes before it is able to connect to the AP that was scanned. This does not happen if the device reboots.
It seems the device goes through 4 scans before being able to connect:
- the exploratory scan, which triggers the moving to dynamic mesh (done every 30 seconds). This is ok, we are the ones forcing this scan when on fixed root.
- a secondary passive scan that always fails for 60 times before setting the device as rootless
- a third active scan once rootless
- a fourth quick scan related to the mesh that takes 10 steps
- connection
I do not understand why so many scans are necessary.
Partial logs for the secondary, 3rd, 4th scans and connection: 24110507_mesh_wifi_scans.txt
@KonssnoK
D (718668) wifi:Send scan done event: status=0, apnum=40
I (718670) mesh: [SCAN][ch:0]AP:40, other(ID:0, RD:0), MAP:0, idle:0, candidate:0, root:0, topMAP:0[c:0,i:0][00:00:00:00:00:00]<>
I (718679) mesh: [FAIL][57]root:0, fail:57, normal:0, <pre>backoff:0
This log indicates that no connectable mesh nodes/routers were detected. When the number of consecutive failures reaches the configured value attempts.fail (default is 60), it will trigger the NO_PARENT_FOUND event. Following this, the conditions for channel/router switch are checked to determine whether a full channel scan should be performed or the BSSID should be cleared. The system will then begin a MESH_NWK_LOOK_FOR_NETWORK scan.
I (730866) mesh: <MESH_NWK_PARENT_SELECTION>no parent found, set ROOTLESS, scan times:60, heap:51451
I (730876) mesh: <MESH_NWK_PARENT_SELECTION>channel<cfg:0> is allowed to switch, do a full channel scan
D (730885) wifi:filter: set rx policy=10I (09:12:45.152) mesh_main: <MESH_EVENT_NO_PARENT_FOUND>scan times:60
I (730896) wifi:mode : sta (ac:17:54:00:0a:b0)
I (09:12:45.167) mesh_main: <MESH_EVENT_NETWORK_STATE>is_rootless:1
I (730900) mesh: <MESH_NWK_LOOK_FOR_NETWORK>need_scan:0x3, need_scan_router:0x1, look_for_nwk_count:62
Since a router KI was detected during the scan, the node attempts to become the root. The root election process requires at least ten voting rounds. Once the voting concludes successfully and the node becomes the root, it will connect to the router.
D (732671) wifi:Send scan done event: status=0, apnum=1
I (732677) mesh: [S1]KI, d2:0f:7d:8a:8b:29, channel:11, rssi:-20
I (732682) mesh: find router:[ssid_len:2]KI, rssi:-20, d2:0f:7d:8a:8b:29(encrypted), new channel:11, old channel:0
I (732692) mesh: [FIND][ch:0]AP:1, otherID:0, MAP:0, idle:0, candidate:0, root:0[d2:0f:7d:8a:8b:29]router found<scan router>
I (732703) mesh: [FIND:61]find a network, channel:11, cfg<channel:0, router:KI, 00:00:00:00:00:00>
I (09:12:46.979) mesh_main: <MESH_EVENT_FIND_NETWORK>new channel:11, router BSSID:000000000000
I (736537) mesh: [SCAN:10/10]rc[128][ac:17:54:00:0a:b1,-20], self[ac:17:54:00:0a:b0,-23,reason:0,votes:1,idle][mine:1,voter:1(1.00)percent:1.00][128,1,ac:17:54:00:0a:b1]
I (736552) mesh: [DONE]connect to router:KI, channel:11, rssi:-23, d2:0f:7d:8a:8b:29[layer:0, assoc:0], my_vote_num:1/voter_num:1, rc[ac:17:54:00:0a:b1/-20/1]
I (737369) wifi:state: assoc -> run (0x10)
D (737369) wifi:start 10s connect timer for 4 way handshake
I (737715) wifi:connected with KI, aid = 1, channel 11, BW20, bssid = d2:0f:7d:8a:8b:29
Thanks for reporting, will close due to inactivity, feel free to reopen if the issue still happens, thanks.
