openhab / openhab-cloud

Cloud companion for openHAB instances
Eclipse Public License 2.0
315 stars 161 forks source link

[BUG?] "RequestId" is "Removed" Earlier than Trailing Traffic being Served #408

Open lsafelix75 opened 1 year ago

lsafelix75 commented 1 year ago

I am seeing this odd behavior which i presume it only occurs when the internet connection between Openhab instance and Cloud is super fast. Anyway, I have my own OpenCloud and another Openhab instance with separate ISPs. Problem is I seldom able to load the homepage of Openhab instance successfully via OpenHabCloud.

After some investigation, the following code is served faster than socket.on("responseContent"...). This code actually calls line 389 of routes/index.js which results requestId being removed prematurely. To test this theory, i intentionally delay emission of socket.emit("responseFinished", responseJson); by 10milliseconds in line 504 of CloudClient.java of org.openhab.io.openhabcloud. Truly, the problem is resolved.

I am not sure whether this is a right approach or whether anyone has seen this problem. But, i am delighted to raise PR if you have encountered the same problem too.

 socket.on('responseFinished', function (data) {
        var self = this;
        var requestId = data.id,
            request;
        if (requestTracker.has(requestId)) {
            request = requestTracker.get(requestId);
            if (self.handshake.uuid === request.openhab.uuid) {
                request.end();
            } else {
                logger.warn('openHAB-cloud: ' + self.handshake.uuid + ' tried to respond to request which it doesn\'t own');
            }
        }
    });
Flole998 commented 1 year ago

I am a little bit surprised: In general the order in which the messages arrive should be preserved (as that's all TCP and TCP shouldn't cause messages to be shuffled around). So I can only imaging that the processing of responseFinished is simply faster even though it was called later, but AFAIK node.js does not preempt and also does not do multithreading, so that also shouldn't be the case. Maybe you can look into when each of the handlers start and end? Or are you using the polling transport/is websocket unavailable in your case? In that case multiple polling connections could probably cause out-of-order events aswell.