Photon 2: WiFi impacts BLE scan

gusgonnet · March 7, 2024, 12:03am

Hello,

I'm experiencing something weird, tried this on three photon 2s, same results.
Code behaves ok on Boron and Argon.

Observation:

When WiFi is on, a scan returns 0 (zero) results.

With or without external antenna.

If I set SYSTEM_MODE to MANUAL, scan returns some results.

If I set SYSTEM_MODE to AUTOMATIC, while the device is trying to connect to WiFi, there are some scan results, but they go down to zero when the cloud connection is finally established.

DeviceOS 5.7.0.

Way to reproduce:

Start with a BLE example (device nearby central) and reduced it to a minimum:

#include "Particle.h"
// SYSTEM_MODE(MANUAL);
SYSTEM_THREAD(ENABLED);

SerialLogHandler logHandler(LOG_LEVEL_INFO);
const size_t SCAN_RESULT_MAX = 30;
BleScanResult scanResults[SCAN_RESULT_MAX];

void setup()
{
  BLE.on();
}

void loop()
{
  int count = BLE.scan(scanResults, SCAN_RESULT_MAX);
  Log.info("scan count=%d", count);
}

Logs

Logs on an Argon (WiFi on, no BT antenna), the scan sees plenty of devices:

0000134817 [app] INFO: scan count=16
0000139771 [app] INFO: scan count=17
0000159585 [app] INFO: scan count=19
0000164539 [app] INFO: scan count=15
0000169492 [app] INFO: scan count=17
0000174446 [app] INFO: scan count=16

Logs on a Photon 2, SYSTEM_MODE(MANUAL):

WiFi off
0000001899 [system.nm] INFO: State changed: NONE -> DISABLED
0000001931 [comm] INFO: channel inited
0000001944 [hal] INFO: rltk_wlan_set_netif_info: 0, 94:94:4a:00:1e:24
0000002153 [hal] INFO: WiFi on
0000007495 [app] INFO: scan count=24
0000012510 [app] INFO: scan count=26
0000017526 [app] INFO: scan count=22

INFO Logs on a Photon 2, SYSTEM_MODE(AUTOMATIC):

0000012661 [system] INFO: Discarding session data
0000012760 [app] INFO: scan count=19
(...)
0000015783 [system] INFO: Cloud connected
0000016225 [comm.protocol] INFO: Received DESCRIBE request; flags: 0x04
0000017774 [app] INFO: scan count=0
0000022789 [app] INFO: scan count=0
0000027804 [app] INFO: scan count=0
0000032821 [app] INFO: scan count=0

full TRACE Logs on a Photon 2, SYSTEM_MODE(AUTOMATIC):

