bt_le_scan_start Fails with Error -5 after 128 scan start/stop cycles


Declan Traill <declan.traill@...>
 

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

SETEC on Facebook     SETEC on Instagram     SETEC on LinkedIn     SETEC on YouTube
SETEC Celebrating 50 Years



Email from setec.com.au does not necessarily represent the official policy of SETEC Pty Ltd.
See Email Disclaimer 20060629 for details.



Johan Hedberg
 

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 (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


Johan Hedberg
 

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.


Declan Traill <declan.traill@...>
 

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.


Chettimada, Vinayak Kariappa
 

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.



Chettimada, Vinayak Kariappa
 

Hi Johan,

It is nothing to do with controller privacy, its just that advertiser is active and by BT Spec. 

If the Host issues this command when scanning or legacy advertising is enabled, the Controller shall return the error code Command Disallowed (0x0C).

Can we do something about this in the host, when address is regenerated?

- Vinayak

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.








Declan Traill <declan.traill@...>
 

Hi,

 

    Sorry for the delay in replying (working on another project).

 

I can confirm the problem still occurs with Controller Privacy turned off, as you suggested would be the case.

 

It sounds like you are on top of the problem – I hope to hear of a possible solution soon…

 

 

Best Regards,

Declan

 

From: Chettimada, Vinayak Kariappa <vinayak.kariappa.chettimada@...>
Sent: Thursday, 23 August 2018 3:21 AM
To: Johan Hedberg <johan.hedberg@...>
Cc: Declan Traill <declan.traill@...>; devel@...
Subject: Re: [Zephyr-devel] bt_le_scan_start Fails with Error -5 after 128 scan start/stop cycles

 

Hi Johan,

 

It is nothing to do with controller privacy, its just that advertiser is active and by BT Spec. 

 

If the Host issues this command when scanning or legacy advertising is enabled, the Controller shall return the error code Command Disallowed (0x0C).

 

Can we do something about this in the host, when address is regenerated?

 

- Vinayak



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.






 



Email from setec.com.au does not necessarily represent the official policy of SETEC Pty Ltd.
See Email Disclaimer 20060629 for details.



Declan Traill <declan.traill@...>
 

Hi Johan/Vinayak and others,

 

    Have you had a chance to look at/reproduce this bug yet?  

Is there a potential solution?

 

 

Thanks for your attention…

 

Regards,

Declan Traill

 

From: Chettimada, Vinayak Kariappa <vinayak.kariappa.chettimada@...>
Sent: Thursday, 23 August 2018 3:21 AM
To: Johan Hedberg <johan.hedberg@...>
Cc: Declan Traill <declan.traill@...>; devel@...
Subject: Re: [Zephyr-devel] bt_le_scan_start Fails with Error -5 after 128 scan start/stop cycles

 

Hi Johan,

 

It is nothing to do with controller privacy, its just that advertiser is active and by BT Spec. 

 

If the Host issues this command when scanning or legacy advertising is enabled, the Controller shall return the error code Command Disallowed (0x0C).

 

Can we do something about this in the host, when address is regenerated?

 

- Vinayak



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.






 



Email from setec.com.au does not necessarily represent the official policy of SETEC Pty Ltd.
See Email Disclaimer 20060629 for details.