search

openthread / wpantund

Wireless Network Interface Daemon for Low-Power Wireless SoCs
Apache License 2.0
174 stars 110 forks source link

Unable to forward NCP logs #494

Closed superwhd closed 3 years ago

superwhd commented 3 years ago

Describe the bug I tried to set up an NCP on nrf52840 and use wpantund to forward logs to syslog. However, I don't see NCP logs in /var/log/syslog.

To Reproduce I was following the steps on https://github.com/openthread/ot-docs/blob/main/site/en/guides/build/logs.md#view-logs-for-an-ncp with some differences:

So here are my steps:

  1. In repository ot-nrf528xx, I changed the log option at src/nrf52840/openthread-core-nrf52840-config.h 
    #ifndef OPENTHREAD_CONFIG_LOG_OUTPUT
-#define OPENTHREAD_CONFIG_LOG_OUTPUT OPENTHREAD_CONFIG_LOG_OUTPUT_PLATFORM_DEFINED
+#define OPENTHREAD_CONFIG_LOG_OUTPUT OPENTHREAD_CONFIG_LOG_OUTPUT_APP
#endif
  2. I built NCP and flashed it to an nrf52840 board: 
    ./script/build nrf52840 UART_trans -DOT_JOINER=ON -DOT_FULL_LOGS=ON
  3. In /etc/wpantund.conf, I set Daemon:SyslogMask "all".
  4. I started wpantund as said on https://github.com/openthread/wpantund/blob/master/INSTALL.md#2-start-wpantund: 
    sudo /usr/local/sbin/wpantund -o NCPSocketName /dev/ttyACM0
  5. I ran tail -F /var/log/syslog.
  6. I used wpanctl to form a network. 
    sudo /usr/local/bin/wpanctl form abc
  7. In the terminal printing /var/log/syslog, I could see NCP messages forwarded by wpantund but I don't see NCP logs.

