Tons of "Failed to decrypt and verify packet"

[Julien Muchembled]

tl;dr Wow it's just when I've finished all the below debugging, and just before sending this email that git fetches new commits by Etienne. Now I'm unable to reproduce the issue. What commit would have fixed it ? b54fde67 (Implement sptps_verify_datagram) ?

Le 04/07/14 21:58, Guus Sliepen a écrit :
> On Mon, Apr 07, 2014 at 02:36:10AM +0200, Julien Muchembled wrote:
> 
>> So I continued to bisect.
>> Commit 0da0728 ("Use AES-256-GCM for the SPTPS protocol") is really the first bad commit.
> 
> Not unexpected. Thanks for doing the bisection!

The bug reported by many Windows users seemed to be the same but now I see mails saying the issue would be solved for some people. I've just tested again with a recent 1.1 commit (762db91) and I can still reproduce the issue, so I'm still stuck with 1.1pre9

I tried to see if it could be an environment issue by running my testcase in a fresh install of Debian Sid, and now I am in front of the most strange bug I've even seen.
I am unable to reproduce the bug in a chroot whereas the tinc binaries and all accessed files are exactly the same: I used strace to list of disk accesses (and for libraries, I downgraded a few packages to match the host).
I have no idea anymore about what could be different between the host and the chroot, so I'll have to give up this approach. This also means I can't provide a VM so someone else could reproduce the bug.

Then, I started to add logs in chacha_poly1305. What I found is that the encrypted messages are not corrupted: the data to be decrypted was really sent by another node, but the keys differs. I didn't check but I doubt it's corruption of the context on either side. I'd rather think tinc uses the wrong key to decrypt: one reason could that tinc fails to identify the sender.

Next, I looked at closer tinc logs of a failure, with microseconds like those I posted on the ML.
In the testcase, nodes are configured as follows:
  n1 port 32573
  n2 port 32574
  n3 port 32575
  n4 port 32576
And in logs:
19.990549 Sending REQ_KEY to n1 (127.0.0.1 port 32573): 15 n2 n1 21 AAAAI4I5PcXYYHVLAMmSB9i/QlfZk1KW4vslBjUFMOWz/fTfQhW/Vwn56946EnXsXsAVrC8LRnSJQcD2j71oM6MmeioRwRp8jIQEqjd0SEjqIFWPll0dhprV3kLa6QFg3BjCTt/XKXd+
19.990549 Sending 153 bytes of metadata to n1 (127.0.0.1 port 32573)
20.510251 UDP address of n4 set to 127.0.0.1 port 32573
20.510251 Failed to decrypt and verify packet
20.510397 UDP address of n4 set to 127.0.0.1 port 32576
20.510397 Got MTU probe request 803 from n4 (127.0.0.1 port 32576)
20.754989 Got MTU probe request 434 from n4 (127.0.0.1 port 32576)

'Failed to decrypt and verify packet' lines always follows a wrong match of node & udp port. Other examples:
22.867526 Sending MTU probe length 1509 to n4 (127.0.0.1 port 32573)
22.867526 UDP address of n4 set to 127.0.0.1 port 32576
22.867526 Got MTU probe request 1496 from n4 (127.0.0.1 port 32576)
22.887972 Got MTU probe request 1352 from n4 (127.0.0.1 port 32576)
22.888209 Got MTU probe request 1404 from n4 (127.0.0.1 port 32576)
23.059937 Sending MTU probe length 219 to n1 (127.0.0.1 port 32573)
23.059937 Sending MTU probe length 560 to n1 (127.0.0.1 port 32573)
23.059937 Sending MTU probe length 595 to n1 (127.0.0.1 port 32573)
23.059937 UDP address of n4 set to 127.0.0.1 port 32573
23.059937 Failed to decrypt and verify packet
23.060306 Failed to decrypt and verify packet
23.060321 Failed to decrypt and verify packet
23.060368 Failed to decrypt and verify packet
23.077170 Failed to decrypt and verify packet
23.077221 Failed to decrypt and verify packet

-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 819 bytes
Desc: OpenPGP digital signature
URL: <http://www.tinc-vpn.org/pipermail/tinc/attachments/20140701/8882a055/attachment.sig>