Bridge is not pairing with multiple accessories

[Roba1993]

Hi,

the pairing is not working when in the config a bridge (or lightbulb) is defined and multiple accessories are added.
Do you have an idea where this needs to be addressed in the code?

Thanks,
Robert

[ewilken]

Thanks for sharing!

This was most likely due to the BridgeAccessory not being reimplemented yet since the rewrite. Oops. Fixed that & added an example for bridged accessories.

When adding multiple accessories to a server, the first one is turned into the bridge accessory. So it makes sense to use the BridgeAccessory there, which just exposes an AccessoryInformationService and nothing else.

Let me know if this works for you and feel free to open more issues should you run into any other quirks!

[Roba1993]

@ewilken Thanks for the support :)
Bridge is pairing and working, but the restart is failing...
Following the log:

Start Service
[2020-07-21T07:58:36Z INFO  hap::transport::http::server] binding TCP listener on 192.168.178.22:32000
[2020-07-21T07:58:36Z DEBUG hap::transport::mdns] announcing mDNS: ["md=DigitalStrom", "id=0a:14:1e:28:32:3c", "c#=4", "s#=1", "ci=2", "pv=1.0", "sf=1", "ff=0"]
[2020-07-21T07:58:36Z DEBUG hap::transport::http::server] incoming TCP stream from 192.168.178.22:56707
[2020-07-21T07:58:36Z DEBUG hap::transport::tcp] polling incoming TCP stream receiver
[2020-07-21T07:58:36Z DEBUG hap::transport::tcp] received 163 Bytes on incoming TCP stream receiver
[2020-07-21T07:58:36Z DEBUG hap::transport::tcp] polling incoming TCP stream receiver
[2020-07-21T07:58:36Z DEBUG hap::transport::tcp] incoming TCP stream error: receiver channel is empty
[2020-07-21T07:58:36Z DEBUG hap::transport::http::handler::pair_verify] received body: [6, 1, 1, 3, 32, 95, 178, 0, 5, 199, 235, 189, 156, 241, 35, 245, 59, 190, 91, 160, 217, 91, 126, 105, 239, 73, 98, 210, 147, 161, 218, 151, 184, 182, 34, 234, 105]
[2020-07-21T07:58:36Z INFO  hap::transport::http::handler::pair_verify] pair verify M1: received verify start request
[2020-07-21T07:58:36Z INFO  hap::transport::http::handler::pair_verify] pair verify M2: sending verify start response
[2020-07-21T07:58:36Z DEBUG hap::transport::tcp] writing 117 Bytes to outgoing TCP stream sender
[2020-07-21T07:58:36Z DEBUG hap::transport::tcp] wrote 117 Bytes to outgoing TCP stream sender
[2020-07-21T07:58:36Z DEBUG hap::transport::tcp] writing 140 Bytes to outgoing TCP stream sender
[2020-07-21T07:58:36Z DEBUG hap::transport::tcp] wrote 140 Bytes to outgoing TCP stream sender
[2020-07-21T07:58:36Z DEBUG hap::transport::tcp] writing 117 Bytes to outgoing TCP stream
[2020-07-21T07:58:36Z DEBUG hap::transport::tcp] wrote 117 Bytes to outgoing TCP stream
[2020-07-21T07:58:36Z DEBUG hap::transport::tcp] writing 140 Bytes to outgoing TCP stream
[2020-07-21T07:58:36Z DEBUG hap::transport::tcp] wrote 140 Bytes to outgoing TCP stream
[2020-07-21T07:58:36Z DEBUG hap::transport::tcp] polling incoming TCP stream receiver
[2020-07-21T07:58:36Z DEBUG hap::transport::tcp] incoming TCP stream error: receiver channel is empty
[2020-07-21T07:58:36Z DEBUG hap::transport::tcp] polling incoming TCP stream receiver
[2020-07-21T07:58:36Z DEBUG hap::transport::tcp] incoming TCP stream error: receiver channel is empty
[2020-07-21T07:58:36Z DEBUG hap::transport::tcp] polling incoming TCP stream receiver
[2020-07-21T07:58:36Z DEBUG hap::transport::tcp] received 252 Bytes on incoming TCP stream receiver
[2020-07-21T07:58:36Z DEBUG hap::transport::tcp] polling incoming TCP stream receiver
[2020-07-21T07:58:36Z DEBUG hap::transport::tcp] incoming TCP stream error: receiver channel is empty
[2020-07-21T07:58:36Z DEBUG hap::transport::http::handler::pair_verify] received body: [5, 120, 99, 38, 160, 28, 164, 227, 231, 110, 109, 81, 161, 152, 42, 227, 230, 45, 54, 142, 236, 82, 42, 52, 98, 11, 2, 133, 140, 199, 184, 167, 94, 18, 176, 49, 192, 160, 64, 196, 43, 51, 240, 152, 121, 134, 131, 61, 78, 252, 208, 156, 157, 10, 195, 249, 127, 155, 11, 32, 103, 50, 174, 108, 243, 193, 141, 169, 12, 237, 110, 9, 176, 207, 51, 244, 125, 197, 200, 239, 26, 195, 239, 199, 7, 168, 41, 36, 19, 231, 65, 195, 221, 233, 239, 109, 62, 90, 242, 169, 21, 51, 102, 183, 241, 98, 47, 167, 133, 117, 116, 213, 155, 118, 145, 60, 94, 68, 83, 18, 128, 207, 6, 1, 3]
[2020-07-21T07:58:36Z INFO  hap::transport::http::handler::pair_verify] pair verify M3: received verify finish request
[2020-07-21T07:58:36Z DEBUG hap::transport::http::handler::pair_verify] received sub-TLV: {1: [65, 49, 55, 67, 57, 50, 49, 57, 45, 52, 55, 68, 49, 45, 52, 48, 65, 54, 45, 65, 49, 52, 51, 45, 69, 55, 55, 49, 66, 53, 52, 65, 66, 67, 68, 48], 10: [13, 211, 88, 144, 0, 4, 101, 217, 206, 50, 243, 195, 33, 138, 69, 136, 184, 164, 36, 201, 244, 92, 113, 198, 65, 161, 218, 252, 91, 251, 24, 16, 16, 211, 240, 174, 188, 120, 7, 8, 165, 255, 177, 26, 106, 160, 215, 186, 189, 75, 128, 128, 152, 115, 235, 255, 149, 145, 42, 175, 187, 40, 151, 9]}
[2020-07-21T07:58:36Z DEBUG hap::transport::http::handler::pair_verify] raw device pairing ID: [65, 49, 55, 67, 57, 50, 49, 57, 45, 52, 55, 68, 49, 45, 52, 48, 65, 54, 45, 65, 49, 52, 51, 45, 69, 55, 55, 49, 66, 53, 52, 65, 66, 67, 68, 48]
[2020-07-21T07:58:36Z DEBUG hap::transport::http::handler::pair_verify] device signature: ed25519::Signature([13, 211, 88, 144, 0, 4, 101, 217, 206, 50, 243, 195, 33, 138, 69, 136, 184, 164, 36, 201, 244, 92, 113, 198, 65, 161, 218, 252, 91, 251, 24, 16, 16, 211, 240, 174, 188, 120, 7, 8, 165, 255, 177, 26, 106, 160, 215, 186, 189, 75, 128, 128, 152, 115, 235, 255, 149, 145, 42, 175, 187, 40, 151, 9])
[2020-07-21T07:58:36Z DEBUG hap::transport::http::handler::pair_verify] device pairing UUID: a17c9219-47d1-40a6-a143-e771b54abcd0
[2020-07-21T07:58:36Z DEBUG hap::transport::tcp] polling incoming TCP stream receiver
[2020-07-21T07:58:36Z DEBUG hap::transport::tcp] incoming TCP stream error: receiver channel is empty
[2020-07-21T07:58:36Z DEBUG hap::transport::tcp] polling incoming TCP stream receiver
[2020-07-21T07:58:36Z DEBUG hap::transport::tcp] incoming TCP stream error: receiver channel is empty
[2020-07-21T07:58:36Z DEBUG hap::transport::http::handler::pair_verify] loaded pairing: Pairing { id: a17c9219-47d1-40a6-a143-e771b54abcd0, permissions: Admin, public_key: [68, 248, 84, 15, 172, 220, 170, 219, 155, 195, 158, 97, 88, 17, 100, 88, 86, 115, 239, 44, 245, 56, 114, 165, 219, 251, 132, 156, 164, 187, 109, 59] }
[2020-07-21T07:58:36Z INFO  hap::transport::http::handler::pair_verify] pair verify M4: sending verify finish response
[2020-07-21T07:58:36Z DEBUG hap::transport::tcp] writing 118 Bytes to outgoing TCP stream sender
[2020-07-21T07:58:36Z DEBUG hap::transport::tcp] wrote 118 Bytes to outgoing TCP stream sender
[2020-07-21T07:58:36Z DEBUG hap::transport::tcp] writing 118 Bytes to outgoing TCP stream
[2020-07-21T07:58:36Z DEBUG hap::transport::tcp] wrote 118 Bytes to outgoing TCP stream
[2020-07-21T07:58:36Z DEBUG hap::transport::tcp] reading from decrypted buffer
[2020-07-21T07:58:36Z DEBUG hap::transport::tcp] reading from encrypted buffer
[2020-07-21T07:58:36Z DEBUG hap::transport::tcp] reading from TCP stream
[2020-07-21T07:58:36Z DEBUG hap::transport::tcp] polling incoming TCP stream receiver
[2020-07-21T07:58:36Z DEBUG hap::transport::tcp] incoming TCP stream error: receiver channel is empty
[2020-07-21T07:58:36Z DEBUG hap::transport::tcp] reading from decrypted buffer
[2020-07-21T07:58:36Z DEBUG hap::transport::tcp] reading from encrypted buffer
[2020-07-21T07:58:36Z DEBUG hap::transport::tcp] reading from TCP stream
[2020-07-21T07:58:36Z DEBUG hap::transport::tcp] reading from encrypted buffer
[2020-07-21T07:58:36Z DEBUG hap::transport::tcp] reading from decrypted buffer
[2020-07-21T07:58:36Z DEBUG hap::transport::tcp] reading from decrypted buffer
[2020-07-21T07:58:36Z DEBUG hap::transport::tcp] reading from encrypted buffer
[2020-07-21T07:58:36Z DEBUG hap::transport::tcp] reading from TCP stream
[2020-07-21T07:58:36Z DEBUG hap::transport::tcp] polling incoming TCP stream receiver
[2020-07-21T07:58:36Z DEBUG hap::transport::tcp] received 65 Bytes on incoming TCP stream receiver
[2020-07-21T07:58:36Z DEBUG hap::transport::tcp] polling incoming TCP stream receiver
[2020-07-21T07:58:36Z DEBUG hap::transport::tcp] incoming TCP stream error: receiver channel is empty
[2020-07-21T07:58:36Z INFO  hap::transport::http::handler::accessories] received list accessories request
[2020-07-21T07:58:36Z DEBUG hap::storage::accessory_list] accessory list JSON: {"accessories":[{"aid":1,"services":[{"characteristics":[{"format":"bool","iid":2,"perms":["pw"],"type":"14"},{"format":"string","iid":3,"perms":["pr"],"type":"20","value":"undefined"},{"format":"string","iid":4,"perms":["pr"],"type":"21","value":"undefined"},{"format":"string","iid":5,"perms":["pr"],"type":"23","value":"Acme Bridge"},{"format":"string","iid":6,"maxLen":64,"perms":["pr"],"type":"30","value":"undefined"},{"format":"string","iid":7,"perms":["pr"],"type":"52","value":"undefined"}],"hidden":false,"iid":1,"primary":false,"type":"3E"}]},{"aid":2,"services":[{"characteristics":[{"format":"bool","iid":2,"perms":["pw"],"type":"14"},{"format":"string","iid":3,"perms":["pr"],"type":"20","value":"undefined"},{"format":"string","iid":4,"perms":["pr"],"type":"21","value":"undefined"},{"format":"string","iid":5,"perms":["pr"],"type":"23","value":"Light 1"},{"format":"string","iid":6,"maxLen":64,"perms":["pr"],"type":"30","value":"undefined"},{"format":"string","iid":7,"perms":["pr"],"type":"52","value":"undefined"}],"hidden":false,"iid":1,"primary":false,"type":"3E"},{"characteristics":[{"format":"bool","iid":9,"perms":["pr","pw","ev"],"type":"25","value":false}],"hidden":false,"iid":8,"primary":true,"type":"43"}]},{"aid":3,"services":[{"characteristics":[{"format":"bool","iid":2,"perms":["pw"],"type":"14"},{"format":"string","iid":3,"perms":["pr"],"type":"20","value":"undefined"},{"format":"string","iid":4,"perms":["pr"],"type":"21","value":"undefined"},{"format":"string","iid":5,"perms":["pr"],"type":"23","value":"Light 2"},{"format":"string","iid":6,"maxLen":64,"perms":["pr"],"type":"30","value":"undefined"},{"format":"string","iid":7,"perms":["pr"],"type":"52","value":"undefined"}],"hidden":false,"iid":1,"primary":false,"type":"3E"},{"characteristics":[{"format":"bool","iid":9,"perms":["pr","pw","ev"],"type":"25","value":false}],"hidden":false,"iid":8,"primary":true,"type":"43"}]}]}
[2020-07-21T07:58:36Z DEBUG hap::transport::tcp] writing 2035 Bytes to outgoing TCP stream sender
[2020-07-21T07:58:36Z DEBUG hap::transport::tcp] wrote 2035 Bytes to outgoing TCP stream sender
[2020-07-21T07:58:36Z DEBUG hap::transport::tcp] writing 2035 Bytes to outgoing TCP stream
[2020-07-21T07:58:36Z DEBUG hap::transport::tcp] wrote 2035 Bytes to outgoing TCP stream
[2020-07-21T07:58:36Z DEBUG hap::transport::tcp] reading from decrypted buffer
[2020-07-21T07:58:36Z DEBUG hap::transport::tcp] reading from encrypted buffer
[2020-07-21T07:58:36Z DEBUG hap::transport::tcp] reading from TCP stream
[2020-07-21T07:58:36Z DEBUG hap::transport::tcp] polling incoming TCP stream receiver
[2020-07-21T07:58:36Z DEBUG hap::transport::tcp] incoming TCP stream error: receiver channel is empty
[2020-07-21T07:58:36Z DEBUG hap::transport::tcp] reading from decrypted buffer
[2020-07-21T07:58:36Z DEBUG hap::transport::tcp] reading from encrypted buffer
[2020-07-21T07:58:36Z DEBUG hap::transport::tcp] reading from TCP stream
[2020-07-21T07:58:36Z DEBUG hap::transport::tcp] polling incoming TCP stream receiver
[2020-07-21T07:58:36Z DEBUG hap::transport::tcp] incoming TCP stream error: receiver channel is empty
[2020-07-21T07:58:37Z DEBUG hap::transport::mdns] announcing mDNS: ["md=DigitalStrom", "id=0a:14:1e:28:32:3c", "c#=4", "s#=1", "ci=2", "pv=1.0", "sf=1", "ff=0"]

