search

Bouke / HAP

Swift implementation of the Homekit Accessory Protocol
https://boukehaarsma.nl/HAP/
MIT License
364 stars 50 forks source link

NIO stack - decryption failing #77

Closed gbrooker closed 5 years ago

gbrooker commented 5 years ago

I'm moving my project over to the new master, but am seeing issues with the NIO stack. I am able to pair with a controller, but HAP gets into an infinite loop reverifying connections over and over, preceded by the following message:

[hap.nio|WARNING] Could not decrypt message from [IPv6]::ffff:10.0.8.144/::ffff:10.0.8.144:62546, closing connection.

Here is a log extract after pairing. The bridge worked fine in the same HomeKit network and config with the previous network stack. Any pointers on where to look in the NIO code for what is causing this problem ?

[hap.controllers.pair-verify|DEBUG] startRequest result: [(HAP.PairTag.identifier, 17 bytes), (HAP.PairTag.signature, 64 bytes)]
[hap.controllers.pair-verify|DEBUG] startRequest result: [(HAP.PairTag.identifier, 17 bytes), (HAP.PairTag.signature, 64 bytes)]
[hap.controllers.pair-verify|DEBUG] startRequest encrypted result: [(HAP.PairTag.state, 1 bytes), (HAP.PairTag.publicKey, 32 bytes), (HAP.PairTag.encryptedData, 101 bytes)]
[hap.controllers.pair-verify|DEBUG] startRequest encrypted result: [(HAP.PairTag.state, 1 bytes), (HAP.PairTag.publicKey, 32 bytes), (HAP.PairTag.encryptedData, 101 bytes)]
[hap.endpoints|INFO] [IPv6]::ffff:10.0.8.8/::ffff:10.0.8.8:50174 POST /pair-verify 200 140
[hap.endpoints|INFO] [IPv6]::ffff:10.0.8.129/::ffff:10.0.8.129:61615 POST /pair-verify 200 140
[hap.controllers.pair-verify|DEBUG] --> username EC48906B-6BEB-4265-97E7-08ADD3E17285
[hap.controllers.pair-verify|DEBUG] --> signature bce6131ba373bc8398c55959d3ca62380975a39a58839d0b1b7023f1b46562e7089039e31d9afd897105d3dbee294715d942fe90455e0f869e2a94b86f8b470d
[hap.controllers.pair-verify|DEBUG] --> public key effeff36f977b12c5ecf7cc536d3bcf9eabc41295768fa88815f4249d205c042
[hap.controllers.pair-verify|INFO] Pair verify completed
[hap.endpoints|INFO] [IPv6]::ffff:10.0.8.8/::ffff:10.0.8.8:50174 POST /pair-verify 200 3
[hap.encryption|INFO] Decrypt message #0, length: 95
[hap.endpoints|INFO] [IPv6]::ffff:10.0.8.8/::ffff:10.0.8.8:50174 GET /accessories 200 11414
[hap.encryption|INFO] Encrypt message #0, length: 139
[hap.encryption|INFO] Encrypt message #1, length: 11414
[hap.encryption|INFO] Encrypt message #13, length: 0
[hap.controllers.pair-verify|DEBUG] --> username EC48906B-6BEB-4265-97E7-08ADD3E17285
[hap.controllers.pair-verify|DEBUG] --> signature c65026bf90f4de0ffb1bac0b449b21587710731c7fb2383139848ed9b37d23e5c830ec9d967f8c4fe9f60025078927098c7e7c1b4e9a6c0c007163e86e76fc0e
[hap.controllers.pair-verify|DEBUG] --> public key effeff36f977b12c5ecf7cc536d3bcf9eabc41295768fa88815f4249d205c042
[hap.controllers.pair-verify|INFO] Pair verify completed
[hap.endpoints|INFO] [IPv6]::ffff:10.0.8.129/::ffff:10.0.8.129:61615 POST /pair-verify 200 3
[hap.encryption|INFO] Decrypt message #0, length: 95
[hap.endpoints|INFO] [IPv6]::ffff:10.0.8.129/::ffff:10.0.8.129:61615 GET /accessories 200 11414
[hap.encryption|INFO] Encrypt message #0, length: 139
[hap.encryption|INFO] Encrypt message #1, length: 11414
[hap.encryption|INFO] Encrypt message #13, length: 0
[hap.controllers.pair-verify|DEBUG] startRequest result: [(HAP.PairTag.identifier, 17 bytes), (HAP.PairTag.signature, 64 bytes)]
[hap.controllers.pair-verify|DEBUG] startRequest encrypted result: [(HAP.PairTag.state, 1 bytes), (HAP.PairTag.publicKey, 32 bytes), (HAP.PairTag.encryptedData, 101 bytes)]
[hap.endpoints|INFO] [IPv6]::ffff:10.0.8.121/::ffff:10.0.8.121:54402 POST /pair-verify 200 140
[hap.controllers.pair-verify|DEBUG] startRequest result: [(HAP.PairTag.identifier, 17 bytes), (HAP.PairTag.signature, 64 bytes)]
[hap.controllers.pair-verify|DEBUG] startRequest encrypted result: [(HAP.PairTag.state, 1 bytes), (HAP.PairTag.publicKey, 32 bytes), (HAP.PairTag.encryptedData, 101 bytes)]
[hap.endpoints|INFO] [IPv6]::ffff:10.0.8.144/::ffff:10.0.8.144:62546 POST /pair-verify 200 140
[hap.controllers.pair-verify|DEBUG] --> username EC48906B-6BEB-4265-97E7-08ADD3E17285
[hap.controllers.pair-verify|DEBUG] --> signature e3997b59368143de8abdb984cbe40b55d06d275f6330f110b12106cf216193d0fb1bb263bad0ba5a15c5f36186e0735d46a5c3f5b4180bc4931703583f28c100
[hap.controllers.pair-verify|DEBUG] --> public key effeff36f977b12c5ecf7cc536d3bcf9eabc41295768fa88815f4249d205c042
[hap.controllers.pair-verify|INFO] Pair verify completed
[hap.endpoints|INFO] [IPv6]::ffff:10.0.8.121/::ffff:10.0.8.121:54402 POST /pair-verify 200 3
[hap.encryption|INFO] Decrypt message #0, length: 95
[hap.endpoints|INFO] [IPv6]::ffff:10.0.8.121/::ffff:10.0.8.121:54402 GET /accessories 200 11414
[hap.encryption|INFO] Encrypt message #0, length: 139
[hap.encryption|INFO] Encrypt message #1, length: 11414
[hap.encryption|INFO] Encrypt message #13, length: 0
[hap.controllers.pair-verify|DEBUG] --> username EC48906B-6BEB-4265-97E7-08ADD3E17285
[hap.controllers.pair-verify|DEBUG] --> signature 9e2e43882e426689271e54e3c42ccef78d9e098e812673ea643ac11be8f25cfa27c98a152bb0884b22615aa941ba1525270c05e7773d3072f9127acb1d029802
[hap.controllers.pair-verify|DEBUG] --> public key effeff36f977b12c5ecf7cc536d3bcf9eabc41295768fa88815f4249d205c042
[hap.controllers.pair-verify|INFO] Pair verify completed
[hap.endpoints|INFO] [IPv6]::ffff:10.0.8.144/::ffff:10.0.8.144:62546 POST /pair-verify 200 3
[hap.encryption|INFO] Decrypt message #0, length: 95
[hap.endpoints|INFO] [IPv6]::ffff:10.0.8.144/::ffff:10.0.8.144:62546 GET /accessories 200 11414
[hap.encryption|INFO] Encrypt message #0, length: 139
[hap.encryption|INFO] Encrypt message #1, length: 11414
[hap.encryption|INFO] Encrypt message #13, length: 0
[hap.controllers.pair-verify|DEBUG] startRequest result: [(HAP.PairTag.identifier, 17 bytes), (HAP.PairTag.signature, 64 bytes)]
[hap.controllers.pair-verify|DEBUG] startRequest encrypted result: [(HAP.PairTag.state, 1 bytes), (HAP.PairTag.publicKey, 32 bytes), (HAP.PairTag.encryptedData, 101 bytes)]
[hap.endpoints|INFO] [IPv6]::ffff:10.0.8.116/::ffff:10.0.8.116:55837 POST /pair-verify 200 140
[hap.controllers.pair-verify|DEBUG] --> username EC48906B-6BEB-4265-97E7-08ADD3E17285
[hap.controllers.pair-verify|DEBUG] --> signature 6a1a766e5e355f7ae1a3ac0b0d84c17908a3207951c1a1c2156c6b7240b46999b0aaa4742428042899c68959358937211745be15e0aa766c4330847ca839a70e
[hap.controllers.pair-verify|DEBUG] --> public key effeff36f977b12c5ecf7cc536d3bcf9eabc41295768fa88815f4249d205c042
[hap.controllers.pair-verify|INFO] Pair verify completed
[hap.endpoints|INFO] [IPv6]::ffff:10.0.8.116/::ffff:10.0.8.116:55837 POST /pair-verify 200 3
[hap.encryption|INFO] Decrypt message #0, length: 95
[hap.endpoints|INFO] [IPv6]::ffff:10.0.8.116/::ffff:10.0.8.116:55837 GET /accessories 200 11414
[hap.encryption|INFO] Encrypt message #0, length: 139
[hap.encryption|INFO] Encrypt message #1, length: 11414
[hap.encryption|INFO] Encrypt message #13, length: 0
[hap.encryption|INFO] Decrypt message #1, length: 205
[hap.endpoints.characteristics|DEBUG] PUT data: Optional("{\"characteristics\":[{\"aid\":25,\"iid\":9,\"ev\":true}]}")
[hap.endpoints.characteristics|DEBUG] Added listener for HAP.GenericCharacteristic<Swift.Bool>
[hap.endpoints|INFO] [IPv6]::ffff:10.0.8.144/::ffff:10.0.8.144:62546 PUT /characteristics 204 0
[hap.encryption|INFO] Encrypt message #14, length: 88
[hap.encryption|INFO] Decrypt message #1, length: 205
[hap.endpoints.characteristics|DEBUG] PUT data: Optional("{\"characteristics\":[{\"aid\":25,\"iid\":9,\"ev\":true}]}")
[hap.endpoints.characteristics|DEBUG] Added listener for HAP.GenericCharacteristic<Swift.Bool>
[hap.endpoints|INFO] [IPv6]::ffff:10.0.8.121/::ffff:10.0.8.121:54402 PUT /characteristics 204 0
[hap.encryption|INFO] Encrypt message #14, length: 88
[hap.encryption|INFO] Decrypt message #1, length: 205
[hap.endpoints.characteristics|DEBUG] PUT data: Optional("{\"characteristics\":[{\"aid\":25,\"iid\":9,\"ev\":true}]}")
[hap.endpoints.characteristics|DEBUG] Added listener for HAP.GenericCharacteristic<Swift.Bool>
[hap.endpoints|INFO] [IPv6]::ffff:10.0.8.116/::ffff:10.0.8.116:55837 PUT /characteristics 204 0
[hap.encryption|INFO] Encrypt message #14, length: 88
[hap.encryption|INFO] Decrypt message #1, length: 236
[hap.endpoints.characteristics|DEBUG] PUT data: Optional("{\"characteristics\":[{\"aid\":24,\"iid\":13,\"ev\":true},{\"aid\":24,\"iid\":23,\"ev\":true}]}")
[hap.endpoints.characteristics|DEBUG] Added listener for HAP.GenericCharacteristic<Swift.String>
[hap.endpoints.characteristics|DEBUG] Added listener for HAP.GenericCharacteristic<Swift.String>
[hap.endpoints|INFO] [IPv6]::ffff:10.0.8.8/::ffff:10.0.8.8:50174 PUT /characteristics 204 0
[hap.encryption|INFO] Encrypt message #14, length: 88
[hap.encryption|INFO] Decrypt message #2, length: 387
[hap.endpoints.characteristics|DEBUG] PUT data: Optional("{\"characteristics\":[{\"aid\":23,\"iid\":30,\"ev\":true},{\"aid\":23,\"iid\":37,\"ev\":true},{\"aid\":23,\"iid\":51,\"ev\":true},{\"aid\":23,\"iid\":23,\"ev\":true},{\"aid\":23,\"iid\":13,\"ev\":true},{\"aid\":23,\"iid\":44,\"ev\":true},{\"aid\":23,\"iid\":58,\"ev\":true}]}")
[hap.endpoints.characteristics|DEBUG] Added listener for HAP.GenericCharacteristic<Swift.String>
[hap.endpoints.characteristics|DEBUG] Added listener for HAP.GenericCharacteristic<Swift.String>
[hap.endpoints.characteristics|DEBUG] Added listener for HAP.GenericCharacteristic<Swift.String>
[hap.endpoints.characteristics|DEBUG] Added listener for HAP.GenericCharacteristic<Swift.String>
[hap.endpoints.characteristics|DEBUG] Added listener for HAP.GenericCharacteristic<Swift.String>
[hap.endpoints.characteristics|DEBUG] Added listener for HAP.GenericCharacteristic<Swift.String>
[hap.endpoints.characteristics|DEBUG] Added listener for HAP.GenericCharacteristic<Swift.String>
[hap.endpoints|INFO] [IPv6]::ffff:10.0.8.8/::ffff:10.0.8.8:50174 PUT /characteristics 204 0
[hap.encryption|INFO] Encrypt message #15, length: 88
[hap.encryption|INFO] Decrypt message #1, length: 236
[hap.endpoints.characteristics|DEBUG] PUT data: Optional("{\"characteristics\":[{\"aid\":24,\"iid\":13,\"ev\":true},{\"aid\":24,\"iid\":23,\"ev\":true}]}")
[hap.endpoints.characteristics|DEBUG] Added listener for HAP.GenericCharacteristic<Swift.String>
[hap.endpoints.characteristics|DEBUG] Added listener for HAP.GenericCharacteristic<Swift.String>
[hap.endpoints|INFO] [IPv6]::ffff:10.0.8.129/::ffff:10.0.8.129:61615 PUT /characteristics 204 0
[hap.encryption|INFO] Encrypt message #14, length: 88
[hap.encryption|INFO] Decrypt message #2, length: 387
[hap.endpoints.characteristics|DEBUG] PUT data: Optional("{\"characteristics\":[{\"aid\":23,\"iid\":30,\"ev\":true},{\"aid\":23,\"iid\":37,\"ev\":true},{\"aid\":23,\"iid\":51,\"ev\":true},{\"aid\":23,\"iid\":23,\"ev\":true},{\"aid\":23,\"iid\":13,\"ev\":true},{\"aid\":23,\"iid\":44,\"ev\":true},{\"aid\":23,\"iid\":58,\"ev\":true}]}")
[hap.endpoints.characteristics|DEBUG] Added listener for HAP.GenericCharacteristic<Swift.String>
[hap.endpoints.characteristics|DEBUG] Added listener for HAP.GenericCharacteristic<Swift.String>
[hap.endpoints.characteristics|DEBUG] Added listener for HAP.GenericCharacteristic<Swift.String>
[hap.endpoints.characteristics|DEBUG] Added listener for HAP.GenericCharacteristic<Swift.String>
[hap.endpoints.characteristics|DEBUG] Added listener for HAP.GenericCharacteristic<Swift.String>
[hap.endpoints.characteristics|DEBUG] Added listener for HAP.GenericCharacteristic<Swift.String>
[hap.endpoints.characteristics|DEBUG] Added listener for HAP.GenericCharacteristic<Swift.String>
[hap.endpoints|INFO] [IPv6]::ffff:10.0.8.129/::ffff:10.0.8.129:61615 PUT /characteristics 204 0
[hap.encryption|INFO] Encrypt message #15, length: 88
[hap.encryption|INFO] Decrypt message #2, length: 512
[hap.nio|WARNING] Could not decrypt message from [IPv6]::ffff:10.0.8.121/::ffff:10.0.8.121:54402, closing connection.
[hap.encryption|INFO] Decrypt message #2, length: 512
[hap.nio|WARNING] Could not decrypt message from [IPv6]::ffff:10.0.8.116/::ffff:10.0.8.116:55837, closing connection.
[hap.controllers.pair-verify|DEBUG] startRequest result: [(HAP.PairTag.identifier, 17 bytes), (HAP.PairTag.signature, 64 bytes)]
[hap.controllers.pair-verify|DEBUG] startRequest encrypted result: [(HAP.PairTag.state, 1 bytes), (HAP.PairTag.publicKey, 32 bytes), (HAP.PairTag.encryptedData, 101 bytes)]
[hap.endpoints|INFO] [IPv6]::ffff:10.0.8.121/::ffff:10.0.8.121:54403 POST /pair-verify 200 140
[hap.controllers.pair-verify|DEBUG] --> username EC48906B-6BEB-4265-97E7-08ADD3E17285
[hap.controllers.pair-verify|DEBUG] --> signature f96008d1df597290d63430834496983dad66d3834add4da45da8aac175de7aa801357c77ccebf594071d9d9ee42664809da6d5a3988f530dfb9b0fd6be6edc00
[hap.controllers.pair-verify|DEBUG] --> public key effeff36f977b12c5ecf7cc536d3bcf9eabc41295768fa88815f4249d205c042
[hap.controllers.pair-verify|INFO] Pair verify completed
[hap.endpoints|INFO] [IPv6]::ffff:10.0.8.121/::ffff:10.0.8.121:54403 POST /pair-verify 200 3
[hap.encryption|INFO] Decrypt message #0, length: 95
[hap.endpoints|INFO] [IPv6]::ffff:10.0.8.121/::ffff:10.0.8.121:54403 GET /accessories 200 11414
[hap.encryption|INFO] Encrypt message #0, length: 139
[hap.encryption|INFO] Encrypt message #1, length: 11414
[hap.encryption|INFO] Encrypt message #13, length: 0
[hap.encryption|INFO] Decrypt message #2, length: 512
[hap.nio|WARNING] Could not decrypt message from [IPv6]::ffff:10.0.8.144/::ffff:10.0.8.144:62546, closing connection.
[hap.controllers.pair-verify|DEBUG] startRequest result: [(HAP.PairTag.identifier, 17 bytes), (HAP.PairTag.signature, 64 bytes)]
[hap.controllers.pair-verify|DEBUG] startRequest encrypted result: [(HAP.PairTag.state, 1 bytes), (HAP.PairTag.publicKey, 32 bytes), (HAP.PairTag.encryptedData, 101 bytes)]
[hap.endpoints|INFO] [IPv6]::ffff:10.0.8.116/::ffff:10.0.8.116:55838 POST /pair-verify 200 140
[hap.controllers.pair-verify|DEBUG] --> username EC48906B-6BEB-4265-97E7-08ADD3E17285
[hap.controllers.pair-verify|DEBUG] --> signature 9733b51120793c97bd6ee3b211cafca7ea48558291467633a41ba6dc38ed8f9167f4553aa0e6ad7270d296e6d64f2573666bb205cab5beaf3f2c0a7623a5ed0f
[hap.controllers.pair-verify|DEBUG] --> public key effeff36f977b12c5ecf7cc536d3bcf9eabc41295768fa88815f4249d205c042
[hap.controllers.pair-verify|INFO] Pair verify completed
[hap.endpoints|INFO] [IPv6]::ffff:10.0.8.116/::ffff:10.0.8.116:55838 POST /pair-verify 200 3
[hap.encryption|INFO] Decrypt message #0, length: 95
[hap.encryption|INFO] Decrypt message #1, length: 512
[hap.nio|WARNING] Could not decrypt message from [IPv6]::ffff:10.0.8.121/::ffff:10.0.8.121:54403, closing connection.
[hap.endpoints|INFO] [IPv6]::ffff:10.0.8.116/::ffff:10.0.8.116:55838 GET /accessories 200 11414
[hap.encryption|INFO] Encrypt message #0, length: 139
[hap.encryption|INFO] Encrypt message #1, length: 11414
[hap.encryption|INFO] Encrypt message #13, length: 0
[hap.controllers.pair-verify|DEBUG] startRequest result: [(HAP.PairTag.identifier, 17 bytes), (HAP.PairTag.signature, 64 bytes)]
[hap.controllers.pair-verify|DEBUG] startRequest encrypted result: [(HAP.PairTag.state, 1 bytes), (HAP.PairTag.publicKey, 32 bytes), (HAP.PairTag.encryptedData, 101 bytes)]
[hap.endpoints|INFO] [IPv6]::ffff:10.0.8.144/::ffff:10.0.8.144:62547 POST /pair-verify 200 140
[hap.encryption|INFO] Decrypt message #1, length: 512
[hap.nio|WARNING] Could not decrypt message from [IPv6]::ffff:10.0.8.116/::ffff:10.0.8.116:55838, closing connection.
[hap.controllers.pair-verify|DEBUG] --> username EC48906B-6BEB-4265-97E7-08ADD3E17285
[hap.controllers.pair-verify|DEBUG] --> signature 18579c95af5dc4bd115bc86b9fc2a4467e3361a66aa9e7f69a7ce83fa58ccc7b7029a84714472449be219442fbdfe28a83b2607a276b709b065bae00889b1e08
[hap.controllers.pair-verify|DEBUG] --> public key effeff36f977b12c5ecf7cc536d3bcf9eabc41295768fa88815f4249d205c042
[hap.controllers.pair-verify|INFO] Pair verify completed
[hap.endpoints|INFO] [IPv6]::ffff:10.0.8.144/::ffff:10.0.8.144:62547 POST /pair-verify 200 3
[hap.encryption|INFO] Decrypt message #0, length: 95
[hap.endpoints|INFO] [IPv6]::ffff:10.0.8.144/::ffff:10.0.8.144:62547 GET /accessories 200 11414
[hap.encryption|INFO] Encrypt message #0, length: 139
[hap.encryption|INFO] Encrypt message #1, length: 11414
[hap.encryption|INFO] Encrypt message #13, length: 0
[hap.encryption|INFO] Decrypt message #1, length: 387
[hap.endpoints.characteristics|DEBUG] PUT data: Optional("{\"characteristics\":[{\"aid\":23,\"iid\":30,\"ev\":true},{\"aid\":23,\"iid\":37,\"ev\":true},{\"aid\":23,\"iid\":51,\"ev\":true},{\"aid\":23,\"iid\":23,\"ev\":true},{\"aid\":23,\"iid\":13,\"ev\":true},{\"aid\":23,\"iid\":44,\"ev\":true},{\"aid\":23,\"iid\":58,\"ev\":true}]}")
[hap.endpoints.characteristics|DEBUG] Added listener for HAP.GenericCharacteristic<Swift.String>
[hap.endpoints.characteristics|DEBUG] Added listener for HAP.GenericCharacteristic<Swift.String>
[hap.endpoints.characteristics|DEBUG] Added listener for HAP.GenericCharacteristic<Swift.String>
[hap.endpoints.characteristics|DEBUG] Added listener for HAP.GenericCharacteristic<Swift.String>
[hap.endpoints.characteristics|DEBUG] Added listener for HAP.GenericCharacteristic<Swift.String>
[hap.endpoints.characteristics|DEBUG] Added listener for HAP.GenericCharacteristic<Swift.String>
[hap.endpoints.characteristics|DEBUG] Added listener for HAP.GenericCharacteristic<Swift.String>
[hap.endpoints|INFO] [IPv6]::ffff:10.0.8.144/::ffff:10.0.8.144:62547 PUT /characteristics 204 0
[hap.encryption|INFO] Encrypt message #14, length: 88
[hap.controllers.pair-verify|DEBUG] startRequest result: [(HAP.PairTag.identifier, 17 bytes), (HAP.PairTag.signature, 64 bytes)]
[hap.controllers.pair-verify|DEBUG] startRequest encrypted result: [(HAP.PairTag.state, 1 bytes), (HAP.PairTag.publicKey, 32 bytes), (HAP.PairTag.encryptedData, 101 bytes)]
[hap.endpoints|INFO] [IPv6]::ffff:10.0.8.124/::ffff:10.0.8.124:49704 POST /pair-verify 200 140
[hap.controllers.pair-verify|DEBUG] --> username EC48906B-6BEB-4265-97E7-08ADD3E17285
[hap.controllers.pair-verify|DEBUG] --> signature 4ba24928162a30657228897d8266831401ba17fef0870cf127278292af33c9e90df2d0f90a098eda1a00a2d0ecf142bb4e0795df57099d2ae76ada204e0f0d0e
[hap.controllers.pair-verify|DEBUG] --> public key effeff36f977b12c5ecf7cc536d3bcf9eabc41295768fa88815f4249d205c042
[hap.controllers.pair-verify|INFO] Pair verify completed
[hap.endpoints|INFO] [IPv6]::ffff:10.0.8.124/::ffff:10.0.8.124:49704 POST /pair-verify 200 3
[hap.encryption|INFO] Decrypt message #0, length: 95
[hap.endpoints|INFO] [IPv6]::ffff:10.0.8.124/::ffff:10.0.8.124:49704 GET /accessories 200 11414
[hap.encryption|INFO] Encrypt message #0, length: 139
[hap.encryption|INFO] Encrypt message #1, length: 11414
[hap.encryption|INFO] Encrypt message #13, length: 0
[hap.encryption|INFO] Decrypt message #1, length: 205
[hap.endpoints.characteristics|DEBUG] PUT data: Optional("{\"characteristics\":[{\"aid\":25,\"iid\":9,\"ev\":true}]}")
[hap.endpoints.characteristics|DEBUG] Added listener for HAP.GenericCharacteristic<Swift.Bool>
[hap.endpoints|INFO] [IPv6]::ffff:10.0.8.124/::ffff:10.0.8.124:49704 PUT /characteristics 204 0
[hap.encryption|INFO] Encrypt message #14, length: 88
[hap.encryption|INFO] Decrypt message #2, length: 205
[hap.endpoints.characteristics|DEBUG] PUT data: Optional("{\"characteristics\":[{\"aid\":25,\"iid\":9,\"ev\":true}]}")
[hap.endpoints.characteristics|DEBUG] Added listener for HAP.GenericCharacteristic<Swift.Bool>
[hap.endpoints|INFO] [IPv6]::ffff:10.0.8.144/::ffff:10.0.8.144:62547 PUT /characteristics 204 0
[hap.encryption|INFO] Encrypt message #15, length: 88
[hap.controllers.pair-verify|DEBUG] startRequest result: [(HAP.PairTag.identifier, 17 bytes), (HAP.PairTag.signature, 64 bytes)]
[hap.controllers.pair-verify|DEBUG] startRequest encrypted result: [(HAP.PairTag.state, 1 bytes), (HAP.PairTag.publicKey, 32 bytes), (HAP.PairTag.encryptedData, 101 bytes)]
[hap.endpoints|INFO] [IPv6]::ffff:10.0.8.116/::ffff:10.0.8.116:55839 POST /pair-verify 200 140
[hap.controllers.pair-verify|DEBUG] --> username EC48906B-6BEB-4265-97E7-08ADD3E17285
[hap.controllers.pair-verify|DEBUG] --> signature 89d33ce1df75982fa2e0873762fcc8d00286868936cfe49748151d299d62106a3528d814432c9f896f00996f9ee6d15014967617fc9c5d9bc2ea7f593ff4210f
[hap.controllers.pair-verify|DEBUG] --> public key effeff36f977b12c5ecf7cc536d3bcf9eabc41295768fa88815f4249d205c042
[hap.controllers.pair-verify|INFO] Pair verify completed
[hap.endpoints|INFO] [IPv6]::ffff:10.0.8.116/::ffff:10.0.8.116:55839 POST /pair-verify 200 3
[hap.encryption|INFO] Decrypt message #0, length: 95
[hap.endpoints|INFO] [IPv6]::ffff:10.0.8.116/::ffff:10.0.8.116:55839 GET /accessories 200 11414
[hap.encryption|INFO] Encrypt message #0, length: 139
[hap.encryption|INFO] Encrypt message #1, length: 11414
[hap.encryption|INFO] Encrypt message #13, length: 0
[hap.encryption|INFO] Decrypt message #1, length: 512
[hap.nio|WARNING] Could not decrypt message from [IPv6]::ffff:10.0.8.116/::ffff:10.0.8.116:55839, closing connection.
[hap.encryption|INFO] Decrypt message #2, length: 512
[hap.nio|WARNING] Could not decrypt message from [IPv6]::ffff:10.0.8.124/::ffff:10.0.8.124:49704, closing connection.
gbrooker commented 5 years ago

