node-tradfri-client icon indicating copy to clipboard operation
node-tradfri-client copied to clipboard

Published 20 hours ago • verified publisher icon AlCalzone

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

Open CliffS opened this issue 6 years ago • 16 comments

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?

CliffS avatar Mar 07 '18 09:03 CliffS

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

AlCalzone avatar Mar 07 '18 09:03 AlCalzone

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

CliffS avatar Mar 07 '18 09:03 CliffS

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

AlCalzone avatar Mar 07 '18 09:03 AlCalzone

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

CliffS avatar Mar 07 '18 09:03 CliffS

Ok, please check your logs with this version: c6a6967

AlCalzone avatar Mar 07 '18 09:03 AlCalzone

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.

AlCalzone avatar Mar 07 '18 09:03 AlCalzone

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

Thanks.

CliffS avatar Mar 07 '18 10:03 CliffS

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?

CliffS avatar Mar 09 '18 11:03 CliffS

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.

AlCalzone avatar Mar 09 '18 11:03 AlCalzone

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 avatar Mar 15 '18 17:03 CliffS

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! :)

CliffS avatar Dec 25 '19 07:12 CliffS

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 avatar Feb 03 '20 15:02 AlCalzone

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.

AlCalzone avatar Mar 03 '20 16:03 AlCalzone

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.

CliffS avatar Apr 14 '20 09:04 CliffS

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

AlCalzone avatar Apr 14 '20 09:04 AlCalzone

@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?

AlCalzone avatar Apr 19 '20 17:04 AlCalzone