IP_LOSE 引起重发

[radiolee]

用台式机抓了几天日志，发现好几天不动了今早重新开始抓。09:06开机，10:48有一条NETIF_LINK_OFF -> IP_LOSE，然后CELL_INFO_UPDATE是正常的，定时开关飞行模式的时间也没到。11:18发现后拨入电话，就已经引起重发了。是不是监听到IP_LOSE后就处理一下，即可解决重发问题？

https://gitee.com/openLuat/LuatOS/issues/I9BUOL?from=project-issue

[2024-05-13 09:06:33.642]开机

[2024-05-13 10:22:17.108][000003908.017] D/user.EVENT.CELL_INFO_UPDATE [2024-05-13 10:27:17.111][000004208.016] D/user.EVENT.CELL_INFO_UPDATE [2024-05-13 10:32:17.111][000004508.016] D/user.EVENT.CELL_INFO_UPDATE [2024-05-13 10:37:12.439][000004803.355] D/user.EVENT.CELL_INFO_UPDATE [2024-05-13 10:42:17.102][000005108.015] D/user.EVENT.CELL_INFO_UPDATE [2024-05-13 10:47:12.186][000005403.094] D/user.EVENT.CELL_INFO_UPDATE [2024-05-13 10:48:03.957][000005454.869] soc_cms_proc 1653:cenc report 1,38,1,1 [2024-05-13 10:48:03.957][000005454.870] cid1, state2 [2024-05-13 10:48:03.976][000005454.870] NETIF_LINK_OFF -> IP_LOSE [2024-05-13 10:52:17.108][000005708.013] D/user.EVENT.CELL_INFO_UPDATE [2024-05-13 10:57:09.301][000006000.213] D/user.EVENT.CELL_INFO_UPDATE [2024-05-13 11:02:17.108][000006308.012] D/user.EVENT.CELL_INFO_UPDATE [2024-05-13 11:07:12.049][000006602.951] D/user.EVENT.CELL_INFO_UPDATE [2024-05-13 11:12:12.411][000006903.311] D/user.EVENT.CELL_INFO_UPDATE [2024-05-13 11:17:17.112][000007208.010] D/user.EVENT.CELL_INFO_UPDATE [2024-05-13 11:18:48.773][000007299.678] LUAT_MOBILE_EVENT_CC status 12 [2024-05-13 11:18:48.777][000007299.679] I/user.==============cc_status==============: PLAY [2024-05-13 11:18:48.792][000007299.680] LUAT_MOBILE_EVENT_CC status 1 [2024-05-13 11:18:48.792][000007299.680] I/user.cc_status INCOMINGCALL 来电事件 18888888888 [2024-05-13 11:18:48.808][000007299.690] D/user.util_notify.add 添加到消息队列, 当前队列长度: 1 消息内容: 来电号码: 18888888888\n来电时间: 2024-05-13 11:18:48\n#CALL #CALL_IN 2 [2024-05-13 11:18:48.808][000007299.693] LUAT_MOBILE_EVENT_CC status 2 [2024-05-13 11:18:48.886][000007299.794] I/user.util_notify.poll 轮询消息队列中 总长度: 0 当前ID: msg-t1715570328c1r7866 当前重发次数: 0 连续失败次数: 0 [2024-05-13 11:18:48.902][000007299.796] D/user.util_location.getMapLink
[2024-05-13 11:18:48.902][000007299.796] I/user.util_notify.send 发送通知 bark [2024-05-13 11:18:48.917][000007299.797] I/user.util_notify POST https://api.day.app/XXXXXXXXXXXXXXXXXXXX [2024-05-13 11:18:48.933][000007299.801] D/user.EVENT.NET_LED_UPDATE 50 50 nil [2024-05-13 11:18:48.933][000007299.801] D/user.util_http.fetch 开始请求 id: http_1 [2024-05-13 11:18:52.057][000007302.962] VOLTE_EVENT_PLAY_STOP [2024-05-13 11:18:52.057][000007302.963] LUAT_MOBILE_EVENT_CC status 12 [2024-05-13 11:18:52.075][000007302.964] I/user.==============cc_status==============: PLAY [2024-05-13 11:18:52.076][000007302.964] LUAT_MOBILE_EVENT_CC status 5 [2024-05-13 11:18:52.091][000007302.965] I/user.cc_status DISCONNECTED/HANGUP_CALL_DONE/MAKE_CALL_FAILED 挂断事件 18888888888 [2024-05-13 11:18:52.170][000007303.072] soc_cms_proc 1653:cenc report 1,38,1,5 [2024-05-13 11:18:52.170][000007303.073] cid5, state2 [2024-05-13 11:19:08.895][000007319.807] D/user.util_http.fetch 请求结束 id: http_1 code: -8 desc: HTTP_ERROR_TIMEOUT [2024-05-13 11:19:08.895][000007319.808] D/user.EVENT.NET_LED_UPDATE nil nil nil [2024-05-13 11:19:08.910][000007319.811] E/user.util_notify.send 发送通知失败, 等待重发 code: -8 body: nil [2024-05-13 11:19:08.910][000007319.811] I/user.util_notify.poll 等待下次重发 当前重发次数 1 连续失败次数 1 [2024-05-13 11:19:13.911][000007324.812] I/user.util_notify.poll 当前第 1 次重发失败, 保存到 fskv msg-t1715570328c1r7866 [2024-05-13 11:19:13.911][000007324.817] I/user.util_notify.poll fskv.set true used,total,count: 8192 65536 1 [2024-05-13 11:19:14.008][000007324.918] I/user.util_notify.poll 轮询消息队列中 总长度: 0 当前ID: msg-t1715570328c1r7866 当前重发次数: 1 连续失败次数: 1 [2024-05-13 11:19:14.023][000007324.920] D/user.util_location.getMapLink
[2024-05-13 11:19:14.023][000007324.920] I/user.util_notify.send 发送通知 bark [2024-05-13 11:19:14.039][000007324.921] I/user.util_notify POST https://api.day.app/XXXXXXXXXXXXXXXXXXXX [2024-05-13 11:19:14.055][000007324.924] D/user.EVENT.NET_LED_UPDATE 50 50 nil [2024-05-13 11:19:14.055][000007324.924] D/user.util_http.fetch 开始请求 id: http_2 [2024-05-13 11:19:34.024][000007344.927] D/user.util_http.fetch 请求结束 id: http_2 code: -8 desc: HTTP_ERROR_TIMEOUT [2024-05-13 11:19:34.024][000007344.927] D/user.EVENT.NET_LED_UPDATE nil nil nil [2024-05-13 11:19:34.039][000007344.930] E/user.util_notify.send 发送通知失败, 等待重发 code: -8 body: nil [2024-05-13 11:19:34.055][000007344.930] I/user.util_notify.poll 等待下次重发 当前重发次数 2 连续失败次数 2 [2024-05-13 11:19:39.032][000007349.931] W/user.util_notify.poll 连续失败次数过多, 开关飞行模式 [2024-05-13 11:19:40.439][000007351.345] ims reg state 1 [2024-05-13 11:19:40.439][000007351.345] cid15, state2 [2024-05-13 11:19:40.454][000007351.346] NETIF_LINK_OFF -> IP_LOSE [2024-05-13 11:19:41.008][000007351.911] cid1, state0 [2024-05-13 11:19:41.024][000007351.913] bearer act 0, result 0 [2024-05-13 11:19:41.024][000007351.914] NETIF_LINK_ON -> IP_READY [2024-05-13 11:19:41.039][000007351.941] TIME_SYNC 0 [2024-05-13 11:19:41.092][000007352.001] soc_cms_proc 1653:cenc report 1,51,1,15 [2024-05-13 11:19:41.539][000007352.447] I/user.util_notify.poll 轮询消息队列中 总长度: 0 当前ID: msg-t1715570328c1r7866 当前重发次数: 2 连续失败次数: 2 [2024-05-13 11:19:41.554][000007352.448] D/user.util_location.getMapLink
[2024-05-13 11:19:41.554][000007352.449] I/user.util_notify.send 发送通知 bark [2024-05-13 11:19:41.570][000007352.449] I/user.util_notify POST https://api.day.app/XXXXXXXXXXXXXXXXXXXX [2024-05-13 11:19:41.586][000007352.452] D/user.EVENT.NET_LED_UPDATE 50 50 nil [2024-05-13 11:19:41.586][000007352.453] D/user.util_http.fetch 开始请求 id: http_3 [2024-05-13 11:19:41.601][000007352.454] dns_run 668:api.day.app state 0 id 2 ipv6 0 use dns server0, try 0 [2024-05-13 11:19:41.617][000007352.491] dns_run 685:dns all done ,now stop [2024-05-13 11:19:42.348][000007353.251] NETIF_LINK_ON -> IP_READY [2024-05-13 11:19:42.649][000007353.554] D/user.util_http.fetch 请求结束 id: http_3 code: 200 desc: nil [2024-05-13 11:19:42.649][000007353.555] D/user.EVENT.NET_LED_UPDATE nil nil nil [2024-05-13 11:19:42.664][000007353.557] I/user.util_notify.send 发送通知成功 code: 200 body: {"code":200,"message":"success","timestamp":1715570382} [2024-05-13 11:19:43.042][000007353.941] ims reg state 0 [2024-05-13 11:19:43.042][000007353.941] LUAT_MOBILE_EVENT_CC status 0 [2024-05-13 11:19:43.058][000007353.942] LUAT_MOBILE_CC_READY [2024-05-13 11:19:43.058][000007353.943] I/user.==============cc_status==============: READY

