On 22 Aug 2018, at 14:21, Chettimada, Vinayak Kariappa <vinayak.kariappa.chettimada@...> wrote:

 

Hi,

Could you please turn off the controller privacy feature and check if you still face issues?
CONFIG_BT_CTLR_PRIVACY=n

This is to narrow down the locality of the problem, just suspecting some race condition with the running advertiser in concurrency,

Regards,
Vinayak

On 22 Aug 2018, at 11:31, Johan Hedberg <johan.hedberg@...> wrote:

Thanks Declan. The logs do indeed show the HCI error:

[bt] [DBG] bt_hci_cmd_send_sync: (0x20004240) opcode 0x2005 status 0x0c

0x0c is the same as "Command Disallowed", i.e. the controller considers
itself to be in a state where it cannot accept a command. OpCode 0x2005
in turn is HCI_Set_Random_Address, so it's this command that the
controller is refusing to accept.

Johan

On Wed, Aug 22, 2018, Declan Traill wrote:

Hi Johan,

 I have attached a new log. This time it fails after 121 cycles (maybe the 128 was a coincidence and the extra debug has changed the timing?).

 Any ideas what is happening?

Regards,
Declan

-----Original Message-----
From: Johan Hedberg <johan.hedberg@...> 
Sent: Wednesday, 22 August 2018 2:34 PM
To: Declan Traill <declan.traill@...>
Cc: devel@...
Subject: Re: [Zephyr-devel] bt_le_scan_start Fails with Error -5 after 128 scan start/stop cycles

Hi Declan,

Could you enable the following options and try to take another log:

CONFIG_BT_DEBUG_LOG=y
CONFIG_BT_DEBUG_HCI_CORE=y

If I remember right, EIO is just a generic mapping to any HCI error coming from the controller. Enabling the above options should hopefully reveal what that error is. If it still doesn't help we'll need to enable controller logs or take a full HCI log (using CONFIG_BT_DEBUG_MONITOR).

Johan

On Wed, Aug 22, 2018, Declan Traill wrote:

Hi,