It's seems like the accessories are not getting recognized correctly?

Thanks,
Robert

[Roba1993]

@ewilken Can you support here?

I unfortunatelly don't have the specification, so I can't do it myself.
Where do you took the specification from?

[ewilken]

Sorry for the unresponsiveness!

The specification is available here.

I can indeed reproduce your issue.

An issue I still need to figure out that could be causing these kind of bugs and is blocking an actual release to me is how to persist the structure of accessories added to the server properly over restarts, so that hard-coded add_accessory() calls produce a consistent accessory list with correct aids & iids over program restarts.

We also need to ensure that the BonjourStatusFlag is persisted correctly to the Config after pairing the first and unpairing the last controller.

I'm hoping to find the time to work on this soon. For the time being, ideas and contributions are of course always welcome!

[ewilken]

But I can't seem to reproduce it consistently. Sometimes it just works and the controller connects back after reopening the Home app or trying to write a characteristic, sometimes it doesn't. 🤔 Will try to investigate further.

[Roba1993]

Hm, for me it´s happining right now all the time.
I have an bridge with 12 additional lights.

the config.json looks like the following

{
  "socket_addr": "192.168.178.22:32000",
  "pin": {
    "pin": [1,1,1,2,2,3,3,3]
  },
  "name": "Digital Strom Bridge",
  "device_id": "0a-14-1e-28-32-3c",
  "device_ed25519_keypair":[ 245,155,183,130,6,161,232,131,182,182,176,240,165,118,60,214,232,214,65,38,206,104,10,212,53,157,70,196,99,10,45,144,199,230,251,17,220,235,185,219,241,189,243,146,238,179,27,69,167,15,180,214,236,243,47,104,201,176,186,61,5,238,228,12],
  "configuration_number": 28,
  "state_number": 1,
  "category": "Bridge",
  "protocol_version": "1.0",
  "status_flag": "NotPaired",
  "feature_flag": "Zero",
  "max_peers": null
}

