Opened 6 months ago

Last modified 3 months ago

#31056 new defect

Hidden service sometimes unable to create circuit

Reported by: dylanholand Owned by:
Priority: High Milestone:
Component: Core Tor/Tor Version: Tor: 0.3.5.8
Severity: Normal Keywords: tor-hs
Cc: asn, dgoulet Actual Points:
Parent ID: Points:
Reviewer: Sponsor:

Description

I have a dedicated server with a few onoin-services on it. One of the services has some traffic to it and this service can't be reached a few times every day, lasting 5-15 minutes.

While it's not available, the other onions is working just fine, it's just this particular .onion (which is the important one).

The service is not of the kind that would get ddos'ed or similar, however, it can have some heavy peaks in traffic, which at some degree correlate with the unavailability. However, no server process is under heavy stress and other services, including other hidden services, is functioning normally)

Server specs:

OS: CentOS/RHEL 7
TOR: 0.3.5.8-1.el7

torrc config:

RunAsDaemon 1
DataDirectory /var/lib/tor
TransPort 9040
TransListenAddress 127.0.0.1
DNSPort 127.0.0.1:54

A few lines from journalctl output, "xxx" is the onion that can't be reached:

Tor[19172]: Giving up launching first hop of circuit to rendezvous point [scrubbed] for service xxx.
Tor[19172]: Giving up launching first hop of circuit to rendezvous point [scrubbed] for service xxx.
Tor[19172]: Giving up launching first hop of circuit to rendezvous point [scrubbed] for service xxx.
Tor[19172]: Giving up launching first hop of circuit to rendezvous point [scrubbed] for service xxx.
Tor[19172]: Giving up launching first hop of circuit to rendezvous point [scrubbed] for service xxx.
Tor[19172]: Couldn't relaunch rendezvous circuit to '[scrubbed]'.
Tor[19172]: Giving up launching first hop of circuit to rendezvous point [scrubbed] for service xxx.
Tor[19172]: Couldn't relaunch rendezvous circuit to '[scrubbed]'.
Tor[19172]: Giving up launching first hop of circuit to rendezvous point [scrubbed] for service xxx.
Tor[19172]: Giving up launching first hop of circuit to rendezvous point [scrubbed] for service xxx.
Tor[19172]: Giving up launching first hop of circuit to rendezvous point [scrubbed] for service xxx.
Tor[19172]: Giving up launching first hop of circuit to rendezvous point [scrubbed] for service xxx.
Tor[19172]: Giving up launching first hop of circuit to rendezvous point [scrubbed] for service xxx.
Tor[19172]: Giving up launching first hop of circuit to rendezvous point

I have not found a similar issue in other tickets and it's very important that I can provide 100% uptime for this .onion.

Many thanks for your time reading this, highly appreciated.

Child Tickets

Change History (7)

comment:1 Changed 6 months ago by teor

Cc: asn dgoulet added
Keywords: tor-hs added

Is it a v2 or v3 onion service?
You censored the address from your logs, and the onion service parts of your config, so I can't tell.

I've also cc'd our onion services developers, who might be able to help more.

comment:2 in reply to:  1 Changed 5 months ago by dylanholand

Replying to teor:

Is it a v2 or v3 onion service?

It's a v2 service

You censored the address from your logs, and the onion service parts of your config, so I can't tell.

I've also cc'd our onion services developers, who might be able to help more.

Thank you!

comment:3 Changed 5 months ago by asn

Hmm the interesting log message here seems to be:

  newcirc = circuit_launch_by_extend_info(CIRCUIT_PURPOSE_S_CONNECT_REND,
                            oldstate->chosen_exit, flags);

  if (!newcirc) {
    log_warn(LD_REND,"Couldn't relaunch rendezvous circuit to '%s'.",
             safe_str(extend_info_describe(oldstate->chosen_exit)));
    return;
  }

Unfortunately without info or debug logs it's not possible to get deeper here :/

If this is something you can reproduce, can you please enable info or debug logs?

You might also want to try a more recent Tor version.

This might be related to #30200, or maybe not.

comment:4 in reply to:  3 ; Changed 5 months ago by dylanholand

Replying to asn:

