"Unauthorized request" messages after tinc update

[Nikolaus Rath]

Nikolaus Rath <Nikolaus-BTH8mxji4b0 at public.gmane.org> writes:
> Guus Sliepen <guus-NnCthlHDAqpg9hUCZPvPmw-XMD5yJDbdMReXY1tMh2IBg at public.gmane.org> writes:
>> On Wed, Aug 28, 2013 at 08:43:25AM -0700, Nikolaus Rath wrote:
>>
>>> This is what it looks like with -d 4. I also updated the server tinc
>>> version to 1.0.22 now:
>>> 
>>> Aug 28 15:20:38 ebox tinc.rath[2759]: Expiring symmetric keys
>>> Aug 28 15:20:38 ebox tinc.rath[2759]: Sending KEY_CHANGED to everyone (BROADCAST): 14 3296e87f ebox
>>> Aug 28 15:39:04 ebox tinc.rath[2759]: Connection from 198.228.212.252 port 32534
>>> Aug 28 15:39:04 ebox tinc.rath[2759]: Sending ID to <unknown> (198.228.212.252 port 32534): 0 ebox 17
>>> Aug 28 15:39:04 ebox tinc.rath[2759]: Sending 10 bytes of metadata to <unknown> (198.228.212.252 port 32534)
>>> Aug 28 15:39:04 ebox tinc.rath[2759]: Got PING from <unknown> (198.228.212.252 port 32534): 8
>>
>> That's very strange. It looks like there is a PING message in a buffer
>> somewhere that is being received by ebox instead of the ID message. I have
>> never seen this before...
>>
>>> Aug 28 15:39:35 ebox tinc.rath[2759]: Connection from 198.228.212.252 port 52274
>>> Aug 28 15:39:35 ebox tinc.rath[2759]: Sending ID to <unknown> (198.228.212.252 port 52274): 0 ebox 17
>>> Aug 28 15:39:35 ebox tinc.rath[2759]: Sending 10 bytes of metadata to <unknown> (198.228.212.252 port 52274)
>>> Aug 28 15:39:35 ebox tinc.rath[2759]: Flushing 10 bytes to <unknown> (198.228.212.252 port 52274)
>>> Aug 28 15:39:35 ebox tinc.rath[2759]: Got ID from <unknown> (198.228.212.252 port 52274): 0 thinkpad 17
>>
>> Which version of tinc is thinkpad running? Could you run tincd there as well
>> with -d4, and copy&paste the log from that one as well when the problem occurs?
>
>
> Hmm. I just realized that I lied to you before. When these messages
> started appearing, I wasn't just upgrading two clients from tinc 1.0.11
> to tinc 1.0.16, but I also added a new client running tinc
> 1.0.19. "thinkpad" is the new client that I added, but this is the first
> time that it triggered one of the "Unauthorized request" messages.
>
>
> I tried to reproduce the problem, but it's not as easy as starting fresh
> tinc instances with -d 4 on client and server. In that case everything
> works smoothly. I guess I'll have to leave them running with -d 4 for a
> while and wait for the message to appear...


Ok, it happened again:

Aug 30 06:12:47 ebox tinc.rath[24083]: Sending KEY_CHANGED to everyone (BROADCAST): 14 38123bcf ebox
Aug 30 06:14:27 ebox tinc.rath[24083]: Connection from 87.173.100.41 port 55925
Aug 30 06:14:27 ebox tinc.rath[24083]: Sending ID to <unknown> (87.173.100.41 port 55925): 0 ebox 17
Aug 30 06:14:27 ebox tinc.rath[24083]: Sending 10 bytes of metadata to <unknown> (87.173.100.41 port 55925)
Aug 30 06:14:27 ebox tinc.rath[24083]: Flushing 10 bytes to <unknown> (87.173.100.41 port 55925)
Aug 30 06:14:27 ebox tinc.rath[24083]: Got PING from <unknown> (87.173.100.41 port 55925): 8
Aug 30 06:14:27 ebox tinc.rath[24083]: Unauthorized request from <unknown> (87.173.100.41 port 55925)
Aug 30 06:14:27 ebox tinc.rath[24083]: Closing connection with <unknown> (87.173.100.41 port 55925)
Aug 30 06:14:27 ebox tinc.rath[24083]: Purging unreachable nodes
Aug 30 06:14:38 ebox tinc.rath[24083]: Connection from 87.173.100.41 port 55927
Aug 30 06:14:38 ebox tinc.rath[24083]: Sending ID to <unknown> (87.173.100.41 port 55927): 0 ebox 17
Aug 30 06:14:38 ebox tinc.rath[24083]: Sending 10 bytes of metadata to <unknown> (87.173.100.41 port 55927)
Aug 30 06:14:38 ebox tinc.rath[24083]: Flushing 10 bytes to <unknown> (87.173.100.41 port 55927)


Unfortunately I still don't have the debug log from the client, because
87.173.100.41 wasn't running with -j 4. I'll activate debugging on all
clients now.


Best,

   -Nikolaus

-- 
 »Time flies like an arrow, fruit flies like a Banana.«

  PGP fingerprint: 5B93 61F8 4EA2 E279 ABF6  02CF A9AD B7F8 AE4E 425C