search

AlCalzone / node-tradfri-client

Library to talk to IKEA Trådfri Gateways without external binaries
MIT License
264 stars 30 forks source link

Error: unexpected response (4.00) to observeScene(169275, 200468) #36

Open CliffS opened 6 years ago

CliffS commented 6 years ago

Seeing a lot of error events in long-running code.

Error: unexpected response (4.00) to observeScene(169275, 200468).
    at TradfriClient.observeScene_callback (/home/cliff/src/git/house/node_modules/node-tradfri-client/build/tradfri-client.js:456:36)
    at PendingRequest.handleResponse [as callback] (/home/cliff/src/git/house/node_modules/node-tradfri-client/build/tradfri-client.js:415:41)
    at Function.onMessage (/home/cliff/src/git/house/node_modules/node-coap-client/build/CoapClient.js:606:33)
    at SocketWrapper.emit (events.js:127:13)
    at SocketWrapper.socket.on (/home/cliff/src/git/house/node_modules/node-coap-client/build/lib/SocketWrapper.js:12:18)
    at Socket.emit (events.js:127:13)
    at Socket.udp_onMessage (/home/cliff/src/git/house/node_modules/node-dtls-client/build/dtls.js:204:34)
    at Socket.emit (events.js:127:13)
    at UDP.onMessage (dgram.js:659:8)

Should I care? Or should I just be ignoring them?

AlCalzone commented 6 years ago

Did you delete a scene? I guess I should not log an error for that response code.

CliffS commented 6 years ago

No scenes deleted or otherwise changed. But I agree with your proposed solution. :)

AlCalzone commented 6 years ago

Oh I mistook code 4.00 for 4.04. I'll enhance the log for those to find out why its happening.

CliffS commented 6 years ago

Also getting 4.08s. I hadn't noticed that some are 4.00 and some are 4.08. You already ignore 4.04s.

AlCalzone commented 6 years ago

Ok, please check your logs with this version: c6a6967

AlCalzone commented 6 years ago

4.08 means Request Entity Incomplete - this is due to an incomplete implementation of RFC 7959, see https://github.com/AlCalzone/node-coap-client/issues/23

Some traffic logs would be nice to find out whats being sent and why its incomplete.

CliffS commented 6 years ago

Right. I've set everything up with links and updated everything. I'll let you know what happens.

Thanks.

CliffS commented 6 years ago

Since running on the https://github.com/AlCalzone/node-tradfri-client/commit/c6a6967fee2d1263ba5b77aa01910f67f4b0152a code, I have not seen this issue. Does that mean you've fixed it?

AlCalzone commented 6 years ago

Can't be as the errors come from node-coap-client and I only added logs to node-tradfri-client. Guess you'll have to continue watching.

CliffS commented 6 years ago

I've been unable to reproduce this so I'm closing this issue for the time being. If it reappears with the latest code, I'll reopen it.

Thanks.

CliffS commented 4 years ago

This has suddenly started happening again after I upgraded recently. I'm current running the v2.1.0 release of node-tradfri-client. The log is as follows:

Dec 25 09:12:27 pi npm[4465]: /opt/cliff/src/git/house/node_modules/ikea-tradfri/lib/Tradfri.js:96
Dec 25 09:12:27 pi npm[4465]:                   throw err;
Dec 25 09:12:27 pi npm[4465]:                   ^
Dec 25 09:12:27 pi npm[4465]: Error: unexpected response (4.00) to observeDevice(65541): [object Object]
Dec 25 09:12:27 pi npm[4465]:     at TradfriClient.handleNonSuccessfulResponse (/opt/cliff/src/git/house/node_modules/node-tradfri-client/build/tradfri-client.js:750:32)
Dec 25 09:12:27 pi npm[4465]:     at TradfriClient.observeDevice_callback (/opt/cliff/src/git/house/node_modules/node-tradfri-client/build/tradfri-client.js:389:23)
Dec 25 09:12:27 pi npm[4465]:     at PendingRequest.handleResponse [as callback] (/opt/cliff/src/git/house/node_modules/node-tradfri-client/build/tradfri-client.js:346:41)
Dec 25 09:12:27 pi npm[4465]:     at Function.onMessage (/opt/cliff/src/git/house/node_modules/node-coap-client/build/CoapClient.js:631:33)
Dec 25 09:12:27 pi npm[4465]:     at SocketWrapper.emit (events.js:188:13)
Dec 25 09:12:27 pi npm[4465]:     at SocketWrapper.socket.on (/opt/cliff/src/git/house/node_modules/node-coap-client/build/lib/SocketWrapper.js:12:18)
Dec 25 09:12:27 pi npm[4465]:     at Socket.emit (events.js:188:13)
Dec 25 09:12:27 pi npm[4465]:     at Socket.udp_onMessage (/opt/cliff/src/git/house/node_modules/node-dtls-client/build/dtls.js:189:34)
Dec 25 09:12:27 pi npm[4465]:     at Socket.emit (events.js:188:13)
Dec 25 09:12:27 pi npm[4465]:     at UDP.onMessage (dgram.js:685:8)