Serial monitor opened successfully:
0000001747 [hal.ble] TRACE: Going to stop the stack...
0000001956 [net.lwip_rltk] INFO: promisc_deinit TODO
0000001961 [hal] INFO: WiFi off
0000001965 [system.nm] INFO: State changed: NONE -> DISABLED
0000001970 [system.nm] TRACE: Interface 4 power state: DOWN
0000002002 [comm] INFO: channel inited
0000002107 [system.nm] INFO: State changed: DISABLED -> IFACE_DOWN
0000002114 [system.nm] INFO: State changed: IFACE_DOWN -> IFACE_REQUEST_UP
0000002122 [net.ifapi] INFO: Netif wl3 state UP
0000002126 [net.rltkncp] TRACE: NCP event 3
0000002128 [net.rltkncp] TRACE: NCP power state changed: IF_POWER_STATE_POWERING_UP
0000002129 [system.nm] INFO: State changed: IFACE_REQUEST_UP -> IFACE_UP
0000002134 [system.nm] TRACE: Interface 4 power state changed: POWERING_UP
0000002148 [hal] INFO: rltk_wlan_set_netif_info: 0, 94:94:4a:00:1e:24
0000002351 [hal] INFO: WiFi on
0000002352 [net.rltkncp] TRACE: NCP event 3
0000002353 [net.rltkncp] TRACE: NCP power state changed: IF_POWER_STATE_UP
0000002354 [system.nm] TRACE: Interface 4 power state changed: UP
0000002356 [ncp.rltk.client] INFO: rltkOff
0000002561 [net.lwip_rltk] INFO: promisc_deinit TODO
0000002562 [hal] INFO: WiFi off
0000002563 [ncp.rltk.client] INFO: rltkOff done
0000002564 [net.rltkncp] TRACE: NCP event 3
0000002564 [net.rltkncp] TRACE: NCP power state changed: IF_POWER_STATE_DOWN
0000002566 [system.nm] TRACE: Interface 4 power state changed: DOWN
0000002578 [hal] INFO: rltk_wlan_set_netif_info: 0, 94:94:4a:00:1e:24
0000002783 [hal] INFO: WiFi on
0000002785 [net.rltkncp] TRACE: NCP event 3
0000002786 [net.rltkncp] TRACE: NCP power state changed: IF_POWER_STATE_UP
0000002787 [system.nm] TRACE: Interface 4 power state changed: UP
0000002788 [ncp.rltk.client] TRACE: NCP state changed: 1
0000002791 [net.rltkncp] TRACE: NCP event 1
0000002794 [ncp.rltk.client] INFO: Try to connect to ssid: canada5
0000002795 [net.lwip_rltk] INFO: is_promisc_enabled
0000002796 [net.lwip_rltk] INFO: get_eap_phase
0000007284 [net.lwip_rltk] INFO: get_eap_phase
0000007289 [hal] INFO: WiFi is already on
0000007401 [net.lwip_rltk] INFO: get_eap_phase
0000007461 [ncp.rltk.client] TRACE: NCP connection state changed: 2
0000007463 [net.rltkncp] TRACE: NCP event 2
0000007464 [net.rltkncp] TRACE: State changed event: 2
0000007465 [net.ifapi] INFO: Netif wl3 link UP, profile=canada5
0000007473 [system.nm] INFO: State changed: IFACE_UP -> IFACE_LINK_UP
0000009353 [hal] INFO: DNS server list changed
0000009357 [hal] INFO: DNS server list changed
0000009362 [net.ifapi] TRACE: Netif wl3 ipv4 configuration changed
0000009369 [system.nm] INFO: State changed: IFACE_LINK_UP -> IP_CONFIGURED
0000009375 [system] INFO: Cloud: connecting
0000009380 [system] INFO: Read Server Address = type:1,domain:$id.udp.particle.io
0000009386 [system] WARN: Failed to load session data from persistent storage
0000009392 [system] INFO: Discarding session data
0000009416 [system] TRACE: Resolving 0a10aced202194944a001e24.v5.udp.particle.io#5684
0000009488 [system] TRACE: Address type: 3
0000009492 [system] TRACE: Cloud socket=0, family=2, type=2, protocol=17
0000009497 [system] INFO: Cloud socket=0, connecting to 3.222.143.118#5684
0000009504 [system] TRACE: 0 Bound cloud socket to lwip interface 
0000009509 [system] TRACE: Cloud socket=0, connected to 3.222.143.118#5684
0000009514 [system] TRACE: Updating cloud keepalive for AF_INET: 25000 -> 25000
0000009520 [system] TRACE: Applying new keepalive interval now
0000009525 [system] INFO: Cloud socket connected
0000009529 [system] INFO: Starting handshake: presense_announce=0
0000009535 [comm.protocol.handshake] INFO: Establish secure connection
0000009541 [comm.dtls] INFO: (CMPL,RENEG,NO_SESS,ERR) restoreStatus=2
0000010895 [comm.protocol.handshake] INFO: Sending HELLO message
0000010901 [comm.coap] TRACE: Sending CoAP message
0000010904 [comm.coap] TRACE: CON POST /h size=39 token= id=1
0000010936 [comm.coap] TRACE: Received CoAP message
0000010940 [comm.coap] TRACE: ACK 0.00  size=4 token= id=1
0000010944 [comm.protocol.handshake] INFO: Handshake completed
0000010949 [comm.protocol.handshake] TRACE: Updating cached session parameters
0000010955 [comm.dtls] INFO: session cmd (CLS,DIS,MOV,LOD,SAV): 4
0000010960 [comm.dtls] INFO: session cmd (CLS,DIS,MOV,LOD,SAV): 3
0000011360 [comm.coap] TRACE: Sending CoAP message
0000011365 [comm.coap] TRACE: CON POST /d?\x01 size=198 token=cc id=2
0000011373 [system] INFO: Send spark/device/last_reset event
0000011379 [comm.coap] TRACE: Sending CoAP message
0000011383 [comm.coap] TRACE: CON POST /E/spark/device/last_reset size=42 token= id=3
0000011391 [comm.coap] TRACE: Sending CoAP message
0000011395 [comm.coap] TRACE: CON POST /E/particle/device/updates/enabled size=44 token= id=4
0000011404 [comm.coap] TRACE: Sending CoAP message
0000011408 [comm.coap] TRACE: CON POST /E/particle/device/updates/forced size=44 token= id=5
0000011418 [comm] INFO: Sending TIME request
0000011421 [comm.coap] TRACE: Sending CoAP message
0000011425 [comm.coap] TRACE: CON GET /t size=7 token=cd id=6
0000011431 [system] INFO: Sending application DESCRIBE
0000011435 [comm.coap] TRACE: Sending CoAP message
0000011440 [comm.coap] TRACE: CON POST /d?\x02 size=25 token=ce id=7
0000011447 [system] INFO: Sending subscriptions
0000011451 [comm.protocol] INFO: Sending subscriptions
0000011455 [comm.coap] TRACE: Sending CoAP message
0000011459 [comm.coap] TRACE: CON GET /e/particle?u size=17 token= id=8
0000011466 [comm.coap] TRACE: Sending CoAP message
0000011471 [comm.coap] TRACE: CON GET /e/spark?u size=14 token= id=9
0000011477 [system] TRACE: Waiting until all handshake messages are processed by the protocol layer
0000011488 [comm.coap] TRACE: Received CoAP message
0000011492 [comm.coap] TRACE: ACK 0.00  size=5 token=cc id=2
0000011496 [comm.protocol] TRACE: Updating system DESCRIBE checksum
0000011502 [comm.dtls] INFO: session cmd (CLS,DIS,MOV,LOD,SAV): 4
0000011930 [comm.dtls] INFO: session cmd (CLS,DIS,MOV,LOD,SAV): 3
0000012252 [comm.coap] TRACE: Received CoAP message
0000012255 [comm.coap] TRACE: ACK 0.00  size=4 token= id=3
0000012360 [comm.coap] TRACE: Received CoAP message
0000012365 [comm.coap] TRACE: ACK 0.00  size=4 token= id=4
0000012437 [comm.coap] TRACE: Received CoAP message
0000012442 [comm.coap] TRACE: ACK 0.00  size=4 token= id=5
0000012547 [comm.coap] TRACE: Received CoAP message
0000012551 [comm.coap] TRACE: ACK 2.05  size=10 token=cd id=6
0000012555 [comm.protocol] INFO: Received TIME response: 1709769121
0000012661 [comm.coap] TRACE: Received CoAP message
0000012664 [comm.coap] TRACE: ACK 0.00  size=5 token=ce id=7
0000012669 [comm.protocol] TRACE: Updating application DESCRIBE checksum
0000012674 [comm.dtls] INFO: session cmd (CLS,DIS,MOV,LOD,SAV): 4
0000012679 [comm.dtls] INFO: session cmd (CLS,DIS,MOV,LOD,SAV): 3
0000012687 [app] INFO: scan count=0
0000012785 [comm.coap] TRACE: Received CoAP message
0000012789 [comm.coap] TRACE: ACK 0.00  size=4 token= id=8
0000012894 [comm.coap] TRACE: Received CoAP message
0000012898 [comm.coap] TRACE: ACK 0.00  size=4 token= id=9
0000012902 [system] INFO: All handshake messages have been processed
0000012908 [comm.protocol] TRACE: Updating subscriptions checksum
0000012913 [comm.dtls] INFO: session cmd (CLS,DIS,MOV,LOD,SAV): 4
0000012918 [comm.dtls] INFO: session cmd (CLS,DIS,MOV,LOD,SAV): 3
0000012951 [comm.coap] TRACE: Received CoAP message
0000012956 [comm.coap] TRACE: CON POST /E/particle/device/updates/pending size=47 token=01 id=54689
0000012963 [comm.coap] TRACE: Sending CoAP message
0000012967 [comm.coap] TRACE: ACK 0.00  size=4 token= id=54689
0000012974 [system] INFO: Cloud connected
0000012979 [comm.coap] TRACE: Received CoAP message
0000012982 [comm.coap] TRACE: CON GET /d?\x04 size=9 token=02 id=54690
0000012987 [comm.protocol] INFO: Received DESCRIBE request; flags: 0x04
0000012993 [comm.coap] TRACE: Sending CoAP message
0000012997 [comm.coap] TRACE: ACK 0.00  size=4 token= id=54690
0000013004 [comm.coap] TRACE: Sending CoAP message
0000013007 [comm.coap] TRACE: CON 2.05  size=151 token=02 id=10
0000013037 [comm.coap] TRACE: Received CoAP message
0000013041 [comm.coap] TRACE: ACK 0.00  size=4 token= id=10
0000017703 [app] INFO: scan count=0
0000022717 [app] INFO: scan count=0
0000027731 [app] INFO: scan count=0
0000032746 [app] INFO: scan count=0
0000037760 [app] INFO: scan count=0
0000038133 [comm.coap] TRACE: Sending CoAP message
0000038137 [comm.coap] TRACE: CON 0.00  size=4 token= id=11
0000038165 [comm.coap] TRACE: Received CoAP message
0000038169 [comm.coap] TRACE: ACK 0.00  size=4 token= id=11
0000042775 [app] INFO: scan count=0
0000047790 [app] INFO: scan count=0
0000052804 [app] INFO: scan count=0

