Corrupt SDK response when heartbeat is fast

[gkamperis]

To reproduce just take your sample android app.
Change the below to enable hertbeat.

private BridgeStateUpdatedCallback bridgeStateUpdatedCallback = new BridgeStateUpdatedCallback() {
@Override
public void onBridgeStateUpdated(Bridge bridge, BridgeStateUpdatedEvent bridgeStateUpdatedEvent) {
Log.i(TAG, "Bridge state updated event: " + bridgeStateUpdatedEvent);
    switch (bridgeStateUpdatedEvent) {
            case INITIALIZED:
                // The bridge state was fully initialized for the first time.
                // It is now safe to perform operations on the bridge state.
                updateUI(UIState.Connected, "Connected!");

                final BridgeConnection bridgeConnection = bridge.getBridgeConnection(BridgeConnectionType.LOCAL);
                if (bridgeConnection == null) return;
                final HeartbeatManager heartbeatManager = bridgeConnection.getHeartbeatManager();
                if (heartbeatManager == null) return;
                heartbeatManager.stopAllHeartbeats();
                //
                heartbeatManager.startHeartbeat(BridgeStateCacheType.LIGHTS_AND_GROUPS, 1000);
                heartbeatManager.startHeartbeat(BridgeStateCacheType.SCENES, 1000);
                break;

            case LIGHTS_AND_GROUPS:
                // At least one light was updated.
                break;

            default:
                break;
        }
    }
};

It either breaks down and disconnects like the below

03-03 14:52:15.585 24576-24576/? I/art: Not late-enabling -Xcheck:jni (already on)
03-03 14:52:15.586 24576-24576/? W/art: Unexpected CPU variant for X86 using defaults: x86_64
03-03 14:52:15.659 24576-24576/com.philips.lighting.hue.demo.huequickstartapp I/HueSDK: JNI_HueSDK - JNI_OnLoad called
03-03 14:52:15.676 24576-24576/com.philips.lighting.hue.demo.huequickstartapp W/art: Before Android 4.1, method android.graphics.PorterDuffColorFilter android.support.graphics.drawable.VectorDrawableCompat.updateTintFilter(android.graphics.PorterDuffColorFilter, android.content.res.ColorStateList, android.graphics.PorterDuff$Mode) would have incorrectly overridden the package-private method in android.graphics.drawable.Drawable
03-03 14:52:15.756 24576-24576/com.philips.lighting.hue.demo.huequickstartapp I/HueQuickStartApp: Status: Connecting to bridge...
03-03 14:52:15.824 24576-24611/com.philips.lighting.hue.demo.huequickstartapp I/OpenGLRenderer: Initialized EGL, version 1.4
03-03 14:52:15.824 24576-24611/com.philips.lighting.hue.demo.huequickstartapp D/OpenGLRenderer: Swap behavior 1
03-03 14:52:15.824 24576-24611/com.philips.lighting.hue.demo.huequickstartapp W/OpenGLRenderer: Failed to choose config with EGL_SWAP_BEHAVIOR_PRESERVED, retrying without...
03-03 14:52:15.824 24576-24611/com.philips.lighting.hue.demo.huequickstartapp D/OpenGLRenderer: Swap behavior 0
03-03 14:52:15.832 24576-24591/com.philips.lighting.hue.demo.huequickstartapp I/HueQuickStartApp: Bridge state updated event: BRIDGE_CONFIG
03-03 14:52:15.838 24576-24616/com.philips.lighting.hue.demo.huequickstartapp I/HueQuickStartApp: Connection event: CONNECTED
03-03 14:52:15.846 24576-24611/com.philips.lighting.hue.demo.huequickstartapp D/EGL_emulation: eglCreateContext: 0x738bee5e5700: maj 3 min 1 rcv 4
03-03 14:52:15.887 24576-24611/com.philips.lighting.hue.demo.huequickstartapp D/EGL_emulation: eglMakeCurrent: 0x738bee5e5700: ver 3 1 (tinfo 0x738be46bbc40)
03-03 14:52:15.888 24576-24611/com.philips.lighting.hue.demo.huequickstartapp E/eglCodecCommon: glUtilsParamSize: unknow param 0x000082da
03-03 14:52:15.888 24576-24611/com.philips.lighting.hue.demo.huequickstartapp E/eglCodecCommon: glUtilsParamSize: unknow param 0x000082da
03-03 14:52:15.902 24576-24611/com.philips.lighting.hue.demo.huequickstartapp D/EGL_emulation: eglMakeCurrent: 0x738bee5e5700: ver 3 1 (tinfo 0x738be46bbc40)
03-03 14:52:16.054 24576-24622/com.philips.lighting.hue.demo.huequickstartapp I/HueQuickStartApp: Connection event: AUTHENTICATED
03-03 14:52:16.083 24576-24591/com.philips.lighting.hue.demo.huequickstartapp I/HueQuickStartApp: Bridge state updated event: FULL_CONFIG
03-03 14:52:16.102 24576-24591/com.philips.lighting.hue.demo.huequickstartapp I/HueQuickStartApp: Bridge state updated event: INITIALIZED
03-03 14:52:16.103 24576-24576/com.philips.lighting.hue.demo.huequickstartapp I/HueQuickStartApp: Status: Connected!
03-03 14:52:16.206 24576-24592/com.philips.lighting.hue.demo.huequickstartapp E/HueSDK: Retriever: invalid json retrieved from: http://QQQ.QQQ.QQQ.QQQ/api/QQQQQQQQQQQQQQQQQQQQQQQQQQ, resource path: /scenes
03-03 14:52:16.206 24576-24624/com.philips.lighting.hue.demo.huequickstartapp E/HueSDK: HeartbeatManager: perform_heartbeat: bridge state not updated, because the response was corrupt - Fatal error, disconnecting
03-03 14:52:16.206 24576-24624/com.philips.lighting.hue.demo.huequickstartapp E/HueSDK: BridgeConnection: Fatal disconnect - Bridge response corrupt, SDK cannot parse.
03-03 14:52:16.226 24576-24628/com.philips.lighting.hue.demo.huequickstartapp E/HueQuickStartApp: Connection error: SDK Error: code RESPONSE_CORRUPT, Bridge response corrupt, SDK cannot parse.
03-03 14:52:16.248 24576-24632/com.philips.lighting.hue.demo.huequickstartapp I/HueQuickStartApp: Connection event: DISCONNECTED

