otbr-agent keep changing status continously #10224

testter2 · 2024-05-13T08:56:39Z

testter2
May 13, 2024

Hi,

I'm working on OTBR using raspberry pi (RCP design),

I have followed steps from : https://openthread.io/guides/border-router/build#install-otbr

raspberry pi and my pc are connected on locally ethernet switch( not connected to internet) , pc communicate with raspberry pi using ssh.

otbr-agent keep changing status continuously and when it's status not running, I can't communicate to raspberry pi.

The following logs shows the services status



pi@raspberrypi:~ $ sudo systemctl status
● raspberrypi
    State: degraded
    Units: 315 loaded (incl. loaded aliases)
     Jobs: 0 queued
   Failed: 1 units
    Since: Thu 1970-01-01 02:00:03 EET; 54 years 4 months ago
  systemd: 252.17-1~deb12u1+rpi1
   CGroup: /
           ├─init.scope
           │ └─1 /sbin/init
           ├─system.slice
           │ ├─ModemManager.service
           │ │ └─689 /usr/sbin/ModemManager
           │ ├─NetworkManager.service
           │ │ └─692 /usr/sbin/NetworkManager --no-daemon
           │ ├─avahi-daemon.service
           │ │ ├─519 "avahi-daemon: running [raspberrypi.local]"
           │ │ └─536 "avahi-daemon: chroot helper"
           │ ├─bluetooth.service
           │ │ └─725 /usr/libexec/bluetooth/bluetoothd
           │ ├─cron.service
           │ │ └─522 /usr/sbin/cron -f
           │ ├─dbus.service
           │ │ └─523 /usr/bin/dbus-daemon --system --address=systemd: --nofork --nopidfile --systemd-activation --syslog-only
           │ ├─mdns.service
           │ │ └─835 /usr/sbin/mdnsd
           │ ├─otbr-agent.service
           │ │ └─836 /usr/sbin/otbr-agent -I wpan0 -B eth0 "spinel+hdlc+uart:///dev/ttyUSB1?uart-baudrate=115200" trel://eth0
           │ ├─otbr-web.service
           │ │ └─837 /usr/sbin/otbr-web
           │ ├─polkit.service
           │ │ └─539 /usr/lib/polkit-1/polkitd --no-debug
           │ ├─rsyslog.service
           │ │ └─543 /usr/sbin/rsyslogd -n -iNONE
           │ ├─ssh.service
           │ │ └─764 "sshd: /usr/sbin/sshd -D [listener] 0 of 10-100 startups"
           │ ├─system-getty.slice
           │ │ └─[email protected]
           │ │   └─833 /sbin/agetty -o "-p -- \\u" --noclear - linux
           │ ├─systemd-journald.service
           │ │ └─242 /lib/systemd/systemd-journald
           │ ├─systemd-logind.service
           │ │ └─552 /lib/systemd/systemd-logind
           │ ├─systemd-timesyncd.service
           │ │ └─444 /lib/systemd/systemd-timesyncd
           │ ├─systemd-udevd.service
           │ │ └─udev
           │ │   ├─268 /lib/systemd/systemd-udevd
           │ │   ├─840 "(udev-worker)"
           │ │   ├─841 "(udev-worker)"
           │ │   └─842 "(udev-worker)"
           │ ├─triggerhappy.service
           │ │ └─554 /usr/sbin/thd --triggers /etc/triggerhappy/triggers.d/ --socket /run/thd.socket --user nobody --deviceglob "/dev/input/event*"
           │ └─wpa_supplicant.service
           │   └─694 /sbin/wpa_supplicant -u -s -O "DIR=/run/wpa_supplicant GROUP=netdev"
           └─user.slice
             └─user-1000.slice
               ├─session-1.scope
               │ ├─780 "sshd: pi [priv]"
               │ ├─803 "sshd: pi@pts/0"
               │ ├─804 -bash
               │ ├─859 sudo systemctl status
               │ ├─860 sudo systemctl status
               │ ├─861 systemctl status
               │ └─862 less
               └─[email protected]
                 └─init.scope
                   ├─783 /lib/systemd/systemd --user
                   └─784 "(sd-pam)"

pi@raspberrypi:~ $ sudo service otbr-agent status
● otbr-agent.service - OpenThread Border Router Agent
     Loaded: loaded (/lib/systemd/system/otbr-agent.service; enabled; preset: enabled)
     Active: active (running) since Mon 2024-05-13 11:22:41 EEST; 9s ago
    Process: 527 ExecStartPre=/usr/sbin/service mdns start (code=exited, status=0/SUCCESS)
   Main PID: 836 (otbr-agent)
      Tasks: 1 (limit: 4915)
        CPU: 162ms
     CGroup: /system.slice/otbr-agent.service
             └─836 /usr/sbin/otbr-agent -I wpan0 -B eth0 "spinel+hdlc+uart:///dev/ttyUSB1?uart-baudrate=115200" trel://eth0
May 13 11:22:42 raspberrypi otbr-agent[836]: 00:00:00.217 [I] P-Netif-------: Deleting route for NAT64
May 13 11:22:42 raspberrypi otbr-agent[836]: 00:00:00.217 [I] P-McastRtMgr--: Disable: OK
May 13 11:22:42 raspberrypi otbr-agent[836]: [INFO]-BA------: Publish meshcop service OpenThread BorderRouter #ADEC._meshcop._udp.local.
May 13 11:22:42 raspberrypi otbr-agent[836]: 00:00:00.218 [I] RouterTable---: Route table
May 13 11:22:42 raspberrypi otbr-agent[836]: 00:00:00.235 [I] P-Netif-------: Host netif is down
May 13 11:22:42 raspberrypi otbr-agent[836]: 00:00:00.236 [I] P-Netif-------: Succeeded to process request#1
May 13 11:22:42 raspberrypi otbr-agent[836]: 00:00:00.236 [W] P-Netif-------: Failed to process request#2: No such process
May 13 11:22:42 raspberrypi otbr-agent[836]: [INFO]-MDNS----: Successfully registered service OpenThread BorderRouter #ADEC._meshcop._udp
May 13 11:22:42 raspberrypi otbr-agent[836]: [INFO]-BA------: Result of publish meshcop service OpenThread BorderRouter #ADEC._meshcop._udp.local: OK
May 13 11:22:42 raspberrypi otbr-agent[836]: [INFO]-BA------: Result of publish meshcop service OpenThread BorderRouter #ADEC._meshcop._udp.local: OK