Hmm the interesting log message here seems to be:

  newcirc = circuit_launch_by_extend_info(CIRCUIT_PURPOSE_S_CONNECT_REND,
                            oldstate->chosen_exit, flags);

  if (!newcirc) {
    log_warn(LD_REND,"Couldn't relaunch rendezvous circuit to '%s'.",
             safe_str(extend_info_describe(oldstate->chosen_exit)));
    return;
  }

Unfortunately without info or debug logs it's not possible to get deeper here :/

If this is something you can reproduce, can you please enable info or debug logs?

You might also want to try a more recent Tor version.

This might be related to #30200, or maybe not.


I have enabled info logging, and will update the ticket with more in-depth info once it happens again.

Thank you for your time!

comment:5 Changed 5 months ago by dylanholand

Here's part of the info-level log-file while this is happening. Let me know if there's anything else I can provide. Thanks a bunch!

Jul 02 10:30:58.000 [info] rend_service_receive_introduction(): Received INTRODUCE2 cell for service "<onion_address_v2>" on circ 3682712543.
Jul 02 10:30:58.000 [info] rep_hist_note_used_internal(): New port prediction added. Will continue predictive circ building for 2747 more seconds.
Jul 02 10:30:58.000 [warn] Giving up launching first hop of circuit to rendezvous point [scrubbed] for service <onion_address_v2>.
Jul 02 10:30:58.000 [info] rend_service_receive_introduction(): Received INTRODUCE2 cell for service "<onion_address_v2>" on circ 3839988605.
Jul 02 10:30:58.000 [info] rep_hist_note_used_internal(): New port prediction added. Will continue predictive circ building for 2747 more seconds.
Jul 02 10:30:58.000 [warn] Giving up launching first hop of circuit to rendezvous point [scrubbed] for service <onion_address_v2>.
Jul 02 10:30:58.000 [info] channelpadding_send_padding_cell_for_callback(): Sending netflow keepalive on 56 to [scrubbed] ([scrubbed]) after 6924 ms. Delta 2ms
Jul 02 10:30:58.000 [info] channelpadding_send_padding_cell_for_callback(): Sending netflow keepalive on 95 to [scrubbed] ([scrubbed]) after 8529 ms. Delta 2ms
Jul 02 10:30:59.000 [info] connection_edge_process_relay_cell(): 68: end cell (misc error) for stream 42650. Removing stream.
Jul 02 10:30:59.000 [info] rend_service_receive_introduction(): Received INTRODUCE2 cell for service "<onion_address_v2>" on circ 3682712543.
Jul 02 10:30:59.000 [info] rep_hist_note_used_internal(): New port prediction added. Will continue predictive circ building for 2747 more seconds.
Jul 02 10:30:59.000 [warn] Giving up launching first hop of circuit to rendezvous point [scrubbed] for service <onion_address_v2>.
Jul 02 10:30:59.000 [info] rep_hist_note_used_internal(): New port prediction added. Will continue predictive circ building for 2747 more seconds.
Jul 02 10:30:59.000 [info] circuit_predict_and_launch_new(): Have 2 clean circs (0 internal), need another internal circ for my hidden service.
Jul 02 10:30:59.000 [info] rend_service_receive_introduction(): Received INTRODUCE2 cell for service "<onion_address_v2>" on circ 3682712543.
Jul 02 10:30:59.000 [info] rep_hist_note_used_internal(): New port prediction added. Will continue predictive circ building for 2747 more seconds.
Jul 02 10:30:59.000 [warn] Giving up launching first hop of circuit to rendezvous point [scrubbed] for service <onion_address_v2>.
Jul 02 10:30:59.000 [info] rend_service_receive_introduction(): Received INTRODUCE2 cell for service "<onion_address_v2>" on circ 3682712543.
Jul 02 10:30:59.000 [info] rep_hist_note_used_internal(): New port prediction added. Will continue predictive circ building for 2747 more seconds.
Jul 02 10:30:59.000 [warn] Giving up launching first hop of circuit to rendezvous point [scrubbed] for service <onion_address_v2>.
Jul 02 10:30:59.000 [info] rend_service_receive_introduction(): Received INTRODUCE2 cell for service "<onion_address_v2>" on circ 3839988605.
Jul 02 10:30:59.000 [info] rep_hist_note_used_internal(): New port prediction added. Will continue predictive circ building for 2747 more seconds.
Jul 02 10:30:59.000 [warn] Giving up launching first hop of circuit to rendezvous point [scrubbed] for service <onion_address_v2>.
Jul 02 10:31:00.000 [info] rend_service_receive_introduction(): Received INTRODUCE2 cell for service "<onion_address_v2>" on circ 3682712543.
Jul 02 10:31:00.000 [info] rep_hist_note_used_internal(): New port prediction added. Will continue predictive circ building for 2747 more seconds.
Jul 02 10:31:00.000 [warn] Giving up launching first hop of circuit to rendezvous point [scrubbed] for service <onion_address_v2>.
Jul 02 10:31:00.000 [info] rend_service_receive_introduction(): Received INTRODUCE2 cell for service "<onion_address_v2>" on circ 3682712543.
Jul 02 10:31:00.000 [info] rep_hist_note_used_internal(): New port prediction added. Will continue predictive circ building for 2747 more seconds.
Jul 02 10:31:00.000 [warn] Giving up launching first hop of circuit to rendezvous point [scrubbed] for service <onion_address_v2>.
Jul 02 10:31:00.000 [info] rep_hist_note_used_internal(): New port prediction added. Will continue predictive circ building for 2747 more seconds.
Jul 02 10:31:00.000 [info] circuit_predict_and_launch_new(): Have 2 clean circs (0 internal), need another internal circ for my hidden service.
Jul 02 10:31:00.000 [info] rend_service_receive_introduction(): Received INTRODUCE2 cell for service "<onion_address_v2>" on circ 3682712543.
Jul 02 10:31:00.000 [info] rep_hist_note_used_internal(): New port prediction added. Will continue predictive circ building for 2747 more seconds.
Jul 02 10:31:00.000 [warn] Giving up launching first hop of circuit to rendezvous point [scrubbed] for service <onion_address_v2>.
Jul 02 10:31:00.000 [info] connection_edge_finished_connecting(): Exit connection to [scrubbed]:80 ([scrubbed]) established.
Jul 02 10:31:00.000 [info] rend_service_receive_introduction(): Received INTRODUCE2 cell for service "<onion_address_v2>" on circ 3839988605.
Jul 02 10:31:00.000 [info] rep_hist_note_used_internal(): New port prediction added. Will continue predictive circ building for 2747 more seconds.
Jul 02 10:31:00.000 [warn] Giving up launching first hop of circuit to rendezvous point [scrubbed] for service <onion_address_v2>.
Jul 02 10:31:00.000 [info] connection_edge_finished_connecting(): Exit connection to [scrubbed]:80 ([scrubbed]) established.
Jul 02 10:31:00.000 [info] connection_edge_finished_connecting(): Exit connection to [scrubbed]:80 ([scrubbed]) established.
Jul 02 10:31:00.000 [info] rend_service_receive_introduction(): Received INTRODUCE2 cell for service "<onion_address_v2>" on circ 3839988605.
Jul 02 10:31:00.000 [info] rep_hist_note_used_internal(): New port prediction added. Will continue predictive circ building for 2747 more seconds.
Jul 02 10:31:00.000 [warn] Giving up launching first hop of circuit to rendezvous point [scrubbed] for service <onion_address_v2>.
Jul 02 10:31:01.000 [info] rep_hist_note_used_internal(): New port prediction added. Will continue predictive circ building for 2747 more seconds.
Jul 02 10:31:01.000 [info] circuit_predict_and_launch_new(): Have 2 clean circs (0 internal), need another internal circ for my hidden service.
Jul 02 10:31:01.000 [info] connection_edge_process_relay_cell(): 38: end cell (misc error) for stream 51212. Removing stream.
Jul 02 10:31:01.000 [info] rend_service_receive_introduction(): Received INTRODUCE2 cell for service "<onion_address_v2>" on circ 3682712543.
Jul 02 10:31:01.000 [info] rep_hist_note_used_internal(): New port prediction added. Will continue predictive circ building for 2747 more seconds.
Jul 02 10:31:01.000 [warn] Giving up launching first hop of circuit to rendezvous point [scrubbed] for service <onion_address_v2>.
Jul 02 10:31:01.000 [info] rend_service_receive_introduction(): Received INTRODUCE2 cell for service "<onion_address_v2>" on circ 4112713265.
Jul 02 10:31:01.000 [info] rep_hist_note_used_internal(): New port prediction added. Will continue predictive circ building for 2747 more seconds.
Jul 02 10:31:01.000 [warn] Giving up launching first hop of circuit to rendezvous point [scrubbed] for service <onion_address_v2>.
Jul 02 10:31:01.000 [info] rend_service_receive_introduction(): Received INTRODUCE2 cell for service "<onion_address_v2>" on circ 3839988605.
Jul 02 10:31:01.000 [info] rep_hist_note_used_internal(): New port prediction added. Will continue predictive circ building for 2747 more seconds.
Jul 02 10:31:01.000 [warn] Giving up launching first hop of circuit to rendezvous point [scrubbed] for service <onion_address_v2>.
Jul 02 10:31:02.000 [info] rend_service_receive_introduction(): Received INTRODUCE2 cell for service "<onion_address_v2>" on circ 3682712543.
Jul 02 10:31:02.000 [info] rep_hist_note_used_internal(): New port prediction added. Will continue predictive circ building for 2747 more seconds.
Jul 02 10:31:02.000 [warn] Giving up launching first hop of circuit to rendezvous point [scrubbed] for service <onion_address_v2>.
Jul 02 10:31:02.000 [info] rend_service_receive_introduction(): Received INTRODUCE2 cell for service "<onion_address_v2>" on circ 3682712543.
Jul 02 10:31:02.000 [info] rep_hist_note_used_internal(): New port prediction added. Will continue predictive circ building for 2747 more seconds.
Jul 02 10:31:02.000 [warn] Giving up launching first hop of circuit to rendezvous point [scrubbed] for service <onion_address_v2>.
Jul 02 10:31:02.000 [info] rend_service_receive_introduction(): Received INTRODUCE2 cell for service "<onion_address_v2>" on circ 4112713265.
Jul 02 10:31:02.000 [info] rep_hist_note_used_internal(): New port prediction added. Will continue predictive circ building for 2747 more seconds.
Jul 02 10:31:02.000 [warn] Giving up launching first hop of circuit to rendezvous point [scrubbed] for service <onion_address_v2>.
Jul 02 10:31:02.000 [info] rend_service_receive_introduction(): Received INTRODUCE2 cell for service "<onion_address_v2>" on circ 3682712543.
Jul 02 10:31:02.000 [info] rep_hist_note_used_internal(): New port prediction added. Will continue predictive circ building for 2747 more seconds.
Jul 02 10:31:02.000 [warn] Giving up launching first hop of circuit to rendezvous point [scrubbed] for service <onion_address_v2>.
Jul 02 10:31:02.000 [info] rep_hist_note_used_internal(): New port prediction added. Will continue predictive circ building for 2747 more seconds.
Jul 02 10:31:02.000 [info] circuit_predict_and_launch_new(): Have 2 clean circs (0 internal), need another internal circ for my hidden service.
Jul 02 10:31:02.000 [info] rend_service_receive_introduction(): Received INTRODUCE2 cell for service "<onion_address_v2>" on circ 4112713265.
Jul 02 10:31:02.000 [info] rep_hist_note_used_internal(): New port prediction added. Will continue predictive circ building for 2747 more seconds.
Jul 02 10:31:02.000 [warn] Giving up launching first hop of circuit to rendezvous point [scrubbed] for service <onion_address_v2>.

comment:6 in reply to:  4 Changed 5 months ago by dylanholand

Replying to asn:

If this is something you can reproduce, can you please enable info or debug logs?


I have not added info-level logs, hope it will help!

comment:7 Changed 3 months ago by arma

I wonder if there are any other useful logs around then.

For example, maybe your guard's microdescriptor expired, and during the period until you had fetched a new one, your Tor didn't want to make a circuit. (It's interesting that it says "Giving up launching first hop".)

Note: See TracTickets for help on using tickets.