or gets errors every heartbeat:

03-03 15:00:52.841 24705-24705/? I/art: Not late-enabling -Xcheck:jni (already on)
03-03 15:00:52.842 24705-24705/? W/art: Unexpected CPU variant for X86 using defaults: x86_64
03-03 15:00:52.882 24705-24705/com.philips.lighting.hue.demo.huequickstartapp I/HueSDK: JNI_HueSDK - JNI_OnLoad called
03-03 15:00:52.894 24705-24705/com.philips.lighting.hue.demo.huequickstartapp W/art: Before Android 4.1, method android.graphics.PorterDuffColorFilter android.support.graphics.drawable.VectorDrawableCompat.updateTintFilter(android.graphics.PorterDuffColorFilter, android.content.res.ColorStateList, android.graphics.PorterDuff$Mode) would have incorrectly overridden the package-private method in android.graphics.drawable.Drawable
03-03 15:00:52.995 24705-24705/com.philips.lighting.hue.demo.huequickstartapp I/HueQuickStartApp: Status: Connecting to bridge...
03-03 15:00:53.060 24705-24742/com.philips.lighting.hue.demo.huequickstartapp I/OpenGLRenderer: Initialized EGL, version 1.4
03-03 15:00:53.060 24705-24742/com.philips.lighting.hue.demo.huequickstartapp D/OpenGLRenderer: Swap behavior 1
03-03 15:00:53.061 24705-24742/com.philips.lighting.hue.demo.huequickstartapp W/OpenGLRenderer: Failed to choose config with EGL_SWAP_BEHAVIOR_PRESERVED, retrying without...
03-03 15:00:53.061 24705-24742/com.philips.lighting.hue.demo.huequickstartapp D/OpenGLRenderer: Swap behavior 0
03-03 15:00:53.080 24705-24742/com.philips.lighting.hue.demo.huequickstartapp D/EGL_emulation: eglCreateContext: 0x738bee5e64c0: maj 3 min 1 rcv 4
03-03 15:00:53.134 24705-24742/com.philips.lighting.hue.demo.huequickstartapp D/EGL_emulation: eglMakeCurrent: 0x738bee5e64c0: ver 3 1 (tinfo 0x738bd4954a60)
03-03 15:00:53.135 24705-24742/com.philips.lighting.hue.demo.huequickstartapp E/eglCodecCommon: glUtilsParamSize: unknow param 0x000082da
03-03 15:00:53.136 24705-24742/com.philips.lighting.hue.demo.huequickstartapp E/eglCodecCommon: glUtilsParamSize: unknow param 0x000082da
03-03 15:00:53.148 24705-24742/com.philips.lighting.hue.demo.huequickstartapp D/EGL_emulation: eglMakeCurrent: 0x738bee5e64c0: ver 3 1 (tinfo 0x738bd4954a60)
03-03 15:00:57.651 24705-24721/com.philips.lighting.hue.demo.huequickstartapp I/HueQuickStartApp: Bridge state updated event: BRIDGE_CONFIG
03-03 15:00:57.657 24705-24749/com.philips.lighting.hue.demo.huequickstartapp I/HueQuickStartApp: Connection event: CONNECTED
03-03 15:00:57.882 24705-24753/com.philips.lighting.hue.demo.huequickstartapp I/HueQuickStartApp: Connection event: AUTHENTICATED
03-03 15:00:57.902 24705-24721/com.philips.lighting.hue.demo.huequickstartapp I/HueQuickStartApp: Bridge state updated event: FULL_CONFIG
03-03 15:00:57.920 24705-24721/com.philips.lighting.hue.demo.huequickstartapp I/HueQuickStartApp: Bridge state updated event: INITIALIZED
03-03 15:00:57.920 24705-24705/com.philips.lighting.hue.demo.huequickstartapp I/HueQuickStartApp: Status: Connected!
03-03 15:00:57.975 24705-24722/com.philips.lighting.hue.demo.huequickstartapp E/HueSDK: Retriever: invalid json retrieved from: http://QQQ.QQQ.QQQ.QQQ/api/QQQQQQQQQQQQQQQQQQQQQQQQQQ, resource path: /groups
03-03 15:00:57.982 24705-24754/com.philips.lighting.hue.demo.huequickstartapp E/HueSDK: LightAndGroupParser: groups node missing
03-03 15:00:57.982 24705-24754/com.philips.lighting.hue.demo.huequickstartapp E/HueSDK: HeartbeatManager: perform_heartbeat: bridge state not updated, because the retriever returned an error, cache type: BRIDGE_STATE_CACHE_TYPE_LIGHTS_AND_GROUPS, connection string: http://QQQ.QQQ.QQQ.QQQ/api/QQQQQQQQQQQQQQQQQQQQQQQQQQ
03-03 15:01:01.373 24705-24722/com.philips.lighting.hue.demo.huequickstartapp E/HueSDK: Retriever: invalid json retrieved from: http://QQQ.QQQ.QQQ.QQQ/api/QQQQQQQQQQQQQQQQQQQQQQQQQQ, resource path: /lights
03-03 15:01:01.397 24705-24754/com.philips.lighting.hue.demo.huequickstartapp E/HueSDK: LightAndGroupParser: lights node missing
03-03 15:01:01.398 24705-24754/com.philips.lighting.hue.demo.huequickstartapp E/HueSDK: HeartbeatManager: perform_heartbeat: bridge state not updated, because the retriever returned an error, cache type: BRIDGE_STATE_CACHE_TYPE_LIGHTS_AND_GROUPS, connection string: http://QQQ.QQQ.QQQ.QQQ/api/QQQQQQQQQQQQQQQQQQQQQQQQQQ
03-03 15:01:06.039 24705-24722/com.philips.lighting.hue.demo.huequickstartapp E/HueSDK: Retriever: invalid json retrieved from: http://QQQ.QQQ.QQQ.QQQ6/api/QQQQQQQQQQQQQQQQQQQQQQQQQQ, resource path: /groups
03-03 15:01:06.041 24705-24754/com.philips.lighting.hue.demo.huequickstartapp E/HueSDK: LightAndGroupParser: groups node missing
03-03 15:01:06.041 24705-24754/com.philips.lighting.hue.demo.huequickstartapp E/HueSDK: HeartbeatManager: perform_heartbeat: bridge state not updated, because the retriever returned an error, cache type: BRIDGE_STATE_CACHE_TYPE_LIGHTS_AND_GROUPS, connection string: http://QQQ.QQQ.QQQ.QQQ/api/QQQQQQQQQQQQQQQQQQQQQQQQQQ