The decryption is failing, because the message length is longer than the read buffer. In Server.swift a NIO AdaptiveRecvByteBufferAllocator is created which defaults to a minimum size of 64 bytes, an initial size of 1024 bytes and a large maximum, however without digging yet into the details of how the buffer resizes itself, I noticed that after a few messages it adapts to a 512 byte buffer size, which is not long enough for many messages, and doesn't seem to grow when larger messages are received.

I increased the minimum size of the buffer until I stopped getting decryption errors by modifying the buffer creation in Server.swift:71

.childChannelOption(ChannelOptions.recvAllocator, value: 
    AdaptiveRecvByteBufferAllocator(minimum: 2056, initial: 4098, maximum: 16392))

With a short interaction using my configuration, the longest message size was 1155 bytes. Even with a initial buffer size of 2046, I was only able to avoid a decryption failure by making the minimum buffer size larger than the longest message.

Here is an extract:

[hap.encryption|INFO] Decrypt message #0, length: 95
[hap.encryption|INFO] Decrypt message #1, length: 236
[hap.encryption|INFO] Decrypt message #2, length: 387
[hap.encryption|INFO] Decrypt message #1, length: 205
[hap.encryption|INFO] Decrypt message #2, length: 537
[hap.encryption|INFO] Decrypt message #1, length: 205
[hap.encryption|INFO] Decrypt message #2, length: 205
[hap.encryption|INFO] Decrypt message #3, length: 1155
[hap.encryption|INFO] Decrypt message #3, length: 537
[hap.encryption|INFO] Decrypt message #4, length: 477
[hap.encryption|INFO] Decrypt message #2, length: 537
[hap.encryption|INFO] Decrypt message #5, length: 1155
[hap.encryption|INFO] Decrypt message #7, length: 927
[hap.encryption|INFO] Decrypt message #3, length: 1042
[hap.encryption|INFO] Decrypt message #4, length: 113
[hap.encryption|INFO] Decrypt message #2, length: 537
[hap.encryption|INFO] Decrypt message #3, length: 1042
[hap.encryption|INFO] Decrypt message #4, length: 113
[hap.encryption|INFO] Decrypt message #3, length: 1042
[hap.encryption|INFO] Decrypt message #4, length: 113
[hap.encryption|INFO] Decrypt message #0, length: 95
[hap.encryption|INFO] Decrypt message #1, length: 236
[hap.encryption|INFO] Decrypt message #2, length: 387
[hap.encryption|INFO] Decrypt message #8, length: 107
[hap.encryption|INFO] Decrypt message #9, length: 205