pi@raspberrypi:~ $ sudo service mdns status
● mdns.service - LSB: Apple Multicast DNS / DNS Service Discovery daemon
     Loaded: loaded (/etc/init.d/mdns; generated)
     Active: active (running) since Mon 2024-05-13 11:22:41 EEST; 37s ago
       Docs: man:systemd-sysv-generator(8)
    Process: 827 ExecStart=/etc/init.d/mdns start (code=exited, status=0/SUCCESS)
      Tasks: 1 (limit: 4915)
        CPU: 78ms
     CGroup: /system.slice/mdns.service
             └─835 /usr/sbin/mdnsd
May 13 11:22:48 raspberrypi mDNSResponder[835]: Default: mDNSCoreReceiveResponse: Received from 127.0.0.1:5353   21 1.0.0.127.in-addr.arpa. PTR raspberrypi-3.local.
May 13 11:22:48 raspberrypi mDNSResponder[835]: Default: mDNSCoreReceiveResponse: Unexpected conflict discarding   21 1.0.0.127.in-addr.arpa. PTR raspberrypi-4.local.
May 13 11:23:16 raspberrypi mDNSResponder[835]: Default: mDNSPlatformSendUDP got error 99 (Cannot assign requested address) sending packet to ff02::fb on interface fe80::f10:d835:aebc:dcf3/eth0/2
May 13 11:23:17 raspberrypi mDNSResponder[835]: Default: mDNSPlatformSendUDP got error 99 (Cannot assign requested address) sending packet to ff02::fb on interface fe80::f10:d835:aebc:dcf3/eth0/2
May 13 11:23:17 raspberrypi mDNSResponder[835]: Default: mDNSPlatformSendUDP got error 99 (Cannot assign requested address) sending packet to ff02::fb on interface fe80::f10:d835:aebc:dcf3/eth0/2
May 13 11:23:17 raspberrypi mDNSResponder[835]: Default: mDNSPlatformSendUDP got error 99 (Cannot assign requested address) sending packet to ff02::fb on interface fe80::f10:d835:aebc:dcf3/eth0/2
May 13 11:23:17 raspberrypi mDNSResponder[835]: Default: mDNSPlatformSendUDP got error 99 (Cannot assign requested address) sending packet to ff02::fb on interface fe80::f10:d835:aebc:dcf3/eth0/2
May 13 11:23:17 raspberrypi mDNSResponder[835]: Default: mDNSPlatformSendUDP got error 99 (Cannot assign requested address) sending packet to ff02::fb on interface fe80::f10:d835:aebc:dcf3/eth0/2
May 13 11:23:18 raspberrypi mDNSResponder[835]: Default: mDNSCoreReceiveResponse: Received from fe80::f10:d835:aebc:dcf3:5353   21 3.f.c.d.c.b.e.a.5.3.8.d.0.1.f.0.0.0.0.0.0.0.0.0.0.0.0.0.0.8.e.f.ip6.arp>
May 13 11:23:18 raspberrypi mDNSResponder[835]: Default: mDNSCoreReceiveResponse: Unexpected conflict discarding   21 3.F.C.D.C.B.E.A.5.3.8.D.0.1.F.0.0.0.0.0.0.0.0.0.0.0.0.0.0.8.E.F.ip6.arpa. PTR raspbe>

pi@raspberrypi:~ $ sudo service otbr-web status
● otbr-web.service - Border Router Web
     Loaded: loaded (/lib/systemd/system/otbr-web.service; enabled; preset: enabled)
     Active: active (running) since Mon 2024-05-13 11:22:41 EEST; 45s ago
   Main PID: 837 (otbr-web)
      Tasks: 1 (limit: 4915)
        CPU: 13ms
     CGroup: /system.slice/otbr-web.service
             └─837 /usr/sbin/otbr-web
May 13 11:22:41 raspberrypi systemd[1]: Started otbr-web.service - Border Router Web.
May 13 11:22:41 raspberrypi otbr-web[837]: otbr-web[837]: [INFO]-WEB-----: Running 0.3.0-thread-reference-20230710-250-g72ae1f15c8
May 13 11:22:41 raspberrypi otbr-web[837]: otbr-web[837]: [INFO]-WEB-----: Border router web started on wpan0
May 13 11:22:41 raspberrypi otbr-web[837]: [INFO]-WEB-----: Running 0.3.0-thread-reference-20230710-250-g72ae1f15c8
May 13 11:22:41 raspberrypi otbr-web[837]: [INFO]-WEB-----: Border router web started on wpan0
May 13 11:22:41 raspberrypi otbr-web[837]: otbr-web[837]: [ERR ]-WEB-----: OpenThread daemon is not running.
May 13 11:22:41 raspberrypi otbr-web[837]: [ERR ]-WEB-----: OpenThread daemon is not running.

pi@raspberrypi:~ $ sudo ot-ctl state
disabled
Done

pi@raspberrypi:~ $ sudo systemctl --failed
  UNIT                               LOAD   ACTIVE SUB    DESCRIPTION
