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


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.com.au
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

Join devel@lists.zephyrproject.org to automatically receive all group messages.