blocking verif pairing without timeout

[NebzHB]

Hi @Apollon77 ,

i encounter some problems on latest version (cannot set from which one...)

if i subscribe 2 times to some characteristics, the POST request to verify pairing just stuck and never respond, would it be possible to make it timeout or something else to receive an error message ?

[10-01-2022 09:16:11]DEBUG : Subscribe to 1.82,1.32,1.33,1.34,1.35,1.36,1.38,1.39,1.40,1.41,1.11,1.12,1.13,1.14,1.63,1.64,1.65,1.66,1.67,1.21 pour VOCOlinc-Flowerbud-0d205d
2022-01-10T08:16:27.947Z hap-controller:http-client Start Pair-Verify process ...
2022-01-10T08:16:27.948Z hap-controller:tlv Add 1 bytes for tag 6: 01
2022-01-10T08:16:27.948Z hap-controller:tlv Add 32 bytes for tag 3: 5ee2f10b2c858dc89e5087860c6bc3ffb86da8bbff959c0b78aef0ea58f7867f
2022-01-10T08:16:27.948Z hap-controller:http-connection 192.168.1.92:80 POST /pair-verify 06010103205ee2f10b2c858dc89e5087860c6bc3ffb86da8bbff959c0b78aef0ea58f7867f
2022-01-10T08:16:28.684Z hap-controller:http-connection 192.168.1.92:80 Response 200 with 140 byte data
2022-01-10T08:16:28.684Z hap-controller:tlv Read 1 bytes for tag 6: 02
2022-01-10T08:16:28.684Z hap-controller:tlv Read 32 bytes for tag 3: c57009838895075701ed4e17a3fdefe16634016beb799e6ff356eb8df4187201
2022-01-10T08:16:28.684Z hap-controller:tlv Read 101 bytes for tag 5: 0604b2baa0efa6db1e715dffeb21d32baa431b282a8e3b7f8753f27cfbd40d3137e866bb30c3d8625a4f7bdae621b8b00953c41a125ea4baabde27cb8e00628120ec00b24daf55be59c738d35bde46a08681f92fe379243466996f408982438ca012c11534
2022-01-10T08:16:28.685Z hap-controller:tlv Read 17 bytes for tag 1: 37453a46343a46343a37453a39323a4246
2022-01-10T08:16:28.685Z hap-controller:tlv Read 64 bytes for tag 10: 4634635feec815cef30d7e352aaf21203c400c3305c9eaa2eeba3b47fe0e7dbd09f5232efa84238993a33fe36dba6d40c99489c43b7d256cde801dadda20f202
2022-01-10T08:16:28.685Z hap-controller:tlv Add 36 bytes for tag 1: 65323163633639312d303032342d343039632d613561652d363932626631333030353266
2022-01-10T08:16:28.685Z hap-controller:tlv Add 64 bytes for tag 10: ffdd7f829066fbd8dda08d41401bc7f51bf07451021b5656b3248161b6315c07412a54ac836773bfc01329ccdf9551bc51c12ab1fd6baef717763c969f811103
2022-01-10T08:16:28.685Z hap-controller:tlv Add 1 bytes for tag 6: 03
2022-01-10T08:16:28.685Z hap-controller:tlv Add 120 bytes for tag 5: 108f669cbf565089b0245bc11d4493bcafc35c7462a951a2d8cb2d0a030da5a70ae8f7a1713e881045b097dcf1989a77010accd7884e2cfb3f934028ce14c9fc231ab7ad4769b251cf8d0110343213c49f0a4c8fa3cea19896fcf521c3c96acd7f4bfad2529d1a7bb4c352bd844fdc09f8e900583e8bbe94
2022-01-10T08:16:28.686Z hap-controller:http-connection 192.168.1.92:80 POST /pair-verify 0601030578108f669cbf565089b0245bc11d4493bcafc35c7462a951a2d8cb2d0a030da5a70ae8f7a1713e881045b097dcf1989a77010accd7884e2cfb3f934028ce14c9fc231ab7ad4769b251cf8d0110343213c49f0a4c8fa3cea19896fcf521c3c96acd7f4bfad2529d1a7bb4c352bd844fdc09f8e900583e8bbe94
2022-01-10T08:16:28.980Z hap-controller:http-connection 192.168.1.92:80 Response 200 with 3 byte data
2022-01-10T08:16:28.980Z hap-controller:tlv Read 1 bytes for tag 6: 04
2022-01-10T08:16:28.980Z hap-controller:http-client Finished Pair-Verify process ...
2022-01-10T08:16:28.980Z hap-controller:http-connection 192.168.1.92:80 GET /accessories
2022-01-10T08:16:29.007Z hap-controller:http-connection 192.168.1.92:80 Response 200 with 4711 byte data