● NetworkManager-wait-online.service loaded failed failed Network Manager Wait Online
LOAD   = Reflects whether the unit definition was properly loaded.
ACTIVE = The high-level unit activation state, i.e. generalization of SUB.
SUB    = The low-level unit activation state, values depend on unit type.
1 loaded units listed.

pi@raspberrypi:~ $ cat /var/log/syslog | grep otbr-agent
raspberrypi systemd[1]: Starting otbr-agent.service - OpenThread Border Router Agent...
raspberrypi systemd[1]: Started otbr-agent.service - OpenThread Border Router Agent.
raspberrypi otbr-agent: [NOTE]-AGENT---: Backbone interface: eth0
raspberrypi otbr-agent[890]: [NOTE]-AGENT---: Running 0.3.0-thread-reference-20230710-250-g72ae1f15c8
raspberrypi otbr-agent[890]: [NOTE]-AGENT---: Thread version: 1.3.0
raspberrypi otbr-agent[890]: [NOTE]-AGENT---: Thread interface: wpan0
raspberrypi otbr-agent[890]: [NOTE]-AGENT---: Radio URL: spinel+hdlc+uart:///dev/ttyUSB1?uart-baudrate=115200
raspberrypi otbr-agent[890]: [NOTE]-AGENT---: Radio URL: trel://eth0
raspberrypi otbr-agent[890]: [NOTE]-ILS-----: Infra link selected: eth0
raspberrypi otbr-agent[890]: [INFO]-NCP-----: OpenThread log level changed to 4
raspberrypi otbr-agent[890]: 49d.17:03:41.606 [I] P-SpinelDrive-: co-processor reset: RESET_POWER_ON
raspberrypi otbr-agent[890]: 49d.17:03:41.606 [C] P-SpinelDrive-: Software reset co-processor successfully
raspberrypi otbr-agent[890]: 49d.17:03:41.716 [I] P-Netif-------: Sent request#1 to set addr_gen_mode to 1
raspberrypi otbr-agent[890]: 00:00:00.191 [I] ChildSupervsn-: Timeout: 0 -> 190
raspberrypi otbr-agent[890]: 00:00:00.192 [I] RoutingManager: Initializing - InfraIfIndex:2
raspberrypi otbr-agent[890]: 00:00:00.192 [I] InfraIf-------: Init infra netif 2
raspberrypi otbr-agent[890]: 00:00:00.192 [N] RoutingManager: No valid /48 BR ULA prefix found in settings, generating new one
raspberrypi otbr-agent[890]: 00:00:00.198 [I] Settings------: Saved BrUlaPrefix fdba:3610:a377::/48
raspberrypi otbr-agent[890]: 00:00:00.198 [N] RoutingManager: BR ULA prefix: fdba:3610:a377::/48 (generated)
raspberrypi otbr-agent[890]: 00:00:00.198 [I] RoutingManager: Generated local OMR prefix: fdba:3610:a377:1::/64
raspberrypi otbr-agent[890]: 00:00:00.198 [I] RoutingManager: Generated local NAT64 prefix: fdba:3610:a377:2:0:0::/96
raspberrypi otbr-agent[890]: 00:00:00.198 [N] RoutingManager: Local on-link prefix: fdde:ad00:beef:cafe::/64
raspberrypi otbr-agent[890]: 00:00:00.198 [I] InfraIf-------: State changed: NOT RUNNING -> RUNNING
raspberrypi otbr-agent[890]: 00:00:00.198 [I] RoutingManager: Enabling
raspberrypi otbr-agent[890]: 00:00:00.198 [I] Nat64---------: IPv4 CIDR for NAT64: 192.168.255.0/24 (actual address pool: 192.168.255.1 - 192.168.255.254, 254 addresses)
raspberrypi otbr-agent[890]: 00:00:00.198 [I] Nat64---------: NAT64 translator is now Disabled
raspberrypi otbr-agent[890]: 00:00:00.200 [I] P-Resolver----: Got nameserver #0: 172.16.0.27
raspberrypi otbr-agent[890]: 00:00:00.200 [I] P-Resolver----: Got nameserver #1: 172.16.0.25
raspberrypi otbr-agent[890]: 00:00:00.200 [I] P-Resolver----: Got nameserver #2: 172.16.0.20
raspberrypi otbr-agent[890]: [INFO]-UTILS---: Set state callback: OK
raspberrypi otbr-agent[890]: 00:00:00.201 [I] Nat64---------: NAT64 translator is now NotRunning
raspberrypi otbr-agent[890]: [INFO]-BA------: Start Thread Border Agent
raspberrypi otbr-agent[890]: [INFO]-BA------: Publish meshcop service OpenThread BorderRouter #B1E5._meshcop._udp.local.
raspberrypi otbr-agent[890]: 00:00:00.208 [I] Settings------: Saved BorderAgentId {id:aa7ceda9c581493bd47e4ec6cbe66ee1}
raspberrypi otbr-agent[890]: [INFO]-MDNS----: Registering service OpenThread BorderRouter #B1E5._meshcop._udp
raspberrypi otbr-agent[890]: 00:00:00.209 [I] BbrLocal------: Add Domain Prefix: ::/0, NotFound
raspberrypi otbr-agent[890]: 00:00:00.209 [I] BbrLocal------: Add BBR Service: seqno (80), delay (5s), timeout (3600s), InvalidState
raspberrypi otbr-agent[890]: [INFO]-ADPROXY-: Started
raspberrypi otbr-agent[890]: [INFO]-DPROXY--: Started
raspberrypi otbr-agent[890]: [INFO]-APP-----: Thread Border Router started on AIL eth0.
raspberrypi otbr-agent[890]: 00:00:00.212 [I] Notifier------: StateChanged (0x42038210) [MLAddr NetData PanId NetName ExtPanId BbrState Nat64]
raspberrypi otbr-agent[890]: 00:00:00.212 [I] Bbr-----------: Start listening on port 61631
raspberrypi otbr-agent[890]: 00:00:00.212 [I] Bbr-----------: Backbone TMF subscribes ff32:40:fdde:ad00:beef:0:0:3: OK
raspberrypi otbr-agent[890]: 00:00:00.212 [I] BbrManager----: Start Backbone TMF agent: OK
raspberrypi otbr-agent[890]: 00:00:00.216 [I] Platform------: Execute command `ipset flush otbr-ingress-allow-dst-swap` = 0
raspberrypi otbr-agent[890]: 00:00:00.219 [I] Platform------: Execute command `ipset flush otbr-ingress-deny-src-swap` = 0
raspberrypi otbr-agent[890]: 00:00:00.222 [I] Platform------: Execute command `ipset add otbr-ingress-deny-src-swap fdde:ad00:beef:0::/64 -exist` = 0
raspberrypi otbr-agent[890]: 00:00:00.226 [I] Platform------: Execute command `ipset swap otbr-ingress-deny-src-swap otbr-ingress-deny-src` = 0
raspberrypi otbr-agent[890]: 00:00:00.229 [I] Platform------: Execute command `ipset swap otbr-ingress-allow-dst-swap otbr-ingress-allow-dst` = 0
raspberrypi otbr-agent[890]: 00:00:00.229 [I] P-Netif-------: NAT64 CIDR updated to 192.168.255.0/24.
raspberrypi otbr-agent[890]: 00:00:00.229 [I] P-Netif-------: Deleting route for NAT64
raspberrypi otbr-agent[890]: 00:00:00.229 [I] P-McastRtMgr--: Disable: OK
raspberrypi otbr-agent[890]: [INFO]-BA------: Publish meshcop service OpenThread BorderRouter #B1E5._meshcop._udp.local.
raspberrypi otbr-agent[890]: 00:00:00.229 [I] RouterTable---: Route table
raspberrypi otbr-agent[890]: 00:00:00.246 [I] P-Netif-------: Host netif is down
raspberrypi otbr-agent[890]: 00:00:00.247 [I] P-Netif-------: Succeeded to process request#1
raspberrypi otbr-agent[890]: 00:00:00.247 [W] P-Netif-------: Failed to process request#2: No such process
raspberrypi otbr-agent[890]: [INFO]-MDNS----: Successfully registered service OpenThread BorderRouter #B1E5._meshcop._udp
raspberrypi otbr-agent[890]: [INFO]-BA------: Result of publish meshcop service OpenThread BorderRouter #B1E5._meshcop._udp.local: OK
raspberrypi otbr-agent[890]: [INFO]-BA------: Result of publish meshcop service OpenThread BorderRouter #B1E5._meshcop._udp.local: OK
raspberrypi otbr-agent[890]: 00:00:26.205 [I] P-Daemon------: Session socket is ready
raspberrypi systemd[1]: Starting otbr-agent.service - OpenThread Border Router Agent...
raspberrypi systemd[1]: Started otbr-agent.service - OpenThread Border Router Agent.
raspberrypi otbr-agent: [NOTE]-AGENT---: Backbone interface: eth0
raspberrypi otbr-agent[850]: [NOTE]-AGENT---: Running 0.3.0-thread-reference-20230710-250-g72ae1f15c8
raspberrypi otbr-agent[850]: [NOTE]-AGENT---: Thread version: 1.3.0
raspberrypi otbr-agent[850]: [NOTE]-AGENT---: Thread interface: wpan0
raspberrypi otbr-agent[850]: [NOTE]-AGENT---: Radio URL: spinel+hdlc+uart:///dev/ttyUSB1?uart-baudrate=115200
raspberrypi otbr-agent[850]: [NOTE]-AGENT---: Radio URL: trel://eth0
raspberrypi otbr-agent[850]: [NOTE]-ILS-----: Infra link selected: eth0
raspberrypi otbr-agent[850]: [INFO]-NCP-----: OpenThread log level changed to 4
raspberrypi otbr-agent[850]: 49d.17:04:01.876 [I] P-SpinelDrive-: co-processor reset: RESET_POWER_ON
raspberrypi otbr-agent[850]: 49d.17:04:01.876 [C] P-SpinelDrive-: Software reset co-processor successfully
raspberrypi otbr-agent[850]: 49d.17:04:01.985 [I] P-Netif-------: Sent request#1 to set addr_gen_mode to 1
raspberrypi otbr-agent[850]: 00:00:00.197 [I] ChildSupervsn-: Timeout: 0 -> 190
raspberrypi otbr-agent[850]: 00:00:00.198 [I] RoutingManager: Initializing - InfraIfIndex:2
raspberrypi otbr-agent[850]: 00:00:00.198 [I] InfraIf-------: Init infra netif 2
raspberrypi otbr-agent[850]: 00:00:00.198 [I] Settings------: Read BrUlaPrefix fdba:3610:a377::/48
raspberrypi otbr-agent[850]: 00:00:00.198 [N] RoutingManager: BR ULA prefix: fdba:3610:a377::/48 (loaded)
raspberrypi otbr-agent[850]: 00:00:00.198 [I] RoutingManager: Generated local OMR prefix: fdba:3610:a377:1::/64
raspberrypi otbr-agent[850]: 00:00:00.198 [I] RoutingManager: Generated local NAT64 prefix: fdba:3610:a377:2:0:0::/96
raspberrypi otbr-agent[850]: 00:00:00.198 [N] RoutingManager: Local on-link prefix: fdde:ad00:beef:cafe::/64
raspberrypi otbr-agent[850]: 00:00:00.198 [I] InfraIf-------: State changed: NOT RUNNING -> RUNNING
raspberrypi otbr-agent[850]: 00:00:00.198 [I] RoutingManager: Enabling
raspberrypi otbr-agent[850]: 00:00:00.199 [I] Nat64---------: IPv4 CIDR for NAT64: 192.168.255.0/24 (actual address pool: 192.168.255.1 - 192.168.255.254, 254 addresses)
raspberrypi otbr-agent[850]: 00:00:00.199 [I] Nat64---------: NAT64 translator is now Disabled
raspberrypi otbr-agent[850]: 00:00:00.201 [I] P-Resolver----: Got nameserver #0: 172.16.0.27
raspberrypi otbr-agent[850]: 00:00:00.201 [I] P-Resolver----: Got nameserver #1: 172.16.0.25
raspberrypi otbr-agent[850]: 00:00:00.202 [I] P-Resolver----: Got nameserver #2: 172.16.0.20
raspberrypi otbr-agent[850]: [INFO]-UTILS---: Set state callback: OK
raspberrypi otbr-agent[850]: 00:00:00.202 [I] Nat64---------: NAT64 translator is now NotRunning
raspberrypi otbr-agent[850]: [INFO]-BA------: Start Thread Border Agent
raspberrypi otbr-agent[850]: [INFO]-BA------: Publish meshcop service OpenThread BorderRouter #0BB2._meshcop._udp.local.
raspberrypi otbr-agent[850]: 00:00:00.203 [I] Settings------: Read BorderAgentId {id:aa7ceda9c581493bd47e4ec6cbe66ee1}
raspberrypi otbr-agent[850]: [INFO]-MDNS----: Registering service OpenThread BorderRouter #0BB2._meshcop._udp
raspberrypi otbr-agent[850]: 00:00:00.204 [I] BbrLocal------: Add Domain Prefix: ::/0, NotFound
raspberrypi otbr-agent[850]: 00:00:00.204 [I] BbrLocal------: Add BBR Service: seqno (86), delay (5s), timeout (3600s), InvalidState
raspberrypi otbr-agent[850]: [INFO]-ADPROXY-: Started
raspberrypi otbr-agent[850]: [INFO]-DPROXY--: Started
raspberrypi otbr-agent[850]: [INFO]-APP-----: Thread Border Router started on AIL eth0.
raspberrypi otbr-agent[850]: 00:00:00.207 [I] Notifier------: StateChanged (0x42038210) [MLAddr NetData PanId NetName ExtPanId BbrState Nat64]
raspberrypi otbr-agent[850]: 00:00:00.208 [I] Bbr-----------: Start listening on port 61631
raspberrypi otbr-agent[850]: 00:00:00.208 [I] Bbr-----------: Backbone TMF subscribes ff32:40:fdde:ad00:beef:0:0:3: OK
raspberrypi otbr-agent[850]: 00:00:00.208 [I] BbrManager----: Start Backbone TMF agent: OK
raspberrypi otbr-agent[850]: 00:00:00.211 [I] Platform------: Execute command `ipset flush otbr-ingress-allow-dst-swap` = 0
raspberrypi otbr-agent[850]: 00:00:00.214 [I] Platform------: Execute command `ipset flush otbr-ingress-deny-src-swap` = 0
raspberrypi otbr-agent[850]: 00:00:00.217 [I] Platform------: Execute command `ipset add otbr-ingress-deny-src-swap fdde:ad00:beef:0::/64 -exist` = 0
raspberrypi otbr-agent[850]: 00:00:00.220 [I] Platform------: Execute command `ipset swap otbr-ingress-deny-src-swap otbr-ingress-deny-src` = 0
raspberrypi otbr-agent[850]: 00:00:00.223 [I] Platform------: Execute command `ipset swap otbr-ingress-allow-dst-swap otbr-ingress-allow-dst` = 0
raspberrypi otbr-agent[850]: 00:00:00.224 [I] P-Netif-------: NAT64 CIDR updated to 192.168.255.0/24.
raspberrypi otbr-agent[850]: 00:00:00.224 [I] P-Netif-------: Deleting route for NAT64
raspberrypi otbr-agent[850]: 00:00:00.224 [I] P-McastRtMgr--: Disable: OK
raspberrypi otbr-agent[850]: [INFO]-BA------: Publish meshcop service OpenThread BorderRouter #0BB2._meshcop._udp.local.
raspberrypi otbr-agent[850]: 00:00:00.224 [I] RouterTable---: Route table
raspberrypi otbr-agent[850]: 00:00:00.241 [I] P-Netif-------: Host netif is down
raspberrypi otbr-agent[850]: 00:00:00.242 [I] P-Netif-------: Succeeded to process request#1
raspberrypi otbr-agent[850]: 00:00:00.242 [W] P-Netif-------: Failed to process request#2: No such process
raspberrypi otbr-agent[850]: [INFO]-MDNS----: Successfully registered service OpenThread BorderRouter #0BB2._meshcop._udp
raspberrypi otbr-agent[850]: [INFO]-BA------: Result of publish meshcop service OpenThread BorderRouter #0BB2._meshcop._udp.local: OK
raspberrypi otbr-agent[850]: [INFO]-BA------: Result of publish meshcop service OpenThread BorderRouter #0BB2._meshcop._udp.local: OK
raspberrypi otbr-agent[850]: 00:00:34.317 [I] InfraIf-------: State changed: RUNNING -> NOT RUNNING
raspberrypi otbr-agent[850]: 00:00:34.336 [I] InfraIf-------: State changed: NOT RUNNING -> RUNNING
raspberrypi otbr-agent[850]: 00:01:19.316 [I] InfraIf-------: State changed: RUNNING -> NOT RUNNING
raspberrypi otbr-agent[850]: 00:01:19.349 [I] InfraIf-------: State changed: NOT RUNNING -> RUNNING
raspberrypi otbr-agent[850]: 00:01:21.843 [I] P-Daemon------: Session socket is ready
raspberrypi otbr-agent[850]: 00:01:21.844 [W] P-Daemon------: Daemon read: Connection reset by peer
raspberrypi otbr-agent[850]: 00:02:04.326 [I] InfraIf-------: State changed: RUNNING -> NOT RUNNING
raspberrypi otbr-agent[850]: 00:03:09.674 [I] InfraIf-------: State changed: NOT RUNNING -> RUNNING
raspberrypi otbr-agent[850]: 00:03:55.316 [I] InfraIf-------: State changed: RUNNING -> NOT RUNNING
raspberrypi otbr-agent[850]: 00:03:55.351 [I] InfraIf-------: State changed: NOT RUNNING -> RUNNING
raspberrypi otbr-agent[850]: 00:04:24.408 [I] InfraIf-------: State changed: RUNNING -> NOT RUNNING
raspberrypi otbr-agent[850]: 00:04:27.480 [I] InfraIf-------: State changed: NOT RUNNING -> RUNNING
raspberrypi otbr-agent[850]: 00:04:40.326 [I] InfraIf-------: State changed: RUNNING -> NOT RUNNING
raspberrypi otbr-agent[850]: 00:04:40.368 [I] InfraIf-------: State changed: NOT RUNNING -> RUNNING
raspberrypi otbr-agent[850]: 00:05:25.318 [I] InfraIf-------: State changed: RUNNING -> NOT RUNNING
raspberrypi otbr-agent[850]: 00:05:25.359 [I] InfraIf-------: State changed: NOT RUNNING -> RUNNING
raspberrypi otbr-agent[850]: 00:06:10.324 [I] InfraIf-------: State changed: RUNNING -> NOT RUNNING
raspberrypi systemd[1]: Starting otbr-agent.service - OpenThread Border Router Agent...
raspberrypi systemd[1]: Started otbr-agent.service - OpenThread Border Router Agent.
raspberrypi otbr-agent: [NOTE]-AGENT---: Backbone interface: eth0
raspberrypi otbr-agent[923]: [NOTE]-AGENT---: Running 0.3.0-thread-reference-20230710-250-g72ae1f15c8
raspberrypi otbr-agent[923]: [NOTE]-AGENT---: Thread version: 1.3.0
raspberrypi otbr-agent[923]: [NOTE]-AGENT---: Thread interface: wpan0
raspberrypi otbr-agent[923]: [NOTE]-AGENT---: Radio URL: spinel+hdlc+uart:///dev/ttyUSB1?uart-baudrate=115200
raspberrypi otbr-agent[923]: [NOTE]-AGENT---: Radio URL: trel://eth0
raspberrypi otbr-agent[923]: [NOTE]-ILS-----: Infra link selected: eth0
raspberrypi otbr-agent[923]: [INFO]-NCP-----: OpenThread log level changed to 4
raspberrypi otbr-agent[923]: 49d.17:04:01.894 [I] P-SpinelDrive-: co-processor reset: RESET_POWER_ON
raspberrypi otbr-agent[923]: 49d.17:04:01.894 [C] P-SpinelDrive-: Software reset co-processor successfully
raspberrypi otbr-agent[923]: 49d.17:04:02.003 [I] P-Netif-------: Sent request#1 to set addr_gen_mode to 1
raspberrypi otbr-agent[923]: 00:00:00.197 [I] ChildSupervsn-: Timeout: 0 -> 190
raspberrypi otbr-agent[923]: 00:00:00.198 [I] RoutingManager: Initializing - InfraIfIndex:2
raspberrypi otbr-agent[923]: 00:00:00.198 [I] InfraIf-------: Init infra netif 2
raspberrypi otbr-agent[923]: 00:00:00.198 [I] Settings------: Read BrUlaPrefix fdba:3610:a377::/48
raspberrypi otbr-agent[923]: 00:00:00.198 [N] RoutingManager: BR ULA prefix: fdba:3610:a377::/48 (loaded)
raspberrypi otbr-agent[923]: 00:00:00.198 [I] RoutingManager: Generated local OMR prefix: fdba:3610:a377:1::/64
raspberrypi otbr-agent[923]: 00:00:00.198 [I] RoutingManager: Generated local NAT64 prefix: fdba:3610:a377:2:0:0::/96
raspberrypi otbr-agent[923]: 00:00:00.199 [N] RoutingManager: Local on-link prefix: fdde:ad00:beef:cafe::/64
raspberrypi otbr-agent[923]: 00:00:00.199 [I] InfraIf-------: State changed: NOT RUNNING -> RUNNING
raspberrypi otbr-agent[923]: 00:00:00.199 [I] RoutingManager: Enabling
raspberrypi otbr-agent[923]: 00:00:00.199 [I] Nat64---------: IPv4 CIDR for NAT64: 192.168.255.0/24 (actual address pool: 192.168.255.1 - 192.168.255.254, 254 addresses)
raspberrypi otbr-agent[923]: 00:00:00.199 [I] Nat64---------: NAT64 translator is now Disabled
raspberrypi otbr-agent[923]: 00:00:00.201 [I] P-Resolver----: Got nameserver #0: 172.16.0.27
raspberrypi otbr-agent[923]: 00:00:00.201 [I] P-Resolver----: Got nameserver #1: 172.16.0.25
raspberrypi otbr-agent[923]: 00:00:00.201 [I] P-Resolver----: Got nameserver #2: 172.16.0.20
raspberrypi otbr-agent[923]: [INFO]-UTILS---: Set state callback: OK
raspberrypi otbr-agent[923]: 00:00:00.201 [I] Nat64---------: NAT64 translator is now NotRunning
raspberrypi otbr-agent[923]: [INFO]-BA------: Start Thread Border Agent
raspberrypi otbr-agent[923]: [INFO]-BA------: Publish meshcop service OpenThread BorderRouter #A542._meshcop._udp.local.
raspberrypi otbr-agent[923]: 00:00:00.202 [I] Settings------: Read BorderAgentId {id:aa7ceda9c581493bd47e4ec6cbe66ee1}
raspberrypi otbr-agent[923]: [INFO]-MDNS----: Registering service OpenThread BorderRouter #A542._meshcop._udp
raspberrypi otbr-agent[923]: 00:00:00.203 [I] BbrLocal------: Add Domain Prefix: ::/0, NotFound
raspberrypi otbr-agent[923]: 00:00:00.203 [I] BbrLocal------: Add BBR Service: seqno (13), delay (5s), timeout (3600s), InvalidState
raspberrypi otbr-agent[923]: [INFO]-ADPROXY-: Started
raspberrypi otbr-agent[923]: [INFO]-DPROXY--: Started
raspberrypi otbr-agent[923]: [INFO]-APP-----: Thread Border Router started on AIL eth0.
raspberrypi otbr-agent[923]: 00:00:00.207 [I] Notifier------: StateChanged (0x42038210) [MLAddr NetData PanId NetName ExtPanId BbrState Nat64]
raspberrypi otbr-agent[923]: 00:00:00.207 [I] Bbr-----------: Start listening on port 61631
raspberrypi otbr-agent[923]: 00:00:00.207 [I] Bbr-----------: Backbone TMF subscribes ff32:40:fdde:ad00:beef:0:0:3: OK
raspberrypi otbr-agent[923]: 00:00:00.207 [I] BbrManager----: Start Backbone TMF agent: OK
raspberrypi otbr-agent[923]: 00:00:00.210 [I] Platform------: Execute command `ipset flush otbr-ingress-allow-dst-swap` = 0
raspberrypi otbr-agent[923]: 00:00:00.213 [I] Platform------: Execute command `ipset flush otbr-ingress-deny-src-swap` = 0
raspberrypi otbr-agent[923]: 00:00:00.217 [I] Platform------: Execute command `ipset add otbr-ingress-deny-src-swap fdde:ad00:beef:0::/64 -exist` = 0
raspberrypi otbr-agent[923]: 00:00:00.220 [I] Platform------: Execute command `ipset swap otbr-ingress-deny-src-swap otbr-ingress-deny-src` = 0
raspberrypi otbr-agent[923]: 00:00:00.223 [I] Platform------: Execute command `ipset swap otbr-ingress-allow-dst-swap otbr-ingress-allow-dst` = 0
raspberrypi otbr-agent[923]: 00:00:00.223 [I] P-Netif-------: NAT64 CIDR updated to 192.168.255.0/24.
raspberrypi otbr-agent[923]: 00:00:00.223 [I] P-Netif-------: Deleting route for NAT64
raspberrypi otbr-agent[923]: 00:00:00.223 [I] P-McastRtMgr--: Disable: OK
raspberrypi otbr-agent[923]: [INFO]-BA------: Publish meshcop service OpenThread BorderRouter #A542._meshcop._udp.local.
raspberrypi otbr-agent[923]: 00:00:00.223 [I] RouterTable---: Route table
raspberrypi otbr-agent[923]: 00:00:00.240 [I] P-Netif-------: Host netif is down
raspberrypi otbr-agent[923]: 00:00:00.241 [I] P-Netif-------: Succeeded to process request#1
raspberrypi otbr-agent[923]: 00:00:00.241 [W] P-Netif-------: Failed to process request#2: No such process
raspberrypi otbr-agent[923]: [INFO]-MDNS----: Successfully registered service OpenThread BorderRouter #A542._meshcop._udp
raspberrypi otbr-agent[923]: [INFO]-BA------: Result of publish meshcop service OpenThread BorderRouter #A542._meshcop._udp.local: OK
raspberrypi otbr-agent[923]: [INFO]-BA------: Result of publish meshcop service OpenThread BorderRouter #A542._meshcop._udp.local: OK
raspberrypi otbr-agent[923]: 00:00:34.298 [I] InfraIf-------: State changed: RUNNING -> NOT RUNNING
raspberrypi otbr-agent[923]: 00:00:34.351 [I] InfraIf-------: State changed: NOT RUNNING -> RUNNING
raspberrypi otbr-agent[923]: 00:01:19.299 [I] InfraIf-------: State changed: RUNNING -> NOT RUNNING
raspberrypi otbr-agent[923]: 00:01:19.335 [I] InfraIf-------: State changed: NOT RUNNING -> RUNNING
raspberrypi otbr-agent[923]: 00:02:04.302 [I] InfraIf-------: State changed: RUNNING -> NOT RUNNING
raspberrypi otbr-agent[923]: 00:07:04.366 [I] InfraIf-------: State changed: NOT RUNNING -> RUNNING
raspberrypi otbr-agent[923]: 00:07:49.308 [I] InfraIf-------: State changed: RUNNING -> NOT RUNNING
raspberrypi otbr-agent[923]: 00:07:49.349 [I] InfraIf-------: State changed: NOT RUNNING -> RUNNING
raspberrypi otbr-agent[923]: 00:08:34.308 [I] InfraIf-------: State changed: RUNNING -> NOT RUNNING
raspberrypi otbr-agent[923]: 00:08:34.350 [I] InfraIf-------: State changed: NOT RUNNING -> RUNNING
raspberrypi otbr-agent[923]: 00:09:19.308 [I] InfraIf-------: State changed: RUNNING -> NOT RUNNING
raspberrypi otbr-agent[923]: 00:09:19.351 [I] InfraIf-------: State changed: NOT RUNNING -> RUNNING
raspberrypi otbr-agent[923]: 00:10:04.296 [I] InfraIf-------: State changed: RUNNING -> NOT RUNNING
raspberrypi otbr-agent[923]: 00:15:04.309 [I] InfraIf-------: State changed: NOT RUNNING -> RUNNING
raspberrypi otbr-agent[923]: 00:15:49.309 [I] InfraIf-------: State changed: RUNNING -> NOT RUNNING
raspberrypi otbr-agent[923]: 00:15:49.349 [I] InfraIf-------: State changed: NOT RUNNING -> RUNNING
raspberrypi otbr-agent[923]: 00:16:34.308 [I] InfraIf-------: State changed: RUNNING -> NOT RUNNING
raspberrypi otbr-agent[923]: 00:16:34.351 [I] InfraIf-------: State changed: NOT RUNNING -> RUNNING
raspberrypi otbr-agent[923]: 00:17:19.308 [I] InfraIf-------: State changed: RUNNING -> NOT RUNNING
raspberrypi otbr-agent[923]: 00:17:19.361 [I] InfraIf-------: State changed: NOT RUNNING -> RUNNING
raspberrypi otbr-agent[923]: 00:18:04.295 [I] InfraIf-------: State changed: RUNNING -> NOT RUNNING

