When you call rzb_fetchDeviceInformationKeys it does not actually read the first time

[tahirmt]

After connection at some point I am calling rzb_fetchDeviceInformationKeys to read device information. However, the first call to this always returns nil values as it doesn't actually read the values

I see the following logs

RZBLogLevelCommand - <DEVICE UUID> discoverServices:@[Device Information]

RZBLogLevelDelegate - peripheral:didDiscoverServices: - <DEVICE UUID> (null)

RZBLogLevelDelegateValue - Services=@[180A]

RZBLogLevelCommand - <DEVICE UUID> discoverCharacteristics:@[System ID, Model Number String, Serial Number String, Software Revision String, Firmware Revision String, Hardware Revision String, Manufacturer Name String, PnP ID] forService:180A

RZBLogLevelDelegate - peripheral:didDiscoverCharacteristicsForService:error: - <DEVICE UUID> (null)

RZBLogLevelDelegateValue - Characteristics=@[2A29, 2A24, 2A25]

However, if I call it again once the characteristics are discovered it returns the values and I see logs like

RZBLogLevelCommand - <DEVICE UUID> readValueForCharacteristic:Model Number String

RZBLogLevelCommand - <DEVICE UUID> readValueForCharacteristic:Serial Number String

RZBLogLevelCommand - <DEVICE UUID> readValueForCharacteristic:Manufacturer Name String

RZBLogLevelCommand - <DEVICE UUID> discoverCharacteristics:@[System ID, Software Revision String, Firmware Revision String, Hardware Revision String, PnP ID] forService:180A

RZBLogLevelDelegate - peripheral:didUpdateValueForCharacteristic:error: - <DEVICE UUID> (null)

RZBLogLevelDelegateValue - Value=<some value>

RZBLogLevelDelegate - peripheral:didUpdateValueForCharacteristic:error: - <DEVICE UUID> (null)

RZBLogLevelDelegateValue - Value=<some value>

RZBLogLevelDelegate - peripheral:didUpdateValueForCharacteristic:error: - <DEVICE UUID> (null)

RZBLogLevelDelegateValue - Value=<some value>

RZBLogLevelDelegate - peripheral:didDiscoverCharacteristicsForService:error: - <DEVICE UUID> 180A (null)

RZBLogLevelDelegateValue - Characteristics=@[2A29, 2A24, 2A25]

My understanding was that RZBluetooth handles the discovery of services and characteristics internally and I do not need to call discoverService and discoverCharacteristics methods...

[cpatterson-lilly]

I see this behavior in our code as well; I just worked around it. I haven't dug in to investigate why it is happening yet.

[KingOfBrian]

Interesting -- that's not good! Can you include a full log dump?

[tahirmt]

@KingOfBrian Like I posted above these are the logs I see

When I read it the first time I get

RZBLogLevelCommand - <DEVICE_UUID> discoverServices:@[Device Information]
RZBLogLevelDelegate - peripheral:didDiscoverServices: - <DEVICE_UUID> (null)
RZBLogLevelDelegateValue - Services=@[180A]
RZBLogLevelCommand - <DEVICE_UUID> discoverCharacteristics:@[System ID, Model Number String, Serial Number String, Software Revision String, Firmware Revision String, Hardware Revision String, Manufacturer Name String, PnP ID] forService:180A
RZBLogLevelDelegate - peripheral:didDiscoverCharacteristicsForService:error: - <DEVICE_UUID> 180A (null)
RZBLogLevelDelegateValue - Characteristics=@[2A29, 2A24, 2A25]

And when I read it the second time