[10-01-2022 09:16:29]DEBUG : Subscribe again to 1.82,1.32,1.33,1.34,1.35,1.36,1.38,1.39,1.40,1.41,1.11,1.12,1.13,1.14,1.63,1.64,1.65,1.66,1.67,1.21 pour VOCOlinc-Flowerbud-0d205d...
2022-01-10T08:16:29.010Z hap-controller:http-client Start Pair-Verify process ...
2022-01-10T08:16:29.010Z hap-controller:tlv Add 1 bytes for tag 6: 01
2022-01-10T08:16:29.010Z hap-controller:tlv Add 32 bytes for tag 3: 3b8bf39779080e87d727dac81675aabd7ec6807765e74cf7412d11e9323a581a
2022-01-10T08:16:29.010Z hap-controller:http-connection 192.168.1.92:80 POST /pair-verify 06010103203b8bf39779080e87d727dac81675aabd7ec6807765e74cf7412d11e9323a581a

and never receive the response...

this problem occurs with multiple devices... i don't understand why...

(FYI : the example on subscribing and unsubscribing characteristics is not accurate anymore (conn return on subscribing + conn parameter when unsubscribing))

[Apollon77]

I will have a look, but in fact it seems that the deice is not responding ... additionally the 0.6 release change the way how subscriptions are handled. SO yes the connection stay internally and is NOT returned anymore and all subscriptions are remembered internally.

It might be that I missed to adjust an example ... will check this too.

But yes missing timeout I will check too

[Apollon77]

mabe the device expects that the existing connection is used? (which is not in any spec .. but ... maybe :-(

[Apollon77]

DO other comand like controlling works whiche having subscribed?

[NebzHB]

you means after the first subscribe ? yes everything works after the second one, my daemon hung on the await subscribeCharacteristics so i'm blocked :(

[NebzHB]

it works in 0.5.0

[Apollon77]

Ahhh I think Isee it ... please try GitHub version

[Apollon77]

Examples also fixed in https://github.com/Apollon77/hap-controller-node/commit/e11f378cb9a2ae3b0a70935b95e5397159607239

[NebzHB]

thx it works !! maybe do that for getAccessories (and getCharacteristics, setCharacteristics, ... etc) too ?

[Apollon77]

It was only relevant for getCharacteristics because only there a pot. existing connection is reused and if a connection exists we should not verify it again ... All other methods alwys create new connections ...

I will release the update soon

[Apollon77]

I also created #80 and #81 for further enhancements

[NebzHB]

Hello, do you know when you will release the current fix ? (to know if I have to do a workaround waiting for that or just wait ;))

[Apollon77]

I currently think to add a queue for peirverify internally to prevent overlapping issues in general - additionalyl to your issue ...

[Apollon77]

@NebzHB COuld you pleasebtry the GitHub version again .. I now added an additional queue for pairVerify calls .. could you try to maybe trigger some calls "kind of in parallel" (not subscribe calls :-)) )

[NebzHB]

Hi,

sorry, i'm not able to trigger some calls in parallel ... but i've tried to remove the if statement around the _pairVerify in subscribe and ask for 2 subscribes, but it still block on the command... should it solve that too ? or is it for another issue ?

[Apollon77]

No the if must not being removed ... ok I will releae qand we will see from others ... the change should not break stuff that was not alreayd broken before ;-)

[NebzHB]