Merry Christmas! :)

AlCalzone commented 4 years ago

Sorry to take so long, but you probably know where my priorities are right now. I'll need a tcpdump to understand whats going on, which must include the connection initiation. I usually set it up with a filter on port 5684 to only capture the CoAP traffic. And I'll need your connection credentials to decrypt the communication.

AlCalzone commented 4 years ago

Can you try again with the latest version of this library? I've identified an issue with expiring credentials - maybe that is the root cause of this issue. The lib now tries to automatically re-authenticate, therefore you should always call authenticate(...) and then connect with the fresh credentials so the lib knows your security code.

CliffS commented 4 years ago

Just seen this again after all this time. It is consistent if I edit a scene in the Android app and happens on save:

Apr 14 11:29:07 pi npm[9533]: /opt/cliff/src/git/house/node_modules/ikea-tradfri/lib/Tradfri.js:96
Apr 14 11:29:07 pi npm[9533]:                   throw err;
Apr 14 11:29:07 pi npm[9533]:                   ^
Apr 14 11:29:07 pi npm[9533]: Error: unexpected response (4.00) to observeScene(131073, 196621):
Apr 14 11:29:07 pi npm[9533]:     at TradfriClient.handleNonSuccessfulResponse (/opt/cliff/src/git/house/node_modules/node-tradfri-client/build/tradfri-client.js:783:32)
Apr 14 11:29:07 pi npm[9533]:     at TradfriClient.observeScene_callback (/opt/cliff/src/git/house/node_modules/node-tradfri-client/build/tradfri-client.js:631:23)
Apr 14 11:29:07 pi npm[9533]:     at PendingRequest.handleResponse [as callback] (/opt/cliff/src/git/house/node_modules/node-tradfri-client/build/tradfri-client.js:595:41)
Apr 14 11:29:07 pi npm[9533]:     at Function.onMessage (/opt/cliff/src/git/house/node_modules/node-coap-client/build/CoapClient.js:631:33)
Apr 14 11:29:07 pi npm[9533]:     at SocketWrapper.emit (events.js:188:13)
Apr 14 11:29:07 pi npm[9533]:     at SocketWrapper.socket.on (/opt/cliff/src/git/house/node_modules/node-coap-client/build/lib/SocketWrapper.js:12:18)
Apr 14 11:29:07 pi npm[9533]:     at Socket.emit (events.js:188:13)
Apr 14 11:29:07 pi npm[9533]:     at Socket.udp_onMessage (/opt/cliff/src/git/house/node_modules/node-dtls-client/build/dtls.js:189:34)
Apr 14 11:29:07 pi npm[9533]:     at Socket.emit (events.js:188:13)
Apr 14 11:29:07 pi npm[9533]:     at UDP.onMessage (dgram.js:685:8)

This is with node-tradfri-client version v2.1.4.

AlCalzone commented 4 years ago

Good to know! I'll see if I can reproduce it.

AlCalzone commented 4 years ago

@CliffS I guess I still need some info. I've tried with the following code:

// @ts-check

const { TradfriClient, discoverGateway } = require("../../build");
const { wait } = require("alcalzone-shared/async");

async function main() {
    const gwinfo = await discoverGateway();

    const tradfri = new TradfriClient(
        gwinfo.addresses[0],
        (msg, sev) => sev !== "silly" && console.error(msg)
    );

    tradfri.on("error", (err) => console.error(err));

    await tradfri.connect( /* my identity */, /* my PSK */);

    await tradfri.observeGroupsAndScenes();

    await wait(180000);

    tradfri.destroy();
}
main();

and added, edited and deleted a scene while the script was running. Did not see anything error-like. Can you try to provide a minimal example which reproducibly causes the error?