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: [email protected]

[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.

[gkamperis]

Any update on this?
It really kills the usage of the new SDK.

[jhvdb87]

We have no reproduction scenario. If you can reproduce, can you provide us the Wireshark logs, so we can investigate this further ?

[gkamperis]

I have already sent it at the philips hue dev email more than a month ago

[jhvdb87]

Ok. I was not aware of that. I will check with my colleagues :)

[gkamperis]

Thank you

[smiLLe]

@jhvdb87
Hi, while i was searching for a link to the new "none deprecated" hue sdk i saw this issue.
I am developing a flutter (dart) based app where I poll the lights/groups every second. I am also experiencing the same problem with the missing "}" in the end of the JSON string, but also sometimes there is a ":" missing between two properties. I do not use the hueSDK, all i do is to directly call a http request through the dart http library.
I own the latest Hue Bridge and use the latest updates as of today.
There is absolutely no way i could reproduce this error. It is just random. About 1-3 of 10 requests fail with an invalid JSON string returned.

[gkamperis]

@smiLLe yes there are also other occurences of this issue in other posts in the forums.

Don't know why it has not been addressed as it has been going on for years.

The previous SDK treated the situation as a "warning" and continued.
The new SDK considers it terminal and stops and therefore becomes unusable.

@jhvdb87 Honestly if the issue is deeply rooted into the bridge firmware and it is too difficult to resolve all we need is an option to tell the SDK to not treat the situation as terminal.

This should be easy to implement.

[jhvdb87]

@smiLLe Thanks for the info.
@gkamperis I agree, we will implement this

[gkamperis]

@jhvdb87 thanks for the quick reply.

Any idea on timelines?

[smiLLe]

@jhvdb87 the fix will end up in the new EDK? I requested access but got no invite. Would appreciate if i had access.

[jhvdb87]

@gkamperis This will be picked up in the coming sprints. So release window will be around 2 months before we can release this fix on our new repo

[gkamperis]

@jhvdb87 Any news on this?

It has been more than two months and the specific issue can be probably resolved with a few lines of code.

A beta version will be sufficient.

[jhvdb87]

Yes there is news: the fix has been implemented. The release is being prepared as we speak. ETA was end Augustus/begin September, so we are a little late.

[gkamperis]

@jhvdb87 the new way of using the sdk in Android introduces a min version of 21.

Why does it do so?
Does the sdk rely on Android APIs? how?

Please consider reducing it to 16.

SDK 16 - 19 still covers about 11% of Android devices

EDIT: seems to be missing mips, mips64, armeabi, x86_64

[gkamperis]

@jhvdb87 when running my app...

E/HueSDK: JNI_HueSDK - Java SDK version 1.28.49 does not match binary version 1.21.0, fatal error!

EDIT: figured it out...
When you migrate from the previous version of the SDK don't forget to remove the *.so libs you had manually added under jniLibs

[jeroenbeuz]

@jhvdb87 the new way of using the sdk in Android introduces a min version of 21.

Why does it do so?
Does the sdk rely on Android APIs? how?

Please consider reducing it to 16.

SDK 16 - 19 still covers about 10% of Android devices

Exactly this. The min SDK has changed from 19 to 21, without any message to developers to let us know about this breaking change. Please reduce it to at least 19 as it was before.

[gkamperis]

@jhvdb87 Any comments/guidance on the missing libs and min SDK?

[jhvdb87]

mips, mips64 and armeabi are deprecated, so we removed them. x86_64 is removed, because it was not used by our app. It shouldn't make a difference though, x86 is still there :)
The min SDK will be reverted to 19 in the next release (not planned yet, but expected rather soon)

[gkamperis]

@jhvdb87 any reason why not support 16+? what android APIs are missing from it?

[jhvdb87]

We have to investigate whether we can revert to 16. We chose 19 initially, because it was back then also the min version used by our Android app.