I have a basic project that scans for 5 seconds, then stops for one second - then repeats forever.
After exactly 128 cycles, the 129th scan start (and all after that) fails with error code -5 (I think this is POSIX: #define EIO 5 /* I/O error */).

Given the number of time it works (128) it seems like a resource or memory may have run out?

Here is the debug log (attached) showing the problem: Any ideas what might be wrong & how to fix it?

Thanks...

P.S. Also at the end of this file is a fragment of debug I saw a couple of times earlier today during testing - showing a kernel error that occurred. It may be related or unrelated to the other problem??

Regards,

Declan Traill
Embedded Firmware Engineer
declan.traill@...
SETEC Pty Ltd
19 Henderson Road, Knoxfield 3180, Victoria, Australia
Phone: +61 3 9763 0962
Fax: +61 3 9763 8789
Direct: +61 3 9213 8458
setec.com.au | teambmpro.com

--------
Email from setec.com.au does not necessarily represent the official 
policy of SETEC Pty Ltd.
See http://www.setec.com.au/emaildisclaimer20060629.html for details.

***** Booting Zephyr OS v1.12.0-1096-g55f6620c3 ***** Zephyr Shell, 
Zephyr version: 1.12.99 Type 'help' for a list of available commands
shell> [bt] [INF] hci_vs_init: HW Platform: Nordic Semiconductor 
shell> (0x0002)
[bt] [INF] hci_vs_init: HW Variant: nRF52x (0x0002) [bt] [INF] 
hci_vs_init: Firmware: Standard Bluetooth controller (0x00) Version 
1.12 Build 99 [bt] [WRN] bt_pub_key_gen: ECC HCI commands not 
available Bluetooth initialized [bt] [INF] bt_dev_show_info: Identity: 
c0:7e:4c:e6:8b:f3 (random) [bt] [INF] bt_dev_show_info: HCI: version 
5.0 (0x09) revision 0x0000, manufacturer 0x05f1 [bt] [INF] 
bt_dev_show_info: LMP: version 5.0 (0x09) subver 0xffff Advertising 
successfully started

Scanning Started 1

Device found in close proximity: 7a:19:47:6d:5e:b8 (random) (RSSI -70) 
Device found - 7a:19:47:6d:5e:b8 (random) - NOT bonded Scanning 
Stopped Scanning Started 2 Scanning Stopped Scanning Started 3 
Scanning Stopped Scanning Started 4
Connected: 59:75:02:8a:8f:b6 (random) (NOT Bonded) Scanning Stopped 
Scanning Started 5 Scanning Stopped Scanning Started 6 Scanning 
Stopped Scanning Started 7 Scanning Stopped Scanning Started 8 
Scanning Stopped Scanning Started 9 Scanning Stopped Scanning Started 
10 Scanning Stopped Scanning Started 11 Device found in close 
proximity: 5d:29:c2:26:6c:4c (random) (RSSI -57) Device found - 
5d:29:c2:26:6c:4c (random) - NOT bonded Scanning Stopped Scanning 
Started 12 Device found in close proximity: 5d:29:c2:26:6c:4c (random) 
(RSSI -61) Device found - 5d:29:c2:26:6c:4c (random) - NOT bonded 
Scanning Stopped Scanning Started 13 Device found in close proximity: 
5d:29:c2:26:6c:4c (random) (RSSI -48) Device found - 5d:29:c2:26:6c:4c 
(random) - NOT bonded Scanning Stopped Scanning Started 14 Device 
found in close proximity: 5d:29:c2:26:6c:4c (random) (RSSI -57) Device 
found - 5d:29:c2:26:6c:4c (random) - NOT bonded Scanning Stopped 
Scanning Started 15 Device found in close proximity: 5d:29:c2:26:6c:4c 
(random) (RSSI -57) Device found - 5d:29:c2:26:6c:4c (random) - NOT 
bonded Scanning Stopped Scanning Started 16 Device found in close 
proximity: 5d:29:c2:26:6c:4c (random) (RSSI -55) Device found - 
5d:29:c2:26:6c:4c (random) - NOT bonded Scanning Stopped Scanning 
Started 17 Device found in close proximity: 5d:29:c2:26:6c:4c (random) 
(RSSI -50) Device found - 5d:29:c2:26:6c:4c (random) - NOT bonded 
Scanning Stopped Scanning Started 18 Device found in close proximity: 
5d:29:c2:26:6c:4c (random) (RSSI -51) Device found - 5d:29:c2:26:6c:4c 
(random) - NOT bonded Scanning Stopped Scanning Started 19 Device 
found in close proximity: 5d:29:c2:26:6c:4c (random) (RSSI -57) Device 
found - 5d:29:c2:26:6c:4c (random) - NOT bonded Scanning Stopped 
Scanning Started 20 Device found in close proximity: 6f:d9:fb:62:fc:95 
(random) (RSSI -51) Device found - 6f:d9:fb:62:fc:95 (random) - NOT 
bonded Scanning Stopped Scanning Started 21 Device found in close 
proximity: 6f:d9:fb:62:fc:95 (random) (RSSI -58) Device found - 
6f:d9:fb:62:fc:95 (random) - NOT bonded Scanning Stopped Scanning 
Started 22 Device found in close proximity: 6f:d9:fb:62:fc:95 (random) 
(RSSI -53) Device found - 6f:d9:fb:62:fc:95 (random) - NOT bonded 
Scanning Stopped Scanning Started 23 Device found in close proximity: 
6f:d9:fb:62:fc:95 (random) (RSSI -52) Device found - 6f:d9:fb:62:fc:95 
(random) - NOT bonded Scanning Stopped Scanning Started 24 Scanning 
Stopped Scanning Started 25 Scanning Stopped Scanning Started 26 
Scanning Stopped Scanning Started 27 Scanning Stopped Scanning Started 
28 Scanning Stopped Scanning Started 29 Scanning Stopped Scanning 
Started 30 Scanning Stopped Scanning Started 31 Scanning Stopped 
Scanning Started 32 Scanning Stopped Scanning Started 33 Scanning 
Stopped Scanning Started 34 Scanning Stopped Scanning Started 35 
Scanning Stopped Scanning Started 36 Scanning Stopped Scanning Started 
37 Scanning Stopped Scanning Started 38 Scanning Stopped Scanning 
Started 39 Device found in close proximity: 72:bd:c4:8a:51:23 (random) 
(RSSI -70) Device found - 72:bd:c4:8a:51:23 (random) - NOT bonded 
Scanning Stopped Scanning Started 40 Scanning Stopped Scanning Started 
41 Device found in close proximity: 72:bd:c4:8a:51:23 (random) (RSSI 
-70) Device found - 72:bd:c4:8a:51:23 (random) - NOT bonded Scanning 
Stopped Scanning Started 42 Scanning Stopped Scanning Started 43 
Scanning Stopped Scanning Started 44 Scanning Stopped Scanning Started 
45 Scanning Stopped Scanning Started 46 Scanning Stopped Scanning 
Started 47 Scanning Stopped Scanning Started 48 Scanning Stopped 
Scanning Started 49 Scanning Stopped Scanning Started 50 Scanning 
Stopped Scanning Started 51 Scanning Stopped Scanning Started 52 
Scanning Stopped Scanning Started 53 Scanning Stopped Scanning Started 
54 Scanning Stopped Scanning Started 55 Device found in close 
proximity: 72:bd:c4:8a:51:23 (random) (RSSI -69) Device found - 
72:bd:c4:8a:51:23 (random) - NOT bonded Scanning Stopped Scanning 
Started 56 Scanning Stopped Scanning Started 57 Scanning Stopped 
Scanning Started 58 Scanning Stopped Scanning Started 59 Scanning 
Stopped Scanning Started 60 Scanning Stopped Scanning Started 61 
Scanning Stopped Scanning Started 62 Scanning Stopped Scanning Started 
63 Scanning Stopped Scanning Started 64 Scanning Stopped Scanning 
Started 65 Scanning Stopped Scanning Started 66 Scanning Stopped 
Scanning Started 67 Scanning Stopped Scanning Started 68 Scanning 
Stopped Scanning Started 69 Scanning Stopped Scanning Started 70 
Scanning Stopped Scanning Started 71 Scanning Stopped Scanning Started 
72 Scanning Stopped Scanning Started 73 Scanning Stopped Scanning 
Started 74 Scanning Stopped Scanning Started 75 Scanning Stopped 
Scanning Started 76 Scanning Stopped Scanning Started 77 Scanning 
Stopped Scanning Started 78 Scanning Stopped Scanning Started 79 
Scanning Stopped Scanning Started 80 Scanning Stopped Scanning Started 
81 Scanning Stopped Scanning Started 82 Scanning Stopped Scanning 
Started 83 Scanning Stopped Scanning Started 84 Scanning Stopped 
Scanning Started 85 Device found in close proximity: 7a:19:47:6d:5e:b8 
(random) (RSSI -69) Device found - 7a:19:47:6d:5e:b8 (random) - NOT 
bonded Scanning Stopped Scanning Started 86 Device found in close 
proximity: 7a:19:47:6d:5e:b8 (random) (RSSI -69) Device found - 
7a:19:47:6d:5e:b8 (random) - NOT bonded Scanning Stopped Scanning 
Started 87 Scanning Stopped Scanning Started 88 Scanning Stopped 
Scanning Started 89 Scanning Stopped Scanning Started 90 Scanning 
Stopped Scanning Started 91 Scanning Stopped Scanning Started 92 
Scanning Stopped Scanning Started 93 Scanning Stopped Scanning Started 
94 Scanning Stopped Scanning Started 95 Scanning Stopped Scanning 
Started 96 Scanning Stopped Scanning Started 97 Scanning Stopped 
Scanning Started 98 Scanning Stopped Scanning Started 99 Scanning 
Stopped Scanning Started 100 Scanning Stopped Scanning Started 101 
Scanning Stopped Scanning Started 102 Scanning Stopped Scanning 
Started 103 Scanning Stopped Scanning Started 104 Scanning Stopped 
Scanning Started 105 Scanning Stopped Scanning Started 106 Scanning 
Stopped Scanning Started 107 Device found in close proximity: 
88:6b:0f:07:08:fc (public) (RSSI -70) Device found - 88:6b:0f:07:08:fc 
(public) - NOT bonded Scanning Stopped Scanning Started 108 Device 
found in close proximity: 88:6b:0f:07:08:fc (public) (RSSI -70) Device 
found - 88:6b:0f:07:08:fc (public) - NOT bonded Scanning Stopped 
Scanning Started 109 Scanning Stopped Scanning Started 110 Scanning 
Stopped Scanning Started 111 Scanning Stopped Scanning Started 112 
Device found in close proximity: 88:6b:0f:07:08:fc (public) (RSSI -70) 
Device found - 88:6b:0f:07:08:fc (public) - NOT bonded Scanning 
Stopped Scanning Started 113 Device found in close proximity: 
88:6b:0f:07:08:fc (public) (RSSI -70) Device found - 88:6b:0f:07:08:fc 
(public) - NOT bonded Scanning Stopped Scanning Started 114 Device 
found in close proximity: 88:6b:0f:07:08:fc (public) (RSSI -70) Device 
found - 88:6b:0f:07:08:fc (public) - NOT bonded Scanning Stopped 
Scanning Started 115 Device found in close proximity: 
88:6b:0f:07:08:fc (public) (RSSI -70) Device found - 88:6b:0f:07:08:fc 
(public) - NOT bonded Scanning Stopped Scanning Started 116 Scanning 
Stopped Scanning Started 117 Device found in close proximity: 
88:6b:0f:07:08:fc (public) (RSSI -70) Device found - 88:6b:0f:07:08:fc 
(public) - NOT bonded Scanning Stopped Scanning Started 118 Scanning 
Stopped Scanning Started 119 Scanning Stopped Scanning Started 120 
Scanning Stopped Scanning Started 121 Device found in close proximity: 
88:6b:0f:07:08:fc (public) (RSSI -70) Device found - 88:6b:0f:07:08:fc 
(public) - NOT bonded Scanning Stopped Scanning Started 122 Scanning 
Stopped Scanning Started 123 Scanning Stopped Scanning Started 124 
Scanning Stopped Scanning Started 125 Scanning Stopped Scanning 
Started 126 Scanning Stopped Scanning Started 127 Scanning Stopped 
Scanning Started 128 Device found in close proximity: 
88:6b:0f:07:08:fc (public) (RSSI -70) Device found - 88:6b:0f:07:08:fc 
(public) - NOT bonded Scanning Stopped Scanning failed to start 129 
(err -5) Scanning Stopped Scanning failed to start 130 (err -5) 
Scanning Stopped Scanning failed to start 131 (err -5) Scanning 
Stopped Scanning failed to start 132 (err -5) Scanning Stopped 
Scanning failed to start 133 (err -5) Scanning Stopped Scanning failed 
to start 134 (err -5)




Scanning failed to start (err -5)
Scanning failed to start (err -5)
[bt] [ERR] rpa_adv_refresh: assert: 'idx < ((unsigned long) (((int) 
sizeof(char[1 - 2 * !(!__builtin_types_compatible_p(__typeof__(rl), 
__typeof__(&(rl)[0])))]) - 1) + (sizeof(rl) / sizeof((rl)[0]))))' 
failed
***** Kernel OOPS! *****
Current thread ID = 0x20004a10
Faulting instruction address = 0x2a134 Fatal fault in thread 
0x20004a10! Aborting.
Scanning failed to start (err -5)
Scanning failed to start (err -5)
S

--------
Email from setec.com.au does not necessarily represent the official
policy of SETEC Pty Ltd.
See http://www.setec.com.au/emaildisclaimer20060629.html for details.