[17-01-2022 08:55:28]INFO : Action received...{"id":"7E:F4:F4:7E:92:BF","aid":"1","iid":"11","val":"1"}
2022-01-17T07:55:28.329Z hap-controller:http-client Start Pair-Verify process ...
2022-01-17T07:55:28.329Z hap-controller:tlv Add 1 bytes for tag 6: 01
2022-01-17T07:55:28.329Z hap-controller:tlv Add 32 bytes for tag 3: afca6606269f6ea1c66e5c42f5564e603c3c2f8bbf03379930aa60429580bf77
2022-01-17T07:55:28.329Z hap-controller:http-connection 192.168.1.92:80 POST /pair-verify 0601010320afca6606269f6ea1c66e5c42f5564e603c3c2f8bbf03379930aa60429580bf77
2022-01-17T07:55:28.914Z hap-controller:http-connection 192.168.1.92:80 Response 200 with 140 byte data
2022-01-17T07:55:28.914Z hap-controller:tlv Read 1 bytes for tag 6: 02
2022-01-17T07:55:28.914Z hap-controller:tlv Read 32 bytes for tag 3: 98cd0cdbe9228dff16b8e861d5ba614a1b8d2bcd77204960deea9e231cc3064e
2022-01-17T07:55:28.914Z hap-controller:tlv Read 101 bytes for tag 5: 3b1910c70e67f6b5297033c0191a571f30ab7a31cb8dfc77ddd857e97f1d59b2729adc0681c9ba62c5690acd876abfd37f680b91a49eed8928570fb422ef5e332dc9f6d20f1eb5ce7fe7b6758dae6a6f5552e822022ed64d60e89cc0991282379f23bb3182
2022-01-17T07:55:28.915Z hap-controller:tlv Read 17 bytes for tag 1: 37453a46343a46343a37453a39323a4246
2022-01-17T07:55:28.915Z hap-controller:tlv Read 64 bytes for tag 10: 871240fc1c51e96b66f153352f2b7740a753926ce07e9e4fd0e82ff112c794f8341a97617bcf341ea253f58a03823664909cb0c65d09473770afe100490ac80f
2022-01-17T07:55:28.915Z hap-controller:tlv Add 36 bytes for tag 1: 36386464626562622d333737302d343062372d623561332d643861353730313439643237
2022-01-17T07:55:28.915Z hap-controller:tlv Add 64 bytes for tag 10: 54087d33e0e3c8d45664e0c389b77352de2d824dec13aaefc7ff7b2a5d48d4a03f1e67c66e66368224d801a5545d4afb8a298547527ed0bd0157c9e23faa6101
2022-01-17T07:55:28.915Z hap-controller:tlv Add 1 bytes for tag 6: 03
2022-01-17T07:55:28.915Z hap-controller:tlv Add 120 bytes for tag 5: 8689b5a205c0da68fe00561ecb009dd8f43029afde1349501ee32ee3219f200b9511d4726b5ede68223516a9f526bcacb5dc0545cad9a6a29a8b8d9e6669a8ea8d4ba04f540a60b73cdad5e9f445f883a4bf919b3065ba791671fb2eb4113ef58ae6c771a2c095e9489afac3dd72310fd720e175084695d7
2022-01-17T07:55:28.915Z hap-controller:http-connection 192.168.1.92:80 POST /pair-verify 06010305788689b5a205c0da68fe00561ecb009dd8f43029afde1349501ee32ee3219f200b9511d4726b5ede68223516a9f526bcacb5dc0545cad9a6a29a8b8d9e6669a8ea8d4ba04f540a60b73cdad5e9f445f883a4bf919b3065ba791671fb2eb4113ef58ae6c771a2c095e9489afac3dd72310fd720e175084695d7
[17-01-2022 08:55:28]INFO : Action received...{"id":"7E:F4:F4:7E:92:BF","aid":"1","iid":"11","val":"0"}
2022-01-17T07:55:29.213Z hap-controller:http-connection 192.168.1.92:80 Response 200 with 3 byte data
2022-01-17T07:55:29.213Z hap-controller:tlv Read 1 bytes for tag 6: 04
2022-01-17T07:55:29.213Z hap-controller:http-client Finished Pair-Verify process ...
2022-01-17T07:55:29.213Z hap-controller:http-client Start Pair-Verify process ...
2022-01-17T07:55:29.213Z hap-controller:http-connection 192.168.1.92:80 PUT /characteristics 7b22636861726163746572697374696373223a5b7b22616964223a312c22696964223a31312c2276616c7565223a747275657d5d7d
2022-01-17T07:55:29.214Z hap-controller:tlv Add 1 bytes for tag 6: 01
2022-01-17T07:55:29.214Z hap-controller:tlv Add 32 bytes for tag 3: eefd2fc41494fd778963e6578bf641fa64df27c8fb6482419f4492afdaac5c58
2022-01-17T07:55:29.214Z hap-controller:http-connection 192.168.1.92:80 POST /pair-verify 0601010320eefd2fc41494fd778963e6578bf641fa64df27c8fb6482419f4492afdaac5c58
2022-01-17T07:55:29.237Z hap-controller:http-connection 192.168.1.92:80 Response 204 with 0 byte data
[17-01-2022 08:55:29]INFO : action done for VOCOlinc-Flowerbud-0d205d : on->true
[17-01-2022 08:55:30]INFO : Event received from VOCOlinc-Flowerbud-0d205d : on=true
2022-01-17T07:55:31.072Z hap-controller:http-connection 192.168.1.92:80 Response 200 with 140 byte data
2022-01-17T07:55:31.072Z hap-controller:tlv Read 1 bytes for tag 6: 02
2022-01-17T07:55:31.072Z hap-controller:tlv Read 32 bytes for tag 3: e1bcff6fe7baee17e897393a6b9cba56932388f467502f5df8f340c0e2ff1210
2022-01-17T07:55:31.072Z hap-controller:tlv Read 101 bytes for tag 5: d419329ed32c62e881f89dba55ba8594308e929894afe90afffff73ab9c6c8a1c79cf07f40f4428f8f4127b1b5205a32e3aa3b295c13b78d0ff8f690aca8007d477ada08cbea237a6710388c19f512872fabb110fb8a7332b24b70473beb8c210e01b03070
2022-01-17T07:55:31.073Z hap-controller:tlv Read 17 bytes for tag 1: 37453a46343a46343a37453a39323a4246
2022-01-17T07:55:31.073Z hap-controller:tlv Read 64 bytes for tag 10: aca868226663aa33826661074e81b758a90c81d1b280a56ffca797b2e57c1230f22199d46a11ec26d92b8aca509f3e7d336283278712a2c13421f74ce90c420a
2022-01-17T07:55:31.073Z hap-controller:tlv Add 36 bytes for tag 1: 36386464626562622d333737302d343062372d623561332d643861353730313439643237
2022-01-17T07:55:31.073Z hap-controller:tlv Add 64 bytes for tag 10: d2d5804ed4a7d315274f01e825d0505a2eea3a932c915f71a53ddf48a216c5c7da237495b30cfe14c71ea1110089e5bf9798fed9f2c25aebe127144fe11d7408
2022-01-17T07:55:31.073Z hap-controller:tlv Add 1 bytes for tag 6: 03
2022-01-17T07:55:31.073Z hap-controller:tlv Add 120 bytes for tag 5: c70e9c1544dfc7ee1d2a7f0f507f7286ac9caeb5feed561d3a84387d01240c23cd55415295639f961e01435bfa09147fea34f2564f5fed4e967dc340f11a86c0fc0988d9649604c8d96c236e6224fac4b35542469f9d56a6f10e54b10f15e94f4a7a12d0e2e9568940e0b4537adbfedf1d0bc2e0c4dde7eb
2022-01-17T07:55:31.073Z hap-controller:http-connection 192.168.1.92:80 POST /pair-verify 0601030578c70e9c1544dfc7ee1d2a7f0f507f7286ac9caeb5feed561d3a84387d01240c23cd55415295639f961e01435bfa09147fea34f2564f5fed4e967dc340f11a86c0fc0988d9649604c8d96c236e6224fac4b35542469f9d56a6f10e54b10f15e94f4a7a12d0e2e9568940e0b4537adbfedf1d0bc2e0c4dde7eb
2022-01-17T07:55:31.369Z hap-controller:http-connection 192.168.1.92:80 Response 200 with 3 byte data
2022-01-17T07:55:31.369Z hap-controller:tlv Read 1 bytes for tag 6: 04
2022-01-17T07:55:31.369Z hap-controller:http-client Finished Pair-Verify process ...
2022-01-17T07:55:31.369Z hap-controller:http-connection 192.168.1.92:80 PUT /characteristics 7b22636861726163746572697374696373223a5b7b22616964223a312c22696964223a31312c2276616c7565223a66616c73657d5d7d
2022-01-17T07:55:31.392Z hap-controller:http-connection 192.168.1.92:80 Response 204 with 0 byte data
[17-01-2022 08:55:31]INFO : action done for VOCOlinc-Flowerbud-0d205d : on->false
[17-01-2022 08:55:32]INFO : Event received from VOCOlinc-Flowerbud-0d205d : on=false

