Attempt to open a stream on first hop of circuit

changed milestone to %Tor: 0.3.4.x-final

added component::core tor/tor milestone::Tor: 0.3.4.x-final points::1 priority::high resolution::fixed severity::normal status::closed tor-circuit type::defect version::tor 0.3.1.1-alpha labels

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

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.

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

Trac:
Status: new to needs_information

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

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...?

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.

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?

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...?

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?

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

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 ;).

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.

Trac:
Status: needs_information to new
Priority: Medium to High

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

Trac:
Parent: N/A to #24898 (moved)

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?

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 (moved).

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

Trac:
Version: Tor: 0.3.2.2-alpha to Tor: 0.3.1.1-alpha

#24898 (moved) is fixed and backported. Closing this.

Trac:
Resolution: N/A to fixed
Status: new to closed

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

Trac:
Resolution: fixed to N/A
Milestone: Tor: 0.3.2.x-final to Tor: 0.3.4.x-final
Parent: #24898 (moved) to N/A
Status: closed to reopened

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

Trac:
Resolution: N/A to fixed
Status: reopened to closed

closed

changed time estimate to 8h

mentioned in issue #26300 (moved)

moved to tpo/core/tor#24011 (closed)

mentioned in issue tpo/core/tor#26300 (closed)

Attempt to open a stream on first hop of circuit

Child items ...

Activity