RZBLogLevelCommand - <DEVICE_UUID> readValueForCharacteristic:Model Number String
RZBLogLevelCommand - <DEVICE_UUID> readValueForCharacteristic:Serial Number String
RZBLogLevelCommand - <DEVICE_UUID> readValueForCharacteristic:Manufacturer Name String
RZBLogLevelCommand - <DEVICE_UUID> discoverCharacteristics:@[System ID, Software Revision String, Firmware Revision String, Hardware Revision String, PnP ID] forService:180A
RZBLogLevelDelegate - peripheral:didUpdateValueForCharacteristic:error: - <DEVICE_UUID> (null)
RZBLogLevelDelegateValue - Value=<ACTUAL DATA VALUE>
RZBLogLevelDelegate - peripheral:didUpdateValueForCharacteristic:error: - <DEVICE_UUID>(null)
RZBLogLevelDelegateValue - Value=<ACTUAL DATA VALUE>
RZBLogLevelDelegate - peripheral:didUpdateValueForCharacteristic:error: - <DEVICE_UUID> (null)
RZBLogLevelDelegateValue - Value=<ACTUAL DATA VALUE>
RZBLogLevelDelegate - peripheral:didDiscoverCharacteristicsForService:error: - <DEVICE_UUID> (null)
RZBLogLevelDelegateValue - Characteristics=@[2A29, 2A24, 2A25]

And for obvious reasons I am obscuring the device UUID and the values being read... As you can see when I call it the first time I do not get any didUpdateValueForCharacteristic:error: get called. Only after the first discovery is complete does it get called. This happens consistently and every time. Not only this, if I manually call readCharacteristicUUID: serviceUUID:completion: on any of these characteristics, I see the same behavior the first time.

My RZBSetLogHandler is as follows

RZBSetLogHandler { (logLevel, format, args) in
                let level: String
                switch logLevel {
                case .command:
                    level = "RZBLogLevelCommand"
                case .delegate:
                    level = "RZBLogLevelDelegate"
                case .simulation:
                    level = "RZBLogLevelSimulation"
                case .configuration:
                    level = "RZBLogLevelConfiguration"
                case .delegateValue:
                    level = "RZBLogLevelDelegateValue"
                case .simulatedDevice:
                    level = "RZBLogLevelSimulatedDevice"
                case .writeCommandData:
                    level = "RZBLogLevelWriteCommandData"
                }
                if let format = format, let args = args {
                    print(level, NSString(format: format, arguments: args), separator: " - ")
                }
            }

As you can see the peripheral:didUpdateValueForCharacteristic:error: delegate is never called the first time.

[tahirmt]

@KingOfBrian It seems it only happens if you call it for characteristics that are not present in the device. So if the device has all of the characteristics, the peripheral:didUpdateValueForCharacteristic:error: is called and everything works as expected.

I logged the result of the read and it appears if there are characteristics that are not found in the peripheral it returns error for all the characteristics the first time and the second time it works.

First time reading