This workaround seems to temporarily cure the decryption issue, but I expect the long term solution requires working out why the buffer is not growing in size as required.

gbrooker commented 5 years ago

Fixed by PR #79 which implements the workaround mentioned above.

Bouke commented 5 years ago

Great investigation so far. The HAP specification notes the following on the transport security:

Each HTTP message is split into frames no larger than 1024 bytes. Each frame has the following format:

<2:AAD for little endian length of encrypted data (n) in bytes>
<n:encrypted data according to AEAD algorithm, up to 1024 bytes>
<16:authTag according to AEAD algorithm>

So my guess is that if you make the buffer 1042, it should be able to receive frames just fine. However while handling reads from the channel, we're not looking at the frame's header, but just forward whatever we get to the Cryptographer. This means that when a frame doesn't fit a buffer, thus is split over multiple reads, we forward incomplete frames to the Cryptographer.

So while I'm happy to take the workaround suggested in the PR, a proper fix would be to read the frame headers. Either by merge the Cryptographer and the CryptographerHandler, or at least by not sending incomplete frames to the Cryptographer.

gbrooker commented 5 years ago

Yes, I noted the mention in the public available spec that frames would be no larger than 1024 bytes, however a minimum buffer size of 1024 still results in decryption failures, due to the occasional frame of length 1155 (as shown in the above log extracts). Either the spec changed or there are some devices on my network (HomePods?) which are not respecting the requirement. Setting the minimum buffer size to 1200 has worked successfully so far. I've added that workaround in PR #79

