Opened 13 months ago

Closed 6 months ago

#24011 closed defect (fixed)

Attempt to open a stream on first hop of circuit

Reported by: teor Owned by:
Priority: High Milestone: Tor: 0.3.4.x-final
Component: Core Tor/Tor Version: Tor: 0.3.1.1-alpha
Severity: Normal Keywords: tor-circuit
Cc: Actual Points:
Parent ID: Points: 1
Reviewer: Sponsor:

Description

I'm seeing these warnings in chutney on recent tor releases.
They seem to have appeared in the last week or two.

Did we merge something that tries to block single-hop exits recently?
Or any changes to circuit creation code?

Because I think it might be buggy.

Warning: Attempt by 127.0.0.1:59488 to open a stream on first hop of circuit. Closing. Number: 1
Warning: circuit_receive_relay_cell (backward) failed. Closing. Number: 1

Child Tickets

Change History (18)

comment:1 Changed 13 months ago by nickm

dgoulet points out that we recently removed the deprecated AllowSingleHopExits option. Maybe that's related?

comment:2 Changed 13 months ago by teor

Also, we recently changed how relays identify clients. So it might be related to that as well.
I'd check if relays that are bootstrapping (using CREATE_FAST) really do authenticate to the first peer, and that their relay flag is set correctly on the remote peer.

comment:3 Changed 12 months ago by dgoulet

Status: newneeds_information

I wonder how much this could be related to #21534... On what tor type do you see these warnings, client, relay, authorities, ... ?

comment:4 Changed 12 months ago by teor

Exits are the only nodes that log these warnings, because they're a single-hop exit warning.

comment:5 Changed 11 months ago by dgoulet

From the warning, the previous hop on the circuit was indeed marked as a client that is:

      const int client_chan = channel_is_client(or_circ->p_chan);
      if ((client_chan || ...)

There are two ways this can be done, through a CREATE/CREATE_FAST/CREATE2 cell which in that case the previous hops is indeed a client or with a unauthenticated connection that is a client or bridge where the connection is marked when the NETINFO cell comes in.

In both cases, the channel is supposed to be a client and not end up with a BEGIN cell at a one hop Exit...

I'm a bit puzzled here on how this can happen, I suspect that we might only see this with chutney (TestingNetwork) because I don't see how client can just start doing one-hop Exit...?

Last edited 11 months ago by dgoulet (previous) (diff)

comment:6 Changed 11 months ago by teor

I think this might be happening because some relay connections are not mutually authenticated.
One possible reason is that chutney sets AssumeReachable, which makes relays start up much faster.
We also run really fast consensus intervals, which can cause race conditions like this.

We should check what it takes for a relay to authenticate - maybe this happens when we don't have relay microdescs (and therefore relay ed keys?)

I haven't seen this error in earlier versions, so it may be something new.
Or it might have always been there, but we're seeing it now, because we have a stricter definition of is_client.

comment:7 Changed 11 months ago by dgoulet

Ok I bet everything that this is why we see this warning now: 66aff2d8f35217cc802bd46eeeaf49326d7de4b0

Originally, we were using is_first_hop instead of "is client" and here is how it was set:

  circ->is_first_hop = (created_cell->cell_type == CELL_CREATED_FAST);

Leaving behind the CREATE and CREATE2 that also makes a channel being marked as a client. This was modified after we removed AllowSingleHopExits with commit: d52a1e2faaf

So now the question is still how did the channel on the OR connection got flagged as a client?

comment:8 Changed 11 months ago by dgoulet

Also, I'm unable to reproduce this warning right now with chutney but I do remember seeing it some weeks ago so this must be some race condition...?

comment:9 Changed 11 months ago by teor

I haven't seen it for a few weeks, either.
Was it something we broke and then fixed?
Or is it a race condition that doesn't happen very often?

comment:10 Changed 11 months ago by teor

Just saw it on master - it's a race condition that seems to happen under heavy CPU load:

PASS: bridges+ipv6-min
Detail: chutney/tools/warnings.sh /Users/dev/tor/../chutney/tools/../net/nodes.1513124118
Warning: Attempt by 127.0.0.1:51534 to open a stream on first hop of circuit. Closing. Number: 1
Warning: circuit_receive_relay_cell (backward) failed. Closing. Number: 1

comment:11 Changed 11 months ago by dgoulet

Ok I've tried a lot in the last hour to hit it and I can't... What I'm trying to get is the debug logs out of it but it could be slowing things down enough to never hit it :S ... If you are ever able to get it with debug, I'll gladly eat those ;).

comment:12 Changed 11 months ago by dgoulet

Priority: MediumHigh
Status: needs_informationnew

Ok, I just noticed 4 of those today in a span of ~3 hours. IPs there are public relays (and some we know personally so I doubt this is malicious):

Dec 14 14:49:57.994 [warn] Attempt by 137.205.124.35:30658 to open a stream on first hop of circuit. Closing.
Dec 14 15:44:01.534 [warn] Attempt by 109.105.109.162:36601 to open a stream on first hop of circuit. Closing.
Dec 14 17:08:05.864 [warn] Attempt by 217.182.196.67:64478 to open a stream on first hop of circuit. Closing.
Dec 14 17:11:09.928 [warn] Attempt by 85.25.43.31:443 to open a stream on first hop of circuit. Closing.

Something is clearly not right and I fear we might have a more important bug than we originally thought especially if this is linked to relay authentication. Those 4 relays above are on 0.3.1.x series.

comment:13 Changed 10 months ago by teor

Parent ID: #24898

#24898 has an explanation for this issue, and will soon have a patch.

comment:14 Changed 10 months ago by arma

Did we say here what versions the warnings happened on?

I see that commit 66aff2d8f3 went into 0.3.2.2-alpha.

And it looks like af8cadf3 is scheduled for inclusion in 0.3.2.10, which isn't out yet?

comment:15 Changed 10 months ago by teor

Version: Tor: 0.3.2.2-alphaTor: 0.3.1.1-alpha

This affects 0.3.1.1-alpha through 0.3.2.9. The next 0.3.1 and 0.3.2 have the fix from #24898.

For details, see:
https://trac.torproject.org/projects/tor/ticket/24898#comment:14

comment:16 Changed 9 months ago by dgoulet

Resolution: fixed
Status: newclosed

#24898 is fixed and backported. Closing this.

comment:17 Changed 6 months ago by dgoulet

Milestone: Tor: 0.3.2.x-finalTor: 0.3.4.x-final
Parent ID: #24898
Resolution: fixed
Status: closedreopened

An 0.2.9.15 relay just triggered this on my 0.3.3.6 relay:

Jun 03 17:17:16.642 [warn] Attempt by 94.19.103.117:48914 to open a stream on first hop of circuit. Closing.

The IP address there is a public relay here: https://metrics.torproject.org/rs.html#details/65663E6D2E761B0650AC8A3F74F1243209D562DE

comment:18 Changed 6 months ago by teor

Resolution: fixed
Status: reopenedclosed

I opened #26300 so we can log extra information when this happens, and try to diagnose the cause.

Note: See TracTickets for help on using tickets.