RZBLogLevelCommand - <PERIPHERAL UUID> discoverServices:@[Device Information]
RZBLogLevelDelegate - peripheral:didDiscoverServices: - <PERIPHERAL UUID> (null)
RZBLogLevelDelegateValue - Services=@[180A]
RZBLogLevelCommand - <PERIPHERAL UUID> discoverCharacteristics:@[System ID, Model Number String, Serial Number String, Software Revision String, Firmware Revision String, Hardware Revision String, Manufacturer Name String, PnP ID] forService:180A
RZBLogLevelDelegate - peripheral:didDiscoverCharacteristicsForService:error: - <PERIPHERAL UUID> 180A (null)
RZBLogLevelDelegateValue - Characteristics=@[2A29, 2A24, 2A25]
2017-07-13 17:52:37.077335+0500 Sample[3497:1905324] Characteristic read (null)
2017-07-13 17:52:37.077670+0500 Sample[3497:1905324] Error reading Error Domain=com.raizlabs.bluetooth Code=6 "(null)" UserInfo={undiscoveredUUIDs=(
    "System ID",
    "Software Revision String",
    "Firmware Revision String",
    "Hardware Revision String",
    "PnP ID"
)}
2017-07-13 17:52:37.077780+0500 Sample[3497:1905324] Characteristic read (null)
2017-07-13 17:52:37.078088+0500 Sample[3497:1905324] Error reading Error Domain=com.raizlabs.bluetooth Code=6 "(null)" UserInfo={undiscoveredUUIDs=(
    "System ID",
    "Software Revision String",
    "Firmware Revision String",
    "Hardware Revision String",
    "PnP ID"
)}
2017-07-13 17:52:37.078150+0500 Sample[3497:1905324] Characteristic read (null)
2017-07-13 17:52:37.078345+0500 Sample[3497:1905324] Error reading Error Domain=com.raizlabs.bluetooth Code=6 "(null)" UserInfo={undiscoveredUUIDs=(
    "System ID",
    "Software Revision String",
    "Firmware Revision String",
    "Hardware Revision String",
    "PnP ID"
)}
2017-07-13 17:52:37.078670+0500 Sample[3497:1905324] Characteristic read (null)
2017-07-13 17:52:37.079007+0500 Sample[3497:1905324] Error reading Error Domain=com.raizlabs.bluetooth Code=6 "(null)" UserInfo={undiscoveredUUIDs=(
    "System ID",
    "Software Revision String",
    "Firmware Revision String",
    "Hardware Revision String",
    "PnP ID"
)}
2017-07-13 17:52:37.079097+0500 Sample[3497:1905324] Characteristic read (null)
2017-07-13 17:52:37.079381+0500 Sample[3497:1905324] Error reading Error Domain=com.raizlabs.bluetooth Code=6 "(null)" UserInfo={undiscoveredUUIDs=(
    "System ID",
    "Software Revision String",
    "Firmware Revision String",
    "Hardware Revision String",
    "PnP ID"
)}
2017-07-13 17:52:37.079469+0500 Sample[3497:1905324] Characteristic read (null)
2017-07-13 17:52:37.079690+0500 Sample[3497:1905324] Error reading Error Domain=com.raizlabs.bluetooth Code=6 "(null)" UserInfo={undiscoveredUUIDs=(
    "System ID",
    "Software Revision String",
    "Firmware Revision String",
    "Hardware Revision String",
    "PnP ID"
)}
2017-07-13 17:52:37.079989+0500 Sample[3497:1905324] Characteristic read (null)
2017-07-13 17:52:37.080387+0500 Sample[3497:1905324] Error reading Error Domain=com.raizlabs.bluetooth Code=6 "(null)" UserInfo={undiscoveredUUIDs=(
    "System ID",
    "Software Revision String",
    "Firmware Revision String",
    "Hardware Revision String",
    "PnP ID"
)}
2017-07-13 17:52:37.080497+0500 Sample[3497:1905324] Characteristic read (null)
2017-07-13 17:52:37.080934+0500 Sample[3497:1905324] Error reading Error Domain=com.raizlabs.bluetooth Code=6 "(null)" UserInfo={undiscoveredUUIDs=(
    "System ID",
    "Software Revision String",
    "Firmware Revision String",
    "Hardware Revision String",
    "PnP ID"
)}

Second time reading