[Apollon77]

Thank you for the log ... this looks fine ... new pair verify is done after first one finished ... no overlappings ... awesome

[NebzHB]

here is some log where i see the queuing in action, making it a few slower than before i think...

[NebzHB]

I don't know the protocol but is the pair-verify mandatory ? or could it be passed if the pairing is ok or if the pair is not too old or something ?

[Apollon77]

Slower maybe .. but in fact the definition is clear ... "PairVerify request must not overlap from same controller" ... so thi si sthe better approach I think - and in fact the requests overlap ... so the "put" is executed on one connection while the second connection is doing pairverify ...

I don't know the protocol but is the pair-verify mandatory ? or could it be passed if the pairing is ok or if the pair is not too old or something ?

Each connection which requires security authentication (like PUT characteristic) needs to be "pair verified". The alternative is to use "persistent connections" - so only one connection to the device which is kept alive ... but then all commands needs to be queued there which will also lead to a delay ... but a much smaller delay becaus ethe actions are usually faster then a pair verify ... but will "bind" one connection ... I will create an issue to implement persistent connection

[NebzHB]

thank you for your explaination, can't wait the release :)

[NebzHB]

Hello, do you have news about the release ?

[Apollon77]

preparing a bigger update, so have a new thing to test hopefully later today or tomorrow. I added better command queuing and fixed some connection leaks and added persistent connections to ideally remove the need of all these pairVerifies