If I add a Particle.disconnect() after 10 seconds:

0000017784 [app] INFO: scan count=0
0000022800 [app] INFO: scan count=0
0000022901 [system] INFO: Cloud: disconnecting
0000022905 [system] INFO: Cloud: disconnected
0000027814 [app] INFO: scan count=0
0000032828 [app] INFO: scan count=0

If I add a WiFi.off() after 10 seconds:

0000018172 [app] INFO: scan count=0
0000023188 [app] INFO: scan count=0
0000023195 [net.ifapi] INFO: Netif wl3 state DOWN
0000023199 [hal] INFO: DNS server list changed
0000023202 [hal] INFO: DNS server list changed
0000023206 [system.nm] INFO: State changed: IP_CONFIGURED -> IFACE_LINK_UP
0000023212 [ncp.rltk.client] INFO: disconnected
0000023215 [net.ifapi] INFO: Netif wl3 link DOWN, profile=NONE
0000023216 [net.rltkncp] ERROR: linkOutput up=0 link_up=0
0000023218 [hal] INFO: DNS server list changed
0000023219 [hal] INFO: DNS server list changed
0000023223 [system.nm] INFO: State changed: IFACE_LINK_UP -> IFACE_UP
0000023226 [system.nm] INFO: State changed: IFACE_UP -> IFACE_REQUEST_DOWN
0000023232 [system.nm] INFO: State changed: IFACE_REQUEST_DOWN -> IFACE_DOWN
0000023238 [ncp.rltk.client] INFO: rltkOff
0000023239 [ncp.rltk.client] INFO: rltkOff done
0000023240 [system] INFO: Cloud: disconnecting
0000023245 [system] INFO: Cloud: disconnected
0000023249 [system.nm] INFO: State changed: IFACE_DOWN -> DISABLED
0000023793 [net.rltkncp] ERROR: linkOutput up=0 link_up=0
0000024793 [net.rltkncp] ERROR: linkOutput up=0 link_up=0
0000025793 [net.rltkncp] ERROR: linkOutput up=0 link_up=0
0000026793 [net.rltkncp] ERROR: linkOutput up=0 link_up=0
0000028196 [app] INFO: scan count=30
0000033212 [app] INFO: scan count=30
0000038228 [app] INFO: scan count=30