RZBLogLevelCommand - <PERIPHERAL UUID> readValueForCharacteristic:Model Number String
RZBLogLevelCommand - <PERIPHERAL UUID> readValueForCharacteristic:Serial Number String
RZBLogLevelCommand - <PERIPHERAL UUID> readValueForCharacteristic:Manufacturer Name String
RZBLogLevelCommand - <PERIPHERAL UUID> discoverCharacteristics:@[System ID, Software Revision String, Firmware Revision String, Hardware Revision String, PnP ID] forService:180A
RZBLogLevelDelegate - peripheral:didUpdateValueForCharacteristic:error: - <PERIPHERAL UUID> 2A24 (null)
RZBLogLevelDelegateValue - Value=<5061766c 6f6b2d53>
2017-07-13 17:52:37.134412+0500 Sample[3497:1905324] Characteristic read <CBCharacteristic: 0x1740a88e0, UUID = Model Number String, properties = 0x2, value = <THE VALUE READ>, notifying = NO>
2017-07-13 17:52:37.134612+0500 Sample[3497:1905324] Error reading (null)
RZBLogLevelDelegate - peripheral:didUpdateValueForCharacteristic:error: - <PERIPHERAL UUID> 2A25 (null)
RZBLogLevelDelegateValue - Value=<4b4242>
2017-07-13 17:52:37.193275+0500 Sample[3497:1905324] Characteristic read <CBCharacteristic: 0x1740aa3e0, UUID = Serial Number String, properties = 0x2, value = <THE VALUE READ>, notifying = NO>
2017-07-13 17:52:37.193393+0500 Sample[3497:1905324] Error reading (null)
RZBLogLevelDelegate - peripheral:didUpdateValueForCharacteristic:error: - <PERIPHERAL UUID> 2A29 (null)
RZBLogLevelDelegateValue - Value=<42656861 76696f72 616c2054 6563686e 6f6c6f67 79204772 6f75702c 20496e63 2e>
2017-07-13 17:52:37.314334+0500 Sample[3497:1905324] Characteristic read <CBCharacteristic: 0x1740a8940, UUID = Manufacturer Name String, properties = 0x2, value = <THE VALUE READ>, notifying = NO>
2017-07-13 17:52:37.314483+0500 Sample[3497:1905324] Error reading (null)
RZBLogLevelDelegate - peripheral:didDiscoverCharacteristicsForService:error: - <PERIPHERAL UUID> 180A (null)
RZBLogLevelDelegateValue - Characteristics=@[2A29, 2A24, 2A25]
2017-07-13 17:52:37.316350+0500 Sample[3497:1905324] Characteristic read (null)
2017-07-13 17:52:37.316781+0500 Sample[3497:1905324] Error reading Error Domain=com.raizlabs.bluetooth Code=6 "(null)" UserInfo={undiscoveredUUIDs=(
    "System ID",
    "Software Revision String",
    "Firmware Revision String",
    "Hardware Revision String",
    "PnP ID"
)}
2017-07-13 17:52:37.316907+0500 Sample[3497:1905324] Characteristic read (null)
2017-07-13 17:52:37.317434+0500 Sample[3497:1905324] Error reading Error Domain=com.raizlabs.bluetooth Code=6 "(null)" UserInfo={undiscoveredUUIDs=(
    "System ID",
    "Software Revision String",
    "Firmware Revision String",
    "Hardware Revision String",
    "PnP ID"
)}
2017-07-13 17:52:37.317663+0500 Sample[3497:1905324] Characteristic read (null)
2017-07-13 17:52:37.318257+0500 Sample[3497:1905324] Error reading Error Domain=com.raizlabs.bluetooth Code=6 "(null)" UserInfo={undiscoveredUUIDs=(
    "System ID",
    "Software Revision String",
    "Firmware Revision String",
    "Hardware Revision String",
    "PnP ID"
)}
2017-07-13 17:52:37.318582+0500 Sample[3497:1905324] Characteristic read (null)
2017-07-13 17:52:37.319051+0500 Sample[3497:1905324] Error reading Error Domain=com.raizlabs.bluetooth Code=6 "(null)" UserInfo={undiscoveredUUIDs=(
    "System ID",
    "Software Revision String",
    "Firmware Revision String",
    "Hardware Revision String",
    "PnP ID"
)}
2017-07-13 17:52:37.319229+0500 Sample[3497:1905324] Characteristic read (null)
2017-07-13 17:52:37.319567+0500 Sample[3497:1905324] Error reading Error Domain=com.raizlabs.bluetooth Code=6 "(null)" UserInfo={undiscoveredUUIDs=(
    "System ID",
    "Software Revision String",
    "Firmware Revision String",
    "Hardware Revision String",
    "PnP ID"
)}
2017-07-13 17:52:37.320255+0500 Sample[3497:1905324] Done second read
RZBLogLevelDelegate - centralManager:didDisconnectPeripheral:error: - <CBCentralManager: 0x17406f5c0> <PERIPHERAL UUID> Error Domain=CBErrorDomain Code=6 "The connection has timed out unexpectedly." UserInfo={NSLocalizedDescription=The connection has timed out unexpectedly.}
17:52:44.447 <UI> PavlokManager.swift peripheral(_:connectionEvent:error:)[201]: "Connection Disconnected on <PavlokS.Device: 0x170077500>"
RZBLogLevelCommand - connectPeripheral:<PERIPHERAL UUID> options:(null)

[cpatterson-lilly]

That matches up with what we saw as well. Our workaround was to only request the device info keys we knew were supported by our device(s).

[KingOfBrian]

I'm not entirely sure why this would result in all nil given the code, but it just seems like a bug. It'd be great if one of you could put up a PR. I don't have a device with a DeviceInfo Service at the moment, so it'd be a bit of pain to do one. I think explicitly discovering services and then reading all of the discovered services might work better.

[tahirmt]

@cpatterson-lilly That's exactly what I did. I only requested the ones that are there in my peripherals and it works fine. @KingOfBrian but services discovery is already there so it shouldn't be needed. I'll see if discovering services first changes anything.