otbr-agent restarting after linux pc coming out of sleep mode

[gadekula1]

otbr-agent restarting after linux pc coming out of sleep mode

pid before sleep:

` systemctl status otbr-agent

• otbr-agent.service - OpenThread Border Router Agent
  Loaded: loaded (/lib/systemd/system/otbr-agent.service; enabled; vendor preset: enabled)
  Active: active (running)
  since Sat 2022-12-31 19:01:12 EST; 1min 32s ago
  Main PID: 5834 (otbr-agent-serv)
  Memory: 616.0K
  CGroup: /system.slice/otbr-agent.service
  |- 5834 /bin/sh /etc/systemd/system/scripts/otbr-agent-service.sh
  - 5854 /usr/sbin/otbr-agent -I wpan0 -B eth0 "spinel+hdlc+uart:///dev/ttyAMA1?uart-baudrate=921600/" trel://eth0

pid after sleep:

`systemctl status otbr-agent

• otbr-agent.service - OpenThread Border Router Agent
  Loaded: loaded (/lib/systemd/system/otbr-agent.service; enabled; vendor preset: enabled)
  Active: active (running)
  since Sat 2022-12-31 19:14:44 EST; 1min 2s ago
  Main PID: 11033 (otbr-agent-serv)
  Memory: 620.0K
  CGroup: /system.slice/otbr-agent.service
  |- 11033 /bin/sh /etc/systemd/system/scripts/otbr-agent-service.sh
  - 11073 /usr/sbin/otbr-agent -I wpan0 -B eth0 "spinel+hdlc+uart:///dev/ttyAMA1?uart-baudrate=921600/" trel://eth0
  Logs:

[5854] 00:13:23.666 [I] InfraIf-------: State changed: RUNNING -> NOT RUNNING 2023-01-01T00:14:37.905537Z [878.887989480] user.info otbr-agent[5854] 00:13:23.666 [I] BorderRouter--: Removed local OMR prefix fd51:a5e:23c3:1::/64 from Thread Network Data 2023-01-01T00:14:37.905950Z [878.888405140] user.info otbr-agent[5854] 00:13:23.666 [I] NetDataPublshr: Unpublishing fd11:1111:1122:2222::/64 2023-01-01T00:14:37.906003Z [878.888455560] user.info otbr-agent[5854] 00:13:23.666 [I] NetDataPublshr: ExternalRoute fd11:1111:1122:2222::/64 - State: Added -> NoEntry 2023-01-01T00:14:37.906029Z [878.888481400] user.info otbr-agent[5854] 00:13:23.666 [I] BorderRouter--: RouterAdvert: Added PIO for fd11:1111:1122:2222::/64 (valid=1543, preferred=0) 2023-01-01T00:14:37.906053Z [878.888505000] user.info otbr-agent[5854] 00:13:23.666 [I] BorderRouter--: RouterAdvert: Added PIO for fd11:1111:1122:2222::/64 (valid=995, preferred=0) 2023-01-01T00:14:37.906301Z [878.888755520] user.info otbr-agent[5854] 00:13:23.666 [I] BorderRouter--: RouterAdvert: Added RIO for fd51:a5e:23c3:1::/64 (lifetime=0) 2023-01-01T00:14:37.906360Z [878.888813100] user.info otbr-agent[5854] 00:13:23.666 [I] BorderRouter--: Sent Router Advertisement on infra netif 2 2023-01-01T00:14:37.906412Z [878.888875700] user.info otbr-agent[5854] 00:13:23.666 [I] BorderRouter--: Border Routing manager stopped 2023-01-01T00:14:37.906453Z [878.888905200] user.info otbr-agent[5854] 00:13:23.666 [I] MeshForwarder-: Received IPv6 UDP msg, len:96, chksum:7962, ecn:no, from:061c676a3ea7a782, sec:no, prio:net, rss:0.0 2023-01-01T00:14:37.906494Z [878.888948200] user.info otbr-agent[5854] 00:13:23.666 [I] MeshForwarder-: src:[fe80:0:0:0:41c:676a:3ea7:a782]:19788 2023-01-01T00:14:37.906542Z [878.888995480] user.info otbr-agent[5854] 00:13:23.666 [I] MeshForwarder-: dst:[fe80:0:0:0:a8fe:737d:13d1:62d1]:19788 2023-01-01T00:14:37.906583Z [878.889035800] user.info otbr-agent[5854] 00:13:23.666 [I] Mle-----------: Receive Link Request (fe80:0:0:0:41c:676a:3ea7:a782) 2023-01-01T00:14:37.906619Z [878.889072100] user.info otbr-agent[5854] 00:13:23.666 [I] Mle-----------: Send Link Accept (fe80:0:0:0:41c:676a:3ea7:a782) 2023-01-01T00:14:37.906644Z [878.889096340] user.info otbr-agent[5854] 00:13:23.666 [I] NetworkData---: Sent server data notification 2023-01-01T00:14:37.906710Z [878.889164860] user.info otbr-agent[5854] 00:13:23.666 [I] NetworkData---: Received network data registration 2023-01-01T00:14:37.907477Z [878.889935340] user.info otbr-agent[5854] 00:13:23.666 [I] NetworkData---: Sent network data registration acknowledgment 2023-01-01T00:14:37.907568Z [878.890021060] user.info otbr-agent[5854] 00:13:23.666 [I] Notifier------: StateChanged (0x00000200) [NetData] 2023-01-01T00:14:37.907645Z [878.890099480] user.info otbr-agent[5854] 00:13:23.667 [I] Mle-----------: Send Data Response (ff02:0:0:0:0:0:0:1) 2023-01-01T00:14:37.907673Z [878.890125360] user.info otbr-agent[5854] 00:13:23.667 [I] BbrLeader-----: PBBR state: Unchanged 2023-01-01T00:14:37.907695Z [878.890147200] user.info otbr-agent[5854] 00:13:23.667 [I] BbrLeader-----: Rloc16:0x2400, seqno:40, delay:5, timeout:3600 2023-01-01T00:14:37.907716Z [878.890167980] user.info otbr-agent[5854] 00:13:23.667 [I] BbrLeader-----: Domain Prefix: ::/0, state: None 2023-01-01T00:14:37.907749Z [878.890201680] user.info otbr-agent[5854] 00:13:23.667 [I] Slaac---------: Removing address fd51:a5e:23c3:1:8142:9b60:720f:bff3 2023-01-01T00:14:37.907790Z [878.890243300] user.info otbr-agent[5854] 00:13:23.667 [I] Platform------: [netif] Sent request#11 to remove fd51:a5e:23c3:1:8142:9b60:720f:bff3/64 2023-01-01T00:14:37.907823Z [878.890275900] user.info otbr-agent[5854] 00:13:23.667 [I] NetDataPublshr: DNS/SRP service (state:Added) in netdata - total:1, preferred:0, desired:2 2023-01-01T00:14:37.907845Z [878.890297700] user.info otbr-agent[5854] 00:13:23.667 [I] Notifier------: StateChanged (0x00000002) [Ip6-] 2023-01-01T00:14:37.907866Z [878.890318460] user.info otbr-agent[5854] 00:13:23.667 [I] Platform------: [netif] DEL [U] fd51:a5e:23c3:1:8142:9b60:720f:bff3 (not found, ignored) 2023-01-01T00:14:37.907887Z [878.890339240] user.info otbr-agent[5854] 00:13:23.667 [I] Platform------: [netif] Succeeded to process request#11 2023-01-01T00:14:37.908046Z [878.890498500] user.warning otbr-agent[5854] 00:13:23.669 [W] Platform------: Handle transmit done failed: Parse 2023-01-01T00:14:39.121696Z [880.104157700] daemon.notice kernel systemd[1]: otbr-agent.service: Main process exited, code=exited, status=134/n/a 2023-01-01T00:14:39.121782Z [880.104235740] daemon.warning kernel systemd[1]: otbr-agent.service: Failed with result 'exit-code'. 2023-01-01T00:14:44.194204Z [885.176664840] daemon.info kernel systemd[1]: otbr-agent.service: Scheduled restart job, restart counter is at 1.