[jhvdb87]

It is not reproducible here. The error shows the response from the bridge can not be parsed and causing the behaviour you mentioned. Can you enable debug logging, which also shows the response we get from the http requests, and post the result ?

[gkamperis]

Maybe it is bridge load related?
What sort of load does the bridge you tested have?
Try 25 lights, 90 scenes, 20 groups.

I will send the debug responses but ultimately does it matter?
The log message above comes from the SDK and it says the lights and groups node is missing.
Most frequent is the scenes and groups node missing.

To me it seems there is a race condition at the SDK level.
The bridge http response gets corrupt while it is parsing it...
or the parser misinterprets the json and cannot close it off and thinks it is corrupt.

Whatever the reason, the issue lies within the SDK as it sometimes works and sometimes does not.

BTW I can replicate this same behaviour with a disconnect followed by a connect in a quick fashion.

So if you press the back button to get out of the app and tap the icon to start again, if call bridge.disconnect() and bridge.connect() in the onResume and onPause events the same issue occurs.
And I also see the CONNECTED followed immediately b a DISCONNECTED in the logs.

Even if I disable the heartbeat and manually call refresh it ends up calling the same methods and get the corruption.

[jhvdb87]

The debug log does matter, because it will contain all the http responses from the requests sent to the bridge. Based on the http responses we can check whether the response from the bridge is valid or there is a problem in the processing part of the SDK.