can anyone help me with this ?

Thanks

superwhd · 2024-05-13T09:54:03Z

superwhd
May 13, 2024
Collaborator

raspberrypi otbr-agent[923]: 00:15:04.309 [I] InfraIf-------: State changed: NOT RUNNING -> RUNNING
raspberrypi otbr-agent[923]: 00:15:49.309 [I] InfraIf-------: State changed: RUNNING -> NOT RUNNING
raspberrypi otbr-agent[923]: 00:15:49.349 [I] InfraIf-------: State changed: NOT RUNNING -> RUNNING
raspberrypi otbr-agent[923]: 00:16:34.308 [I] InfraIf-------: State changed: RUNNING -> NOT RUNNING
raspberrypi otbr-agent[923]: 00:16:34.351 [I] InfraIf-------: State changed: NOT RUNNING -> RUNNING
raspberrypi otbr-agent[923]: 00:17:19.308 [I] InfraIf-------: State changed: RUNNING -> NOT RUNNING
raspberrypi otbr-agent[923]: 00:17:19.361 [I] InfraIf-------: State changed: NOT RUNNING -> RUNNING
raspberrypi otbr-agent[923]: 00:18:04.295 [I] InfraIf-------: State changed: RUNNING -> NOT RUNNING

This indicates the ethernet network interface's state of your Raspberry Pi has been continuously changing.

