One notification setup succeeds, other one fails

[RobLewis]

Summary

One of two notification setups fails

Preconditions

Connect to BLE peripheral sending data on 2 characteristics

Steps to reproduce actual result

1. Connect to BLE device
2. on connection, set up notifications for 2 characteristics
3. Service Discovery begins (unrequested)
4. Error handler is called for second notification setup
5. "unsubscribed" message for second notification setup
6. Service Discovery completes
7. Notification enable descriptor (0x2902) is written for first notification setup, succeeds
8. Other BLE activity appears to proceed normally

   Actual result

   No notifications are received from second characteristic. Also, neither the doOnNext() nor doOnError() messages are logged for the setup of the notification (lines 6 and 8 in the code below).
   

   Expected result

   Stream of data packet notifications from second characteristic, occasional updates from first characteristic
   

Here is the code that attempts to set up the failing notification:

frameNotifSub = selectedScope.getConnectionObservable()  
        .subscribeOn( Schedulers.io() ) 
        .doOnNext( rxBleConnection -> selectedScope.bleConnection = rxBleConnection ) // save connection back to the variable
        .flatMap( rxBleConnection -> rxBleConnection.setupNotification( asDataCharId ) )
        .doOnNext( notificationObservable -> { // Notification has been set up
            Log.d( LOG_TAG, "Set up notification for Data frames from device: " ); 
        })
        .doOnError( throwable -> Log.d( LOG_TAG, "Error setting up Data frame notification: " + throwable.getMessage() ) )
        .flatMap( notificationObservable -> notificationObservable )
        .timestamp() // wrap each packet in a Timestamped object
        .scan( new ArrayList<Timestamped<byte[]>>(MAX_FRAME_SIZE / PACKET_SIZE + 1),
                ( ArrayList<Timestamped<byte[]>> packetBuffer, Timestamped<byte[]> packet )
                    -> DataOps.addPacket( packetBuffer, packet ) )
        .filter( pBuf -> pBuf != null ) // emit only non-null (full) packet buffers
        .map( pBuf -> DataOps.pBuf2dFrame( pBuf ) ) // convert packet buffer to data frame
        .observeOn( AndroidSchedulers.mainThread() ) //  can this affect UI?
        .doOnUnsubscribe( () -> Log.d( LOG_TAG, "Data Notification was unsubscribed") )
        .subscribe( this::processFrame, this::handleFrameError ); 

[RobLewis]

By replacing the above code with the following, the Data characteristic notification works:

dataNotifSub = selectedScope.getConnectionObservable()
        .flatMap(rxBleConnection -> rxBleConnection.setupNotification( asDataCharId))
        .doOnNext(notificationObservable -> runOnUiThread(this::dataNotificationHasBeenSetUp))
        .doOnError(setupThrowable -> runOnUiThread(this::dataNotificationSetupError))  
        .flatMap(notificationObservable -> notificationObservable)
        .timestamp()  
        .observeOn(AndroidSchedulers.mainThread())
        .subscribe(this::onDataNotificationReceived, this::onDataNotificationError);

This would seem to imply that there's something wrong with my original code, but I can't figure out what it is. I spent a lot of time studying the scan() operator and I believe I'm using it correctly. Everything else seems pretty straightforward. The runOnUiThread() was copied from code I found somewhere but I honestly don't understand why it's necessary. If all I want to do is log the information and possibly set some variables, do I really need it?

[dariuszseweryn]

1. You can touch the UI only from the main thread.
2. I see no error description apart of Error handler is called for second notification setup. Could you paste a stacktrace or at least what is the error?

Logs could be helpful to diagnose.

[RobLewis]

Thanks for fast response! Log is attached. logs_2_03-08.txt Comments: The characteristic that fails is 0x1235; the one that succeeds is 0x1239.

1. Line 154: Initial scan, finding 2 devices, completes.
2. Line 246: connection to user-selected device finishes. In the next line, service discovery starts.
3. Line 248: error message from the handleFrameError method (from the last line of the code I posted). I don't know why this method is being called here, especially since the messages advising of notification setup (line 6 in my code) or setup error (line 8) are not appearing.
4. Line 249: "Data Notification was unsubscribed" message from the next-to-last line of my code.
5. Line 323: Service discovery completes.
6. Line 342: Notification is set up for the other characteristic (0x1239). In my code, the setup for this one actually comes before the setup for 0x1235.
7. Line 400: First notification appears on characteristic 0x1239. Characteristic 0x1236 is written occasionally, and succeeds.

I will post more info in a separate comment.

[RobLewis]

Since you have the log, can you tell me why the MAC address frequently appears on 4 consecutive lines? See, for example, lines 494-497.

There is no stacktrace since the program doesn't terminate. It just fails to set up notifications on one of the two characteristics.

If I can't make this work, my fallback position is to use something similar to the working code I posted above to collect the data packets, then process them into a data frame and send it to a BehaviorSubject, which the code to process incoming data frames can subscribe to. Does this seem feasible? Is there a better way?

[dariuszseweryn]

If there is no error coming from RxBleConnection.setupNotification() then it seems that the problem lies on the application side.

I suggest to print the stack trace of the error that is happening. I have skimmed through the logs and I do not see a problem with how the library is working — if you think otherwise — feel free to add more information.

The mac addresses come from the Android OS and are an implementation detail of the Android API - cannot tell much about it.

A well written RxJava data flow should work well and without problems. Subjects are discouraged - there are some articles about it on the Internet.

[RobLewis]

Thanks. Can you help me understand how it could happen that NEITHER message ("Notification has been set up" or "Error setting up notification") is logged (lines 6 and 8 in my code)? It just jumps right to the end and says I'm unsubscribed.

[dariuszseweryn]

Looks like a NullPointerException somewhere. Possibly when creating the chain - maybe in some .flatMap() or .doOnNext().

[RobLewis]

Don't know if this is relevant, but my scan() function returns null most of the time; only when the packet buffer is full does it return non-null data. But these nulls are filtered out in the next step: .filter( pBuf -> pBuf != null ). I got this idea from StackOverflow—do you see a potential problem?

[dariuszseweryn]

From http://reactivex.io/documentation/operators/scan.html The Scan operator applies a function to the first item emitted by the source Observable and then emits the result of that function as its own first emission. It also feeds the result of the function back into the function along with the second item emitted by the source Observable in order to generate its second emission. It continues to feed back its own subsequent emissions along with the subsequent emissions from the source Observable in order to create the rest of its sequence. You have your null.

Best Regards

[RobLewis]

Just FYI: I read "The Problem with Subjects" http://tomstechnicalblog.blogspot.com/2016/03/rxjava-problem-with-subjects.html and none of the caveats seem to apply to my application, so I rewrote it using a BehaviorSubject and it appears to work well. Now experimenting with threading to try to increase performance.

Thanks again for your help. This will teach me not to believe everything I read on StackOverflow!