To enable debug logging, you have the set the log level in HueLog.java.

We internally test on bridges that have more lights and other resources. So far this issue has never been reproduced.

[gkamperis]

Is there an email I can send this to?
The log is quite big to paste.

I got an error for groups and for scenes

checking the response it seems it is missing the final ending } on one response but not on others.
So to be clear, at one time the response for groups is formed correctly and at another time it is missing the final '}' to close off the json.

same goes for scenes.

and as I mentioned already the older SDK had the same issue.

[jhvdb87]

Email: philipshuedev@philips.com

[jhvdb87]

"and as I mentioned already the older SDK had the same issue."

Ok I missed that part. Are you saying that our old iOS and Java SDK have the same issue ?

[gkamperis]

I have sent an email.

Yes indeed the old SDK (Java - cannot comment for iOS) also had the same issue.
I mentioned this in the other thread as well.
However the older SDK does not disconnect upon the issue.

So, maybe it is the bridge or some common code between the two SDKs?

no idea but for sure the last } is missing

[jhvdb87]

There is no common code between old an new SDK's.
Do you have a V1 (round) or V2 (square) bridge ?

[gkamperis]

v2 latest firmware but it has been happening through various firmware updates for a long time now

Model: BSB002
API version 1.23.0
SW: 1801260942

but you can see this from the log as well.

by common code I didn't mean shared library but common implementation that has the issue

[gkamperis]

here is a different incident but again invalid JSON with the old SDK

https://developers.meethue.com/content/unable-parse-response-when-pushlinking-invalid-json-returned-bridge

[jhvdb87]

Analysing the logs clearly shows that for some requests the '}' at the end is missing. As this behaviour is also seen on the old SDK's, I suspect this is a bridge issue. I will file a ticket internally. I'll keep you posted.

[gkamperis]

BTW same with latest bridge version:

SWVersion: 1802201122
Api version: 1.24.0

[gkamperis]

Also it might be worth reconsidering the current HueSDK implementation to disconnect when it gets these errors.
The older SDK did not disconnect and it was usable.
The new one with this intermittent issue really becomes almost unusable.

Why was the decision taken to disconnect after a bad response?
Makes very little sense...
Can you at least add an option or something like that?

Thanks

[jhvdb87]

I agree the disconnect is inconvenient. I don't think the disconnect option should be configurable though.

[gkamperis]

Only mentioned configurable to allow for any reasoning behind making this fatal.

As mentioned the disconnect makes this unusable.
The treatment of the error is different to the older SDK.
Please consider making it a non fatal situation.

Thanks again for your help.