Analysis:

analysis on above logs:

changing lan state to InfraIf-------: State changed: RUNNING -> NOT RUNNING
Unpublishing ip addr
Border Routing manager stopped
Platform------: [netif] DEL [U] fd51:a5e:23c3:1:8142:9b60:720f:bff3
Platform------: Handle transmit done failed:

if (err->error == 0)
{
    otLogInfoPlat("[netif] Succeeded to process request#%u", requestSeq);
    ExitNow();
}

triggering exit

#define ExitNow(...)
do
{
VA_ARGS;
goto exit;
} while (false)

finally returning fromprocessNetlinkEvent

from platformNetifProcess

void otSysMainloopProcess(otInstance aInstance, const otSysMainloopContext aMainloop)
{
ot::Posix::Mainloop::Manager::Get().Process(*aMainloop);

#if OPENTHREAD_POSIX_VIRTUAL_TIME
virtualTimeProcess(aInstance, aMainloop);
#else
platformRadioProcess(aInstance, aMainloop);
#endif
#if OPENTHREAD_CONFIG_RADIO_LINK_TREL_ENABLE
platformTrelProcess(aInstance, aMainloop);
#endif
platformAlarmProcess(aInstance);
#if OPENTHREAD_CONFIG_PLATFORM_NETIF_ENABLE
platformNetifProcess(aMainloop);
#endif
}

    if (otSysMainloopPoll(&mainloop) >= 0)
    {
        otSysMainloopProcess(instance, &mainloop);

#if !OPENTHREAD_POSIX_CONFIG_DAEMON_ENABLE
otAppCliProcess(&mainloop);
#endif

finally its existing from main method

while parsing NetlinkEvent (Received IPv6 UDP msg and trying to forward on non existing ip) its going for the toss and exiting from main