[Apollon77]

@NebzHB Could you give githib version a try if all is good for you please before I release? I test in parallel some more too. Changes see CHangelog in readme

[Apollon77]

PS: If you like also try the new persistent Connection feature (see https://github.com/Apollon77/hap-controller-node/blob/main/examples/ip/get-characteristics.js#L21)

[NebzHB]

just two questions about persistent connection, when should it be used and not ? (to know when i should enable it in my plugin) and when to close it ? (you said when not needed...) I've made a daemon, should i just close it on exit ? the client is kept in the global vars, or should i test isConnected on each call ?

[Apollon77]

In my eyes it makes sense to always use the persistent connection. Then the process will have one "standing" connection to the device. When this is disconnected all is fine and it will be re-established on next command, so nothign to worry about. In fact without persistent each command opens a new connection and needs to do a pairVerify first (needs 1s on my hue bridge ... the command afterwards needs 100ms or such) :-)) For subscriptions and pairing process own connections are used.

The "close" is needed when you want to "end the communication with the device", so on exit is enough.

And no, you do not need to check isCOnnected ... library handles that automatically and will create new connection if needed ... you ccan use debug mode to see when he does new connection vs. reuse old one

[Apollon77]

PS @NebzHB Is the lib version working for you? If yes then I release ... for me it works

[NebzHB]

yes it does works fine from my tests ! thank you it seems a big leap forward :) i'll set the persistent connections in my code !

[NebzHB]

wow, commands are stunning fast now !

is there a reason some example are not yet using the persistant connections ? or there is maybe some reasons to do that sometimes ?

[Apollon77]

wow, commands are stunning fast now !

Great to hear!

is there a reason some example are not yet using the persistant connections ? or there is maybe some reasons to do that sometimes ?

Hm not really ... I just added it to one example as example andto wait for feedback first, will consider for next version.

Deploy on it's way (hopefully ... sometimes the windows hosts error out ... lets see :-)) ) https://github.com/Apollon77/hap-controller-node/actions/runs/1729041414

[NebzHB]

:( it seems it failed

[Apollon77]

released in the meantime