Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

execute "wpanctl get" - causes NCP stuck #3095

Closed
NickNamerr opened this issue Sep 24, 2018 · 8 comments
Closed

execute "wpanctl get" - causes NCP stuck #3095

NickNamerr opened this issue Sep 24, 2018 · 8 comments
Labels
platform: efr32 question

Comments

@NickNamerr
Copy link

After executes 4-5 times in the row command "wpanctl get" it stuck on showing parameter "Thread:NeighborTable". Here is some logs for better understanding the issue:

"wpanctl status" :
wpan0 => [
"NCP:State" => "associated"
"Daemon:Enabled" => true
"NCP:Version" => "OPENTHREAD/20170716-00904-g06bff963-dirty; EFR32; Sep 24 2018 15:34:21"
"Daemon:Version" => "0.08.00d (0.07.01-255-g47407b8; Sep 24 2018 14:49:37)"
"Config:NCP:DriverName" => "spinel"
"NCP:HardwareAddress" => [000B57FFFEA77ECE]
"NCP:Channel" => 11
"Network:NodeType" => "end-device"
"Network:Name" => "OpenThreadDemo"
"Network:XPANID" => 0x1111111122222222
"Network:PANID" => 0x1234
"IPv6:LinkLocalAddress" => "fe80::881e:c618:e800:ce3c"
"IPv6:MeshLocalAddress" => "fd11:1111:1122:0:5fbb:d716:6fa:fbe0"
"IPv6:MeshLocalPrefix" => "fd11:1111:1122::/64"
"com.nestlabs.internal:Network:AllowingJoin" => false

"wpanctl get"
Thread:Leader:Weight = 0x40
Thread:NeighborTable: (7)
get: error: Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken.

cat /var/log/syslog
Sep 24 15:43:43 raspberrypi wpantund[5527]: SpinelNCPTaskSendCommand.cpp:340: Requirement Failed ((mRetVal) == 0)
Sep 24 15:43:43 raspberrypi wpantund[5527]: SendCommand task encountered an error: 16 (0x00000010)
Sep 24 15:43:48 raspberrypi wpantund[5527]: SpinelNCPTask.cpp:86: Requirement Failed (IS_EVENT_FROM_NCP(event) && GetInstance(this)->mInboundHeader == mLastHeader)
Sep 24 15:43:48 raspberrypi wpantund[5527]: SpinelNCPTaskGetNetworkTopology.cpp:511: Requirement Failed ((ret) == 0)
Sep 24 15:43:48 raspberrypi wpantund[5527]: Getting child/neighbor table failed: 7
Sep 24 15:43:53 raspberrypi wpantund[5527]: SpinelNCPTask.cpp:86: Requirement Failed (IS_EVENT_FROM_NCP(event) && GetInstance(this)->mInboundHeader == mLastHeader)
Sep 24 15:43:53 raspberrypi wpantund[5527]: SpinelNCPTaskSendCommand.cpp:340: Requirement Failed ((mRetVal) == 0)
Sep 24 15:43:53 raspberrypi wpantund[5527]: SendCommand task encountered an error: 7 (0x00000007)
Sep 24 15:43:58 raspberrypi wpantund[5527]: SpinelNCPTask.cpp:86: Requirement Failed (IS_EVENT_FROM_NCP(event) && GetInstance(this)->mInboundHeader == mLastHeader)
Sep 24 15:43:58 raspberrypi wpantund[5527]: SpinelNCPTaskGetNetworkTopology.cpp:511: Requirement Failed ((ret) == 0)
Sep 24 15:43:58 raspberrypi wpantund[5527]: Getting child/neighbor table failed: 7
Sep 24 15:44:03 raspberrypi wpantund[5527]: SpinelNCPTask.cpp:86: Requirement Failed (IS_EVENT_FROM_NCP(event) && GetInstance(this)->mInboundHeader == mLastHeader)
Sep 24 15:44:03 raspberrypi wpantund[5527]: SpinelNCPTaskSendCommand.cpp:340: Requirement Failed ((mRetVal) == 0)
Sep 24 15:44:03 raspberrypi wpantund[5527]: SendCommand task encountered an error: 7 (0x00000007)
Sep 24 15:44:08 raspberrypi wpantund[5527]: SpinelNCPTask.cpp:86: Requirement Failed (IS_EVENT_FROM_NCP(event) && GetInstance(this)->mInboundHeader == mLastHeader)
Sep 24 15:44:08 raspberrypi wpantund[5527]: SpinelNCPTaskSendCommand.cpp:340: Requirement Failed ((mRetVal) == 0)
Sep 24 15:44:08 raspberrypi wpantund[5527]: SendCommand task encountered an error: 7 (0x00000007)
Sep 24 15:44:13 raspberrypi wpantund[5527]: SpinelNCPTask.cpp:86: Requirement Failed (IS_EVENT_FROM_NCP(event) && GetInstance(this)->mInboundHeader == mLastHeader)
Sep 24 15:44:13 raspberrypi wpantund[5527]: SpinelNCPTaskSendCommand.cpp:340: Requirement Failed ((mRetVal) == 0)
Sep 24 15:44:13 raspberrypi wpantund[5527]: SendCommand task encountered an error: 7 (0x00000007)
Sep 24 15:44:18 raspberrypi wpantund[5527]: SpinelNCPTask.cpp:86: Requirement Failed (IS_EVENT_FROM_NCP(event) && GetInstance(this)->mInboundHeader == mLastHeader)
Sep 24 15:44:18 raspberrypi wpantund[5527]: SpinelNCPTaskSendCommand.cpp:340: Requirement Failed ((mRetVal) == 0)
Sep 24 15:44:18 raspberrypi wpantund[5527]: SendCommand task encountered an error: 7 (0x00000007)
Sep 24 15:44:20 raspberrypi wpantund[5527]: SpinelNCPInstance-Protothreads.cpp:232: Requirement Failed (IS_EVENT_FROM_NCP(event) && GetInstance(this)->mInboundHeader == mLastHeader)
Sep 24 15:44:20 raspberrypi wpantund[5527]: NCP is misbehaving or unresponsive
Sep 24 15:44:20 raspberrypi wpantund[5527]: State change: "associated" -> "uninitialized"
Sep 24 15:44:20 raspberrypi wpantund[5527]: Taking interface(s) down. . .
Sep 24 15:44:21 raspberrypi ntpd[805]: Deleting interface #57 wpan0, 2001:db8:8568:b2b5:881e:c618:e800:ce3c#123, interface stats: received=0, sent=0, dropped=0, active_time=124 secs
Sep 24 15:44:21 raspberrypi ntpd[805]: Deleting interface #58 wpan0, fd11:1111:1122:0:5fbb:d716:6fa:fbe0#123, interface stats: received=0, sent=0, dropped=0, active_time=124 secs
Sep 24 15:44:21 raspberrypi ntpd[805]: Deleting interface #59 wpan0, fe80::881e:c618:e800:ce3c%7#123, interface stats: received=0, sent=0, dropped=0, active_time=124 secs
Sep 24 15:44:23 raspberrypi wpantund[5527]: SpinelNCPTask.cpp:86: Requirement Failed (IS_EVENT_FROM_NCP(event) && GetInstance(this)->mInboundHeader == mLastHeader)
Sep 24 15:44:23 raspberrypi wpantund[5527]: SpinelNCPTaskSendCommand.cpp:340: Requirement Failed ((mRetVal) == 0)
Sep 24 15:44:23 raspberrypi wpantund[5527]: SendCommand task encountered an error: 7 (0x00000007)
Sep 24 15:44:25 raspberrypi wpantund[5527]: SpinelNCPInstance-Protothreads.cpp:414: Requirement Failed (IS_EVENT_FROM_NCP(event) && GetInstance(this)->mInboundHeader == mLastHeader)
Sep 24 15:44:26 raspberrypi wpantund[5527]: Resetting and trying again... (retry 1)
@NickNamerr
Copy link
Author

I have 27 REEDs in the network. After reset, when NeighborTable did not filled yet, it executes command without any issues. Maximum amount of devices in NeighborTable i have seen is 15. I hope it helps.

@jwhui
Copy link
Member

jwhui commented Sep 25, 2018

Can you see if the NCP is stuck in a loop? For example, by using JTAG and grabbing a stack trace?

@NickNamerr
Copy link
Author

I shall try to debug it.

@abtink
Copy link
Member

abtink commented Oct 3, 2018

What is the value of OPENTHREAD_CONFIG_NCP_TX_BUFFER_SIZE in your configuration. Can you increase it?

I have a theory of what's happning. If the the spinel encoded neighbor table frame does not fit in the spinel NCP buffer, the NCP encoder will keep trying to prepare the response and hits the no buffer error and tries again, causing it to remain stuck in a loop.

@NickNamerr
Copy link
Author

#ifndef OPENTHREAD_CONFIG_NCP_TX_BUFFER_SIZE
#define OPENTHREAD_CONFIG_NCP_TX_BUFFER_SIZE 512
#endif

@abtink
Copy link
Member

abtink commented Oct 5, 2018

That's very likely to be the cause. Can you increase it to at least 1K (preferably 2K)?

@NickNamerr
Copy link
Author

I shall try it. Thanks.

@jwhui
Copy link
Member

jwhui commented Nov 6, 2018

@NickNamerr, any update on this issue?

@jwhui jwhui closed this as completed Dec 5, 2018
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
platform: efr32 question
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@NickNamerr @jwhui @abtink