You may use ip monitor link to check what happened to it so that we can do further debugging.

0 replies

superwhd · 2024-05-13T09:56:34Z

superwhd
May 13, 2024
Collaborator

On the other hand, have you let your otbr-agent join/create a Thread network? I don't see relevant logs.

0 replies

testter2 · 2024-05-13T15:28:27Z

testter2
May 13, 2024
Author

ip monitor link command doesn't seem to show anything for what happened.

The previous behavior happens if i didn't join/create thread network in a little time (less than 3 minutes) which is strange for me !

I wants to run test cases from thread harness tool under br1 and br2 roles so I needed to add thread border router and start running test case quickly before otbr-agent stop running.

Although I have managed to start previous procedure quickly, I can see many test cases fails from test harness

1- Is the behavior of restarting otbr-agent normal in case of no activity done on the device ?

2- Are there any specific configurations that should be enabled in raspberry pi setup to run BR_1 and BR_2 roles for thread 1.2 test cases like DUA feature ( is it enough to use default build INFRA_IF_NAME=eth0 ./script/setup) ?

1 reply

jwhui Jun 5, 2024
Maintainer

Is the behavior of restarting otbr-agent normal in case of no activity done on the device ?

No, restarting is not normal. But transitioning between RUNNING and NOT RUNNING states does not indicate any restarting.