[radiolee]

摘录了一些日志：IP_LOSE后，NTP失败，所以12小时NTP同步保活无效

[2024-05-13 21:57:43.817][000045634.661] I/user.util_notify.send 发送通知成功 code: 200 body: {"code":200,"message":"success","timestamp":1715608664} [2024-05-13 22:02:18.948][000045909.796] D/user.EVENT.CELL_INFO_UPDATE ………… [2024-05-13 23:27:11.974][000051002.818] D/user.EVENT.CELL_INFO_UPDATE [2024-05-13 23:27:12.023][000051002.879] soc_cms_proc 1653:cenc report 1,38,1,1 [2024-05-13 23:27:12.023][000051002.880] cid1, state2 [2024-05-13 23:27:12.039][000051002.880] NETIF_LINK_OFF -> IP_LOSE [2024-05-13 23:32:14.458][000051305.302] D/user.EVENT.CELL_INFO_UPDATE ………… [2024-05-14 03:12:18.924][000064509.776] D/user.EVENT.CELL_INFO_UPDATE [2024-05-14 03:17:10.692][000064801.538] query ntp.aliyun.com [2024-05-14 03:17:12.686][000064803.538] timeout send ntp_error [2024-05-14 03:17:12.686][000064803.538] 前一个ntp服务器未响应,尝试下一个 [2024-05-14 03:17:12.702][000064803.538] query ntp.ntsc.ac.cn [2024-05-14 03:17:13.792][000064804.648] D/user.EVENT.CELL_INFO_UPDATE [2024-05-14 03:17:14.692][000064805.538] timeout send ntp_error [2024-05-14 03:17:14.692][000064805.538] 前一个ntp服务器未响应,尝试下一个 [2024-05-14 03:17:14.708][000064805.538] query time1.cloud.tencent.com [2024-05-14 03:17:16.692][000064807.538] timeout send ntp_error