(I've manually removed some irrelevant rows/columns from the log file for privacy reasons.)

wpantundlog.txt

syslog.txt

abtink commented 3 years ago

wpantund NCP logging used to work fine NCP build with LOG_OUTPUT_APP. I don't recall any recent changes to logging in either wpantund code or OT NcpBase module.

abtink commented 3 years ago

I tested wpantund with NCP build on simulation platform (troanj config) and I do see logs working fine (the wpantund logs which start with NCP => are from NCP and are OpenThread logc).

May 14 10:27:40 abtink-desktop.mtv.corp.google.com wpantund[2616184]: NCP => [0001884823896][INFO]-MAC-----:     src:[fe80:0:0:0:e842:2326:b02f:c83b]:19788
May 14 10:27:40 abtink-desktop.mtv.corp.google.com wpantund[2616184]: NCP => [0001884823896][INFO]-MAC-----:     dst:[ff02:0:0:0:0:0:0:1]:19788
May 14 10:27:40 abtink-desktop.mtv.corp.google.com wpantund[2616184]: [->NCP] Dropping matched packet.
May 14 10:27:40 abtink-desktop.mtv.corp.google.com wpantund[2616184]: TunnelIPv6Interface: "ff33:40:fddc:3348:a063::1" was added to "wpan1"
May 14 10:27:40 abtink-desktop.mtv.corp.google.com wpantund[2616184]: TunnelIPv6Interface: "ff32:40:fddc:3348:a063::1" was added to "wpan1"
May 14 10:27:40 abtink-desktop.mtv.corp.google.com wpantund[2616184]: TunnelIPv6Interface: "ff33:40:fddc:3348:a063::1" was added to "wpan1"
May 14 10:27:40 abtink-desktop.mtv.corp.google.com wpantund[2616184]: TunnelIPv6Interface: "ff32:40:fddc:3348:a063::1" was added to "wpan1"
May 14 10:27:40 abtink-desktop.mtv.corp.google.com wpantund[2616184]: [->NCP] Dropping matched packet.
May 14 10:27:42 abtink-desktop.mtv.corp.google.com wpantund[2616184]: NCP => [0001884825697][INFO]-MLE-----: Send Advertisement (ff02:0:0:0:0:0:0:1)
May 14 10:27:42 abtink-desktop.mtv.corp.google.com wpantund[2616184]: NCP => [0001884825697][INFO]-MAC-----: Sent IPv6 UDP msg, len:90, chksum:175a, to:0xffff, sec:no, prio:net
May 14 10:27:42 abtink-desktop.mtv.corp.google.com wpantund[2616184]: NCP => [0001884825697][INFO]-MAC-----:     src:[fe80:0:0:0:e842:2326:b02f:c83b]:19788
May 14 10:27:42 abtink-desktop.mtv.corp.google.com wpantund[2616184]: NCP => [0001884825697][INFO]-MAC-----:     dst:[ff02:0:0:0:0:0:0:1]:19788
May 14 10:27:43 abtink-desktop.mtv.corp.google.com wpantund[2616184]: [->NCP] Dropping matched packet.
May 14 10:27:46 abtink-desktop.mtv.corp.google.com wpantund[2616184]: NCP => [0001884829603][INFO]-MLE-----: Send Advertisement (ff02:0:0:0:0:0:0:1)
May 14 10:27:46 abtink-desktop.mtv.corp.google.com wpantund[2616184]: NCP => [0001884829603][INFO]-MAC-----: Sent IPv6 UDP msg, len:90, chksum:f417, to:0xffff, sec:no, prio:net
May 14 10:27:46 abtink-desktop.mtv.corp.google.com wpantund[2616184]: NCP => [0001884829603][INFO]-MAC-----:     src:[fe80:0:0:0:e842:2326:b02f:c83b]:19788
May 14 10:27:46 abtink-desktop.mtv.corp.google.com wpantund[2616184]: NCP => [0001884829603][INFO]-MAC-----:     dst:[ff02:0:0:0:0:0:0:1]:19788
May 14 10:27:52 abtink-desktop.mtv.corp.google.com wpantund[2616184]: [->NCP] Dropping matched packet.
May 14 10:27:53 abtink-desktop.mtv.corp.google.com wpantund[2616184]: NCP => [0001884836961][INFO]-MLE-----: Send Advertisement (ff02:0:0:0:0:0:0:1)
May 14 10:27:53 abtink-desktop.mtv.corp.google.com wpantund[2616184]: NCP => [0001884836963][INFO]-MAC-----: Sent IPv6 UDP msg, len:90, chksum:0212, to:0xffff, sec:no, prio:net
May 14 10:27:53 abtink-desktop.mtv.corp.google.com wpantund[2616184]: NCP => [0001884836963][INFO]-MAC-----:     src:[fe80:0:0:0:e842:2326:b02f:c83b]:19788
May 14 10:27:53 abtink-desktop.mtv.corp.google.com wpantund[2616184]: NCP => [0001884836963][INFO]-MAC-----:     dst:[ff02:0:0:0:0:0:0:1]:19788
May 14 10:28:04 abtink-desktop.mtv.corp.google.com wpantund[2616184]: NCP => [0001884848084][INFO]-MLE-----: Send Advertisement (ff02:0:0:0:0:0:0:1)
May 14 10:28:04 abtink-desktop.mtv.corp.google.com wpantund[2616184]: NCP => [0001884848084][INFO]-MAC-----: Sent IPv6 UDP msg, len:90, chksum:3db8, to:0xffff, sec:no, prio:net
May 14 10:28:04 abtink-desktop.mtv.corp.google.com wpantund[2616184]: NCP => [0001884848084][INFO]-MAC-----:     src:[fe80:0:0:0:e842:2326:b02f:c83b]:19788
May 14 10:28:04 abtink-desktop.mtv.corp.google.com wpantund[2616184]: NCP => [0001884848084][INFO]-MAC-----:     dst:[ff02:0:0:0:0:0:0:1]:19788
abtink commented 3 years ago

@superwhd , here are the commands to help you build the simulation build and run and test it on your machine:

From openthread folder:

# Build NCP  with `troanj` config
$ ./tests/toranj/build.sh ncp

# run `wpantund` with NCP in simulation mode (make sure to replace  {PATH TO OPENTHREAD} based where ot repo is located on your machine)
$ sudo /usr/local/sbin/wpantund -o Config:NCP:SocketPath "{PATH TO OPENTHREAD}/openthread/examples/apps/ncp/ot-ncp-ftd 1" -o SyslogMask "all -debug" -o Config:NCP:DriverName spinel -o Config:TUN:InterfaceName wpan1 

# From another terminal you can start `wpanctl` and control the device
$ sudo /usr/local/bin/wpanctl -I wpan1
abtink commented 3 years ago

@superwhd , in the syslog that you posted, I see the following:

wpantund[364499]: SpinelNCPTaskForm.cpp:227: Check Failed (error 4)
wpantund[364499]: [->NCP] CMD_PROP_VALUE_SET(PROP_MAC_15_4_PANID) tid:11
wpantund[364499]:   ↳ 8B03365F4D
wpantund[364499]: [NCP->] CMD_PROP_VALUE_IS(PROP_MAC_15_4_PANID) tid:11
wpantund[364499]: [->NCP] CMD_PROP_VALUE_SET(PROP_NET_XPANID) tid:12
wpantund[364499]:   ↳ 8C0345C116CD3800F9019E
wpantund[364499]: [NCP->] CMD_PROP_VALUE_IS(UNKNOWN) tid:0
wpantund[364499]: [NCP->] CMD_PROP_VALUE_IS(UNKNOWN) tid:0
wpantund[364499]: [NCP->] CMD_PROP_VALUE_IS(PROP_MAC_15_4_PANID) tid:0
wpantund[364499]: [NCP->] CMD_PROP_VALUE_IS(PROP_NET_XPANID) tid:12
wpantund[364499]: [->NCP] CMD_PROP_VALUE_SET(PROP_NET_NETWORK_NAME) tid:13
wpantund[364499]:   ↳ 8D034461626300
wpantund[364499]: [NCP->] CMD_PROP_VALUE_IS(UNKNOWN) tid:0
wpantund[364499]: [NCP->] CMD_PROP_VALUE_IS(PROP_NET_XPANID) tid:0
wpantund[364499]: [NCP->] CMD_PROP_VALUE_IS(PROP_NET_NETWORK_NAME) tid:13
wpantund[364499]: [->NCP] CMD_PROP_VALUE_SET(PROP_NET_MASTER_KEY) tid:14
wpantund[364499]:   ↳ 8E0346FA01066B438F3F1106EF0EB666AA480F
wpantund[364499]: [NCP->] CMD_PROP_VALUE_IS(UNKNOWN) tid:0
wpantund[364499]: [NCP->] CMD_PROP_VALUE_IS(PROP_NET_NETWORK_NAME) tid:0
wpantund[364499]: [NCP->] CMD_PROP_VALUE_IS(PROP_NET_MASTER_KEY) tid:14

The [NCP->] CMD_PROP_VALUE_IS(UNKNOWN) tid:0 seem to be the logs being emitted from NCP.

What is the version wpantund you are using? Is it the latest? Looks to me that you may be using an older version of wpantund.

abtink commented 3 years ago

I think I see what may have happened, you are following guide which says use git checkout full/latest-release. This is very old tag. I don't know why this is added in the guide. We should use master.

@superwhd , can you help update the guide here to remove the git checkout full/latest-release (and replace it with master). Thanks.

superwhd commented 3 years ago

@abtink Thanks a lot for investigating the issue! I switched to master branch and installed wpantund. Now I can see logs from both wpantund CLI and /var/log/syslog. I'll send a PR to update wpantund's doc.