Are there any specific configurations that should be enabled in raspberry pi setup to run BR_1 and BR_2 roles for thread 1.2 test cases like DUA feature ( is it enough to use default build INFRA_IF_NAME=eth0 ./script/setup) ?

That should be sufficient.

The infra if state change is called here:

openthread/src/posix/platform/infra_if.cpp

Line 574 in d6eb56c

    
           SuccessOrDie(otPlatInfraIfStateChanged(gInstance, mInfraIfIndex, otSysInfraIfIsRunning()));

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

OpenThread

otbr-agent keep changing status continously #10224

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{editor}}'s edit

{{editor}}'s edit

Uh oh!

Replies: 3 comments 1 reply

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{editor}}'s edit

{{editor}}'s edit

Uh oh!

Uh oh!

{{title}}

Uh oh!

Select a reply

Uh oh!

OpenThread

otbr-agent keep changing status continously #10224

Uh oh!

Uh oh!

testter2 May 13, 2024

Replies: 3 comments · 1 reply

Uh oh!

superwhd May 13, 2024 Collaborator

Uh oh!

superwhd May 13, 2024 Collaborator

Uh oh!

Uh oh!

testter2 May 13, 2024 Author

Uh oh!

jwhui Jun 5, 2024 Maintainer

testter2
May 13, 2024

Replies: 3 comments 1 reply

superwhd
May 13, 2024
Collaborator

superwhd
May 13, 2024
Collaborator

testter2
May 13, 2024
Author

jwhui Jun 5, 2024
Maintainer