[radiolee]

-- 检测 NETIF_LINK_OFF -> IP_LOSE 事件 后开关飞行模式
sys.subscribe("IP_LOSE", function()
    mobile.flymode(0, true)
    mobile.flymode(0, false)
end)

加在主任务最前面，再测段时间

[radiolee]

-- 检测 NETIF_LINK_OFF -> IP_LOSE 事件 后开关飞行模式
sys.subscribe("IP_LOSE", function()
    mobile.flymode(0, true)
    mobile.flymode(0, false)
end)

成功，10:50等到一个IP_LOSE事件，开关飞行模式后，11:02电话触发秒发，没有重发现象了。

[2024-05-14 10:34:51.411][000004503.384] D/user.EVENT.CELL_INFO_UPDATE [2024-05-14 10:39:51.508][000004803.484] D/user.EVENT.CELL_INFO_UPDATE [2024-05-14 10:44:51.839][000005103.804] D/user.EVENT.CELL_INFO_UPDATE [2024-05-14 10:49:51.208][000005403.183] D/user.EVENT.CELL_INFO_UPDATE [2024-05-14 10:50:40.764][000005452.739] soc_cms_proc 1653:cenc report 1,38,1,1 [2024-05-14 10:50:40.764][000005452.740] cid1, state2 [2024-05-14 10:50:40.764][000005452.741] NETIF_LINK_OFF -> IP_LOSE [2024-05-14 10:50:42.164][000005454.134] I/user.IP_LOSE事件触发开关飞行模式 [2024-05-14 10:50:42.164][000005454.135] ims reg state 1 [2024-05-14 10:50:42.164][000005454.135] cid15, state2 [2024-05-14 10:50:42.164][000005454.136] NETIF_LINK_OFF -> IP_LOSE [2024-05-14 10:50:42.673][000005454.638] I/user.IP_LOSE事件触发开关飞行模式 [2024-05-14 10:50:42.784][000005454.743] W/user.util_notify.poll mobile.status nil 网络未注册 [2024-05-14 10:50:43.220][000005455.178] cid1, state0 [2024-05-14 10:50:43.221][000005455.178] bearer act 0, result 0 [2024-05-14 10:50:43.221][000005455.178] NETIF_LINK_ON -> IP_READY [2024-05-14 10:50:43.242][000005455.214] TIME_SYNC 0 [2024-05-14 10:50:43.323][000005455.284] soc_cms_proc 1653:cenc report 1,51,1,15 [2024-05-14 10:50:44.323][000005456.294] NETIF_LINK_ON -> IP_READY [2024-05-14 10:50:45.033][000005457.002] ims reg state 0 [2024-05-14 10:50:45.033][000005457.012] LUAT_MOBILE_EVENT_CC status 0 [2024-05-14 10:50:45.033][000005457.012] LUAT_MOBILE_CC_READY [2024-05-14 10:50:45.033][000005457.013] I/user.==============cc_status==============: READY [2024-05-14 10:55:45.527][000005757.502] D/user.EVENT.CELL_INFO_UPDATE [2024-05-14 11:00:45.470][000006057.442] D/user.EVENT.CELL_INFO_UPDATE [2024-05-14 11:02:31.492][000006163.460] LUAT_MOBILE_EVENT_CC status 12 [2024-05-14 11:02:31.492][000006163.461] I/user.==============cc_status==============: PLAY [2024-05-14 11:02:31.492][000006163.461] LUAT_MOBILE_EVENT_CC status 1 [2024-05-14 11:02:31.492][000006163.462] I/user.cc_status INCOMINGCALL 来电事件 18888888888 [2024-05-14 11:02:31.492][000006163.472] D/user.util_notify.add 添加到消息队列, 当前队列长度: 1 消息内容: 来电号码: 18888888888\n来电时间: 2024-05-14 11:02:31\n#CALL #CALL_IN 2 [2024-05-14 11:02:31.492][000006163.473] LUAT_MOBILE_EVENT_CC status 2 [2024-05-14 11:02:31.612][000006163.575] I/user.util_notify.poll 轮询消息队列中 总长度: 0 当前ID: msg-t1715655751c2r9812 当前重发次数: 0 连续失败次数: 0 [2024-05-14 11:02:31.620][000006163.577] D/user.util_location.getMapLink
[2024-05-14 11:02:31.623][000006163.577] I/user.util_notify.send 发送通知 bark [2024-05-14 11:02:31.638][000006163.578] I/user.util_notify POST https://api.day.app/XXXXXXXX [2024-05-14 11:02:31.638][000006163.581] D/user.EVENT.NET_LED_UPDATE 50 50 nil [2024-05-14 11:02:31.654][000006163.582] D/user.util_http.fetch 开始请求 id: http_2 [2024-05-14 11:02:31.670][000006163.583] dns_run 668:api.day.app state 0 id 3 ipv6 0 use dns server0, try 0 [2024-05-14 11:02:31.701][000006163.674] dns_run 685:dns all done ,now stop [2024-05-14 11:02:32.808][000006164.772] D/user.util_http.fetch 请求结束 id: http_2 code: 200 desc: nil [2024-05-14 11:02:32.808][000006164.773] D/user.EVENT.NET_LED_UPDATE nil nil nil [2024-05-14 11:02:32.823][000006164.775] I/user.util_notify.send 发送通知成功 code: 200 body: {"code":200,"message":"success","timestamp":1715655753} [2024-05-14 11:02:33.757][000006165.729] VOLTE_EVENT_PLAY_STOP [2024-05-14 11:02:33.757][000006165.729] LUAT_MOBILE_EVENT_CC status 12 [2024-05-14 11:02:33.776][000006165.730] I/user.==============cc_status==============: PLAY [2024-05-14 11:02:33.776][000006165.730] LUAT_MOBILE_EVENT_CC status 5 [2024-05-14 11:02:33.792][000006165.731] I/user.cc_status DISCONNECTED/HANGUP_CALL_DONE/MAKE_CALL_FAILED 挂断事件 18888888888 [2024-05-14 11:02:33.870][000006165.837] soc_cms_proc 1653:cenc report 1,38,1,7 [2024-05-14 11:02:33.870][000006165.838] cid7, state2 [2024-05-14 11:05:45.464][000006357.441] D/user.EVENT.CELL_INFO_UPDATE

[radiolee]

https://github.com/0wQ/air780e-forwarder/pull/55 已提交PR

[radiolee]

仍有问题，继续测