That's it! killing WiFi with WiFi.off() lets BLE get scan results.

@Support Would you mind checking this, please?
Maybe there is a new setting in Photon 2 that I'm missing.
Thanks

jettonj · March 7, 2024, 3:00am

I've seen a similar-ish issue, but for scanning wifi networks instead of BLE devices. Intermittent dropped BLE packets with AndroidBLEExample - #3 by jettonj

For me adding the SYSTEM_THREAD(ENABLED) seemed to help a lot, but that's of course not your issue here and just because I haven't seen it come back up doesn't mean its fixed. I'd be very happy if you find a solution!

armor · March 7, 2024, 6:46pm

@gusgonnet

Photon2 Device OS 5.7.0 - estimated 14 Bluetooth devices visible

With SYSTEM_MODE(AUTOMATIC);

000214920 [app] INFO: BLE scan found 0 devices
0000214925 [system] INFO: Cloud: disconnected
0000219936 [app] INFO: BLE scan found 0 devices
0000224951 [app] INFO: BLE scan found 1 devices
0000229967 [app] INFO: BLE scan found 0 devices
0000234983 [app] INFO: BLE scan found 0 devices
0000240000 [app] INFO: BLE scan found 0 devices
0000245015 [app] INFO: BLE scan found 0 devices

With SYSTEM_MODE(MANUAL);