I agree that a proper fix would be to ensure that a complete frame is read before sending for decryption.

Bouke commented 5 years ago

I've started working on a proper fix for this in #80. A fixed read buffer of 1042 (not 1024) would probably workaround the issue, as then each frame would at most fill the entire buffer. However I don't think the current allocator works that way, so that's why it's probably failing for you. Setting a bigger size would only defer the issue until bigger messages are send by the client.

gbrooker commented 5 years ago

Great, let me know when you would like me to test it out on my local network.

I've experimented with simple setups in hap-server to try to reproduce the large messages. I only get small messages with the default configuration, and not a great deal bigger when I add all the test accessories that are currently commented out in main.swift. However if I add a TV accessory, which has many more Services and Characteristics, I see much larger messages, and so it may be possible for you to reproduce the issue too.

To see the packet lengths, change the log level of hap.encryptionin hap-server/main.swift :

    getLogger("hap.encryption").logLevel = .info

You can search the log for lines beginning with [hap.encryption|INFO] Decrypt message

Then add a TV accessory to main.swift:

let tv = Accessory.Television(info: Service.Info(name: "Main TV", serialNumber: "00008"),
                              inputs: [("Channel 1", Enums.InputSourceType.hdmi),
                                       ("Channel 2", Enums.InputSourceType.hdmi),
                                       ("Channel 3", Enums.InputSourceType.hdmi),
                                       ("Channel 4", Enums.InputSourceType.hdmi),
                                       ("Channel 5", Enums.InputSourceType.hdmi),
                                       ("Channel 6", Enums.InputSourceType.hdmi),
                                       ("Channel 7", Enums.InputSourceType.hdmi),
                                       ("Channel 8", Enums.InputSourceType.hdmi)
    ])

and add the accessory to the bridge

let device = Device(
    bridgeInfo: Service.Info(name: "Bridge", serialNumber: "00001"),
    setupCode: "123-44-321",
    storage: storage,
    accessories: [
        tv,
        livingRoomLightbulb,
        bedroomNightStand
...

You will need to use the PR #78 changes to be able to sucessfully add the Television device to HomeKit. You don't need the beta builds, you can add this test device under iOS 12.1. Although it just cannot be controlled from the iOS 12.1 UI, you can still see the large messages. Note that without PR #78 HomeKit is unable to add the accessory.

With the setup above, I am seeing packets as long as 1338 bytes. I checked which device was sending the longer messages, and discovered they were coming from both the iOS 12.1 iPhone I used to add the bridge, and from one (of two) HomePod's on the network which is the primary HomeKit Hub for the test Home.

With these changes, are you able to reproduce the long packets ?

Bouke commented 5 years ago

Thanks, this helps a lot. I've got a fix ready in my PR. With the steps to reproduce that you provided, the problem does no longer appear. I also reduced the amount of memory allocations required when encrypting / decrypting. As a result the code should be a little more performant on constrained environments, like the Raspberry Pi.

I've updated my home installation to that branch, to further test it. Can you let me know how it works for you?