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.