Then there is a a17c9219-47d1-40a6-a143-e771b54abcd0.json with

{"id":"a17c9219-47d1-40a6-a143-e771b54abcd0","permissions":"0x01","public_key":[68,248,84,15,172,220,170,219,155,195,158,97,88,17,100,88,86,115,239,44,245,56,114,165,219,251,132,156,164,187,109,59]}

And a a0dbf194-6eff-4264-a95c-5497660fedeb.json with

{"id":"a0dbf194-6eff-4264-a95c-5497660fedeb","permissions":"0x00","public_key":[51,126,45,93,0,206,82,247,130,184,59,70,86,60,65,237,210,149,109,93,36,95,135,70,117,132,194,90,38,221,157,31]}

Which is a little bit confusing why there are two public keys created....

[ewilken]

a17c9219-47d1-40a6-a143-e771b54abcd0 is probably the controller you used to pair with the server and a0dbf194-6eff-4264-a95c-5497660fedeb is probably another controller (or person) that has access to your HomeKit home. The way the pairing process works is that the pairing controller adds the other controllers of the home to the server after a successful pairing process.

Would you mind trying if this issue still occurs with v0.1.0-pre.7? To me, bridged accessories seem to be working fine now.

[ewilken]

Closing. Feel free to reopen should you encounter this again!