0000005025 [hal] INFO: rltk_wlan_set_netif_info: 0, 94:94:4a:05:57:90
0000005234 [hal] INFO: WiFi on
0000010574 [app] INFO: BLE scan found 14 devices
0000015590 [app] INFO: BLE scan found 15 devices
0000020606 [app] INFO: BLE scan found 14 devices
0000025621 [app] INFO: BLE scan found 14 devices
0000030637 [app] INFO: BLE scan found 12 devices
0000035653 [app] INFO: BLE scan found 10 devices
0000040669 [app] INFO: BLE scan found 11 devices
0000045684 [app] INFO: BLE scan found 12 devices

With SYSTEM_MODE(SEMI_AUTOMATIC); and WiFi.connect(); before BLE.on();

0000003743 [system.nm] INFO: State changed: DISABLED -> IFACE_DOWN
0000003750 [hal] INFO: rltk_wlan_set_netif_info: 0, 94:94:4a:05:57:90
0000003757 [system.nm] INFO: State changed: IFACE_DOWN -> IFACE_REQUEST_UP
0000003907 [net.ifapi] INFO: Netif wl3 state UP
0000003911 [system.nm] INFO: State changed: IFACE_REQUEST_UP -> IFACE_UP
0000003985 [hal] INFO: WiFi on
0000003987 [hal] INFO: WiFi is already on
0000003988 [ncp.rltk.client] INFO: rltkOff
0000003989 [ncp.rltk.client] INFO: rltkOff done
0000003989 [hal] INFO: WiFi is already on
0000003992 [ncp.rltk.client] INFO: Try to connect to ssid: xxxx
0000003994 [net.lwip_rltk] INFO: is_promisc_enabled
0000003995 [net.lwip_rltk] INFO: get_eap_phase
0000009376 [app] INFO: BLE scan found 16 devices
0000012044 [net.lwip_rltk] INFO: get_eap_phase
0000012262 [net.lwip_rltk] INFO: get_eap_phase
0000012277 [net.ifapi] INFO: Netif wl3 link UP, profile=xxxx
0000012288 [system.nm] INFO: State changed: IFACE_UP -> IFACE_LINK_UP
0000013157 [hal] INFO: DNS server list changed
0000013162 [system.nm] INFO: State changed: IFACE_LINK_UP -> IP_CONFIGURED
0000014392 [app] INFO: BLE scan found 15 devices
0000019408 [app] INFO: BLE scan found 0 devices
0000024423 [app] INFO: BLE scan found 0 devices
0000029438 [app] INFO: BLE scan found 0 devices

Clearly isn't working as it should. Thanks for highlighting.

I would really like to use BLE channel on the P2 but starting to think that it will not be feasible since Bonding doesn't work, Pairing only LESC Just-Works method working, no authentication methods supported, cannot make advertising devices not connectable....it is a depressingly long list. The security omissions are really bad though.

gusgonnet · March 7, 2024, 6:49pm

Thank you for running the test on your side.
Yeah, looks BLE on photon 2 needs some love, let's see what the team at Particle finds out.

gusgonnet · March 8, 2024, 12:59am

Update: Got word that this will be fixed in Device OS 5.8.0 coming soon.

gusgonnet · March 19, 2024, 12:57pm

This issue is resolved in 5.8.0.

system · April 18, 2024, 10:58pm

This topic was automatically closed 30 days after the last reply. New replies are no longer allowed.

Topic		Replies	Views
WiFi scan failure Device OS photon2 , p2	2	99	March 20, 2024
Argon vs Photon 2 for BLE Only Build BLE // NFC	3	498	December 6, 2022
WiFi.scan() returning 0 networks when no credentials present Troubleshooting photon	2	624	April 2, 2019
[solved]WiFi scan fails in manual/semi_automatic mode Troubleshooting	5	1416	June 11, 2017
Wired WiFi.scan result Firmware	1	549	July 8, 2019

Photon 2: WiFi impacts BLE scan

Observation:

Way to reproduce:

Logs

Related Topics