Opened 10 years ago

Last modified 7 years ago

#1092 closed defect (Works for me)

Hidden Service is up after some hours

Reported by: illuminai Owned by:
Priority: Low Milestone:
Component: Core Tor/Tor Version: 0.2.1.19
Severity: Keywords:
Cc: illuminai, Sebastian, karsten, nickm Actual Points:
Parent ID: Points:
Reviewer: Sponsor:

Description

Ok so I've configured hidden service for use with tor 0.2.1.19 with my ubuntu 9.04 xen vps box, and it went up after about 3-4 hours, which i think is DAMN LONG. about 1:30 hours before my hs went up i enabled debug.log in my torrc file (contents below).
here are the details:

box: Ubuntu 9.04 x86_64 xen VPS
kernel: 2.6.18-128.1.10.el5xen
tor version: 0.2.1.19 from http://mirror.noreply.org/pub/tor repo

/var/log/tor/debug.log:
Sep 12 13:20:28.479 [info] rend_service_load_keys(): Loading hidden-service keys from "/var/lib/tor/6ircn/"
Sep 12 13:20:28.511 [info] rend_service_load_keys(): Loading hidden-service keys from "/var/lib/tor/6ircn/"
Sep 12 13:20:31.364 [info] circuit_predict_and_launch_new(): Have 2 clean circs (0 internal), need another internal circ for my hidden service.
Sep 12 13:20:32.368 [info] circuit_predict_and_launch_new(): Have 3 clean circs (1 internal), need another internal circ for my hidden service.
Sep 12 13:20:33.372 [info] circuit_predict_and_launch_new(): Have 4 clean circs (2 internal), need another internal circ for my hidden service.
Sep 12 13:21:12.525 [info] upload_service_descriptor(): Sending publish request for hidden service coimvmqgv2m33j7g
Sep 12 13:21:12.525 [debug] directory_initiate_command_rend(): Initiating hidden-service v2 descriptor upload
Sep 12 13:21:12.526 [info] directory_post_to_hs_dir(): Sending publish request for v2 descriptor for service '[scrubbed]' with descriptor ID '[scrubbed]' with validity of 31916 seconds to hidden service directory '42' on port 9030.
Sep 12 13:21:12.526 [debug] directory_initiate_command_rend(): Initiating hidden-service v2 descriptor upload
Sep 12 13:21:12.528 [info] directory_post_to_hs_dir(): Sending publish request for v2 descriptor for service '[scrubbed]' with descriptor ID '[scrubbed]' with validity of 31916 seconds to hidden service directory 'sophia' on port 0.
Sep 12 13:21:12.528 [debug] directory_initiate_command_rend(): Initiating hidden-service v2 descriptor upload
Sep 12 13:21:12.530 [info] directory_post_to_hs_dir(): Sending publish request for v2 descriptor for service '[scrubbed]' with descriptor ID '[scrubbed]' with validity of 31916 seconds to hidden service directory 'HW1' on port 9030.
Sep 12 13:21:12.530 [debug] directory_initiate_command_rend(): Initiating hidden-service v2 descriptor upload
Sep 12 13:21:12.532 [info] directory_post_to_hs_dir(): Sending publish request for v2 descriptor for service '[scrubbed]' with descriptor ID '[scrubbed]' with validity of 31916 seconds to hidden service directory 'minespar2c70fb' on port 0.
Sep 12 13:21:12.532 [debug] directory_initiate_command_rend(): Initiating hidden-service v2 descriptor upload
Sep 12 13:21:12.534 [info] directory_post_to_hs_dir(): Sending publish request for v2 descriptor for service '[scrubbed]' with descriptor ID '[scrubbed]' with validity of 31916 seconds to hidden service directory 'ZbiG' on port 9030.
Sep 12 13:21:12.534 [debug] directory_initiate_command_rend(): Initiating hidden-service v2 descriptor upload
Sep 12 13:21:12.536 [info] directory_post_to_hs_dir(): Sending publish request for v2 descriptor for service '[scrubbed]' with descriptor ID '[scrubbed]' with validity of 31916 seconds to hidden service directory 'PPrivComGermany4' on port 0.
Sep 12 13:21:14.543 [info] upload_service_descriptor(): Sending publish request for hidden service coimvmqgv2m33j7g
Sep 12 13:21:14.543 [debug] directory_initiate_command_rend(): Initiating hidden-service descriptor upload
Sep 12 13:21:14.546 [debug] directory_initiate_command_rend(): Initiating hidden-service descriptor upload
Sep 12 13:21:14.548 [debug] directory_initiate_command_rend(): Initiating hidden-service descriptor upload
Sep 12 13:21:29.803 [info] circuit_predict_and_launch_new(): Have 9 clean circs (2 internal), need another internal circ for my hidden service.
Sep 12 13:21:31.811 [info] circuit_predict_and_launch_new(): Have 8 clean circs (2 internal), need another internal circ for my hidden service.
Sep 12 13:21:33.820 [info] circuit_predict_and_launch_new(): Have 8 clean circs (2 internal), need another internal circ for my hidden service.
Sep 12 13:22:01.935 [info] upload_service_descriptor(): Sending publish request for hidden service coimvmqgv2m33j7g
Sep 12 13:22:01.935 [debug] directory_initiate_command_rend(): Initiating hidden-service descriptor upload
Sep 12 13:22:01.935 [debug] directory_initiate_command_rend(): Initiating hidden-service descriptor upload
Sep 12 13:22:01.935 [debug] directory_initiate_command_rend(): Initiating hidden-service descriptor upload
Sep 12 13:22:13.993 [info] upload_service_descriptor(): Sending publish request for hidden service coimvmqgv2m33j7g
Sep 12 13:22:13.993 [debug] directory_initiate_command_rend(): Initiating hidden-service v2 descriptor upload
Sep 12 13:22:13.993 [info] directory_post_to_hs_dir(): Sending publish request for v2 descriptor for service '[scrubbed]' with descriptor ID '[scrubbed]' with validity of 31855 seconds to hidden service directory '42' on port 9030.
Sep 12 13:22:13.993 [debug] directory_initiate_command_rend(): Initiating hidden-service v2 descriptor upload
Sep 12 13:22:13.993 [info] directory_post_to_hs_dir(): Sending publish request for v2 descriptor for service '[scrubbed]' with descriptor ID '[scrubbed]' with validity of 31855 seconds to hidden service directory 'sophia' on port 0.
Sep 12 13:22:13.993 [debug] directory_initiate_command_rend(): Initiating hidden-service v2 descriptor upload
Sep 12 13:22:13.993 [info] directory_post_to_hs_dir(): Sending publish request for v2 descriptor for service '[scrubbed]' with descriptor ID '[scrubbed]' with validity of 31855 seconds to hidden service directory 'HW1' on port 9030.
Sep 12 13:22:13.993 [debug] directory_initiate_command_rend(): Initiating hidden-service v2 descriptor upload
Sep 12 13:22:13.993 [info] directory_post_to_hs_dir(): Sending publish request for v2 descriptor for service '[scrubbed]' with descriptor ID '[scrubbed]' with validity of 31855 seconds to hidden service directory 'minespar2c70fb' on port 0.
Sep 12 13:22:13.993 [debug] directory_initiate_command_rend(): Initiating hidden-service v2 descriptor upload
Sep 12 13:22:13.993 [info] directory_post_to_hs_dir(): Sending publish request for v2 descriptor for service '[scrubbed]' with descriptor ID '[scrubbed]' with validity of 31855 seconds to hidden service directory 'ZbiG' on port 9030.
Sep 12 13:22:13.993 [debug] directory_initiate_command_rend(): Initiating hidden-service v2 descriptor upload
Sep 12 13:22:13.993 [info] directory_post_to_hs_dir(): Sending publish request for v2 descriptor for service '[scrubbed]' with descriptor ID '[scrubbed]' with validity of 31855 seconds to hidden service directory 'PPrivComGermany4' on port 0.
Sep 12 13:22:29.103 [info] circuit_predict_and_launch_new(): Have 7 clean circs (2 internal), need another internal circ for my hidden service.
Sep 12 13:22:33.120 [info] circuit_predict_and_launch_new(): Have 7 clean circs (2 internal), need another internal circ for my hidden service.
Sep 12 13:23:01.236 [info] upload_service_descriptor(): Sending publish request for hidden service coimvmqgv2m33j7g
Sep 12 13:23:01.236 [debug] directory_initiate_command_rend(): Initiating hidden-service v2 descriptor upload
Sep 12 13:23:01.236 [info] directory_post_to_hs_dir(): Sending publish request for v2 descriptor for service '[scrubbed]' with descriptor ID '[scrubbed]' with validity of 31807 seconds to hidden service directory '42' on port 9030.
Sep 12 13:23:01.236 [debug] directory_initiate_command_rend(): Initiating hidden-service v2 descriptor upload
Sep 12 13:23:01.236 [info] directory_post_to_hs_dir(): Sending publish request for v2 descriptor for service '[scrubbed]' with descriptor ID '[scrubbed]' with validity of 31807 seconds to hidden service directory 'sophia' on port 0.
Sep 12 13:23:01.236 [debug] directory_initiate_command_rend(): Initiating hidden-service v2 descriptor upload
Sep 12 13:23:01.236 [info] directory_post_to_hs_dir(): Sending publish request for v2 descriptor for service '[scrubbed]' with descriptor ID '[scrubbed]' with validity of 31807 seconds to hidden service directory 'HW1' on port 9030.
Sep 12 13:23:01.236 [debug] directory_initiate_command_rend(): Initiating hidden-service v2 descriptor upload
Sep 12 13:23:01.236 [info] directory_post_to_hs_dir(): Sending publish request for v2 descriptor for service '[scrubbed]' with descriptor ID '[scrubbed]' with validity of 31807 seconds to hidden service directory 'minespar2c70fb' on port 0.
Sep 12 13:23:01.236 [debug] directory_initiate_command_rend(): Initiating hidden-service v2 descriptor upload
Sep 12 13:23:01.236 [info] directory_post_to_hs_dir(): Sending publish request for v2 descriptor for service '[scrubbed]' with descriptor ID '[scrubbed]' with validity of 31807 seconds to hidden service directory 'ZbiG' on port 9030.
Sep 12 13:23:01.236 [debug] directory_initiate_command_rend(): Initiating hidden-service v2 descriptor upload
Sep 12 13:23:01.236 [info] directory_post_to_hs_dir(): Sending publish request for v2 descriptor for service '[scrubbed]' with descriptor ID '[scrubbed]' with validity of 31807 seconds to hidden service directory 'PPrivComGermany4' on port 0.
Sep 12 13:23:29.351 [info] circuit_predict_and_launch_new(): Have 5 clean circs (2 internal), need another internal circ for my hidden service.
Sep 12 13:23:33.367 [info] circuit_predict_and_launch_new(): Have 5 clean circs (2 internal), need another internal circ for my hidden service.
Sep 12 13:24:29.595 [info] circuit_predict_and_launch_new(): Have 3 clean circs (2 internal), need another internal circ for my hidden service.
Sep 12 13:24:33.612 [info] circuit_predict_and_launch_new(): Have 3 clean circs (2 internal), need another internal circ for my hidden service.
Sep 12 13:25:33.779 [info] circuit_predict_and_launch_new(): Have 3 clean circs (2 internal), need another internal circ for my hidden service.
Sep 12 14:21:58.919 [info] circuit_predict_and_launch_new(): Have 4 clean circs (2 internal), need another internal circ for my hidden service.
Sep 12 14:22:02.932 [info] upload_service_descriptor(): Sending publish request for hidden service coimvmqgv2m33j7g
Sep 12 14:22:02.932 [debug] directory_initiate_command_rend(): Initiating hidden-service descriptor upload
Sep 12 14:22:02.933 [debug] directory_initiate_command_rend(): Initiating hidden-service descriptor upload
Sep 12 14:22:02.934 [debug] directory_initiate_command_rend(): Initiating hidden-service descriptor upload
Sep 12 14:22:58.087 [info] circuit_predict_and_launch_new(): Have 2 clean circs (2 internal), need another internal circ for my hidden service.
Sep 12 14:23:02.101 [info] upload_service_descriptor(): Sending publish request for hidden service coimvmqgv2m33j7g
Sep 12 14:23:02.101 [debug] directory_initiate_command_rend(): Initiating hidden-service v2 descriptor upload
Sep 12 14:23:02.103 [info] directory_post_to_hs_dir(): Sending publish request for v2 descriptor for service '[scrubbed]' with descriptor ID '[scrubbed]' with validity of 28206 seconds to hidden service directory '42' on port 9030.
Sep 12 14:23:02.103 [debug] directory_initiate_command_rend(): Initiating hidden-service v2 descriptor upload
Sep 12 14:23:02.105 [info] directory_post_to_hs_dir(): Sending publish request for v2 descriptor for service '[scrubbed]' with descriptor ID '[scrubbed]' with validity of 28206 seconds to hidden service directory 'sophia' on port 0.
Sep 12 14:23:02.105 [debug] directory_initiate_command_rend(): Initiating hidden-service v2 descriptor upload
Sep 12 14:23:02.107 [info] directory_post_to_hs_dir(): Sending publish request for v2 descriptor for service '[scrubbed]' with descriptor ID '[scrubbed]' with validity of 28206 seconds to hidden service directory 'HW1' on port 9030.
Sep 12 14:23:02.107 [debug] directory_initiate_command_rend(): Initiating hidden-service v2 descriptor upload
Sep 12 14:23:02.109 [info] directory_post_to_hs_dir(): Sending publish request for v2 descriptor for service '[scrubbed]' with descriptor ID '[scrubbed]' with validity of 28206 seconds to hidden service directory 'minespar2c70fb' on port 0.
Sep 12 14:23:02.110 [debug] directory_initiate_command_rend(): Initiating hidden-service v2 descriptor upload
Sep 12 14:23:02.111 [info] directory_post_to_hs_dir(): Sending publish request for v2 descriptor for service '[scrubbed]' with descriptor ID '[scrubbed]' with validity of 28206 seconds to hidden service directory 'ZbiG' on port 9030.
Sep 12 14:23:02.111 [debug] directory_initiate_command_rend(): Initiating hidden-service v2 descriptor upload
Sep 12 14:23:02.113 [info] directory_post_to_hs_dir(): Sending publish request for v2 descriptor for service '[scrubbed]' with descriptor ID '[scrubbed]' with validity of 28206 seconds to hidden service directory 'PPrivComGermany4' on port 0.
Sep 12 14:23:14.533 [debug] connection_dir_client_reached_eof(): Received response from directory server '94.78.156.90:65006': 503 "Currently not acting as v2 hidden service directory"
Sep 12 14:23:14.533 [info] connection_dir_client_reached_eof(): Received http status code 503 ("Currently not acting as v2 hidden service directory") from server '94.78.156.90:65006'. I'll try again soon.
Sep 12 14:23:58.343 [info] circuit_predict_and_launch_new(): Have 5 clean circs (2 internal), need another internal circ for my hidden service.
Sep 12 14:24:33.480 [info] circuit_predict_and_launch_new(): Have 3 clean circs (2 internal), need another internal circ for my hidden service.
Sep 12 14:24:58.582 [info] circuit_predict_and_launch_new(): Have 3 clean circs (2 internal), need another internal circ for my hidden service.
Sep 12 14:25:33.633 [info] circuit_predict_and_launch_new(): Have 2 clean circs (2 internal), need another internal circ for my hidden service.
Sep 12 14:25:35.636 [info] circuit_predict_and_launch_new(): Have 2 clean circs (2 internal), need another internal circ for my hidden service.
Sep 12 14:25:58.646 [info] circuit_predict_and_launch_new(): Have 2 clean circs (2 internal), need another internal circ for my hidden service.
Sep 12 14:26:33.664 [info] circuit_predict_and_launch_new(): Have 2 clean circs (2 internal), need another internal circ for my hidden service.
Sep 12 14:26:35.672 [info] circuit_predict_and_launch_new(): Have 2 clean circs (2 internal), need another internal circ for my hidden service.
Sep 12 14:47:24.908 [info] circuit_predict_and_launch_new(): Have 2 clean circs (2 internal), need another internal circ for my hidden service.
Sep 12 14:48:24.955 [info] circuit_predict_and_launch_new(): Have 2 clean circs (2 internal), need another internal circ for my hidden service.
Sep 12 14:49:24.999 [info] circuit_predict_and_launch_new(): Have 2 clean circs (2 internal), need another internal circ for my hidden service.
Sep 12 14:50:48.060 [info] circuit_predict_and_launch_new(): Have 2 clean circs (2 internal), need another internal circ for my hidden service.
Sep 12 14:51:48.096 [info] circuit_predict_and_launch_new(): Have 2 clean circs (2 internal), need another internal circ for my hidden service.
Sep 12 14:59:04.451 [info] circuit_predict_and_launch_new(): Have 2 clean circs (2 internal), need another internal circ for my hidden service.
Sep 12 15:00:30.532 [info] circuit_predict_and_launch_new(): Have 2 clean circs (2 internal), need another internal circ for my hidden service.

/var/log/tor/notices.log:
Sep 12 13:20:28.477 [notice] Tor 0.2.1.19 opening new log file.
Sep 12 13:20:28.533 [notice] Parsing GEOIP file.
Sep 12 13:20:29.067 [notice] We now have enough directory information to build circuits.
Sep 12 13:20:29.067 [notice] Bootstrapped 80%: Connecting to the Tor network.
Sep 12 13:20:29.356 [notice] Bootstrapped 85%: Finishing handshake with first hop.
Sep 12 13:20:30.538 [notice] Bootstrapped 90%: Establishing a Tor circuit.
Sep 12 13:20:33.567 [notice] Tor has successfully opened a circuit. Looks like client functionality is working.
Sep 12 13:20:33.567 [notice] Bootstrapped 100%: Done.
Sep 12 15:01:19.591 [notice] Our directory information is no longer up-to-date enough to build circuits: We have no recent network-status consensus.

/var/log/tor/log:
Sep 12 12:20:00.163 [notice] Tor 0.2.1.19 opening log file.
Sep 12 12:20:00.305 [notice] Parsing GEOIP file.
Sep 12 12:20:00.959 [notice] We now have enough directory information to build circuits.
Sep 12 12:20:00.960 [notice] Bootstrapped 80%: Connecting to the Tor network.
Sep 12 12:25:01.075 [notice] Bootstrapped 85%: Finishing handshake with first hop.
Sep 12 12:25:02.281 [notice] Bootstrapped 90%: Establishing a Tor circuit.
Sep 12 12:25:05.788 [notice] Tor has successfully opened a circuit. Looks like client functionality is working.
Sep 12 12:25:05.788 [notice] Bootstrapped 100%: Done.
Sep 12 12:26:01.577 [notice] No Tor server allows exit to [scrubbed]:6667. Rejecting.
Sep 12 12:28:46.771 [notice] No Tor server allows exit to [scrubbed]:6667. Rejecting.
Sep 12 12:28:50.337 [notice] No Tor server allows exit to [scrubbed]:22. Rejecting.
Sep 12 12:36:31.089 [warn] Socks version 99 not recognized. (Tor is not an http proxy.)
Sep 12 12:36:31.116 [warn] Fetching socks handshake failed. Closing.
Sep 12 12:43:13.989 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Sep 12 12:43:13.991 [notice] Tor 0.2.1.19 opening log file.
Sep 12 12:44:07.010 [notice] Interrupt: exiting cleanly.
Sep 12 12:44:09.083 [notice] Tor 0.2.1.19 opening log file.
Sep 12 12:44:09.118 [notice] Parsing GEOIP file.
Sep 12 12:44:09.643 [notice] We now have enough directory information to build circuits.
Sep 12 12:44:09.643 [notice] Bootstrapped 80%: Connecting to the Tor network.
Sep 12 12:44:09.900 [notice] Bootstrapped 85%: Finishing handshake with first hop.
Sep 12 12:44:11.078 [notice] Bootstrapped 90%: Establishing a Tor circuit.
Sep 12 12:44:12.874 [notice] Tor has successfully opened a circuit. Looks like client functionality is working.
Sep 12 12:44:12.874 [notice] Bootstrapped 100%: Done.
Sep 12 12:46:31.132 [notice] Interrupt: exiting cleanly.
Sep 12 12:46:33.163 [notice] Tor 0.2.1.19 opening log file.
Sep 12 12:46:33.197 [notice] Parsing GEOIP file.
Sep 12 12:46:33.724 [notice] We now have enough directory information to build circuits.
Sep 12 12:46:33.724 [notice] Bootstrapped 80%: Connecting to the Tor network.
Sep 12 12:46:33.960 [notice] Bootstrapped 85%: Finishing handshake with first hop.
Sep 12 12:46:35.137 [notice] Bootstrapped 90%: Establishing a Tor circuit.
Sep 12 12:46:36.827 [notice] Tor has successfully opened a circuit. Looks like client functionality is working.
Sep 12 12:46:36.827 [notice] Bootstrapped 100%: Done.
Sep 12 12:50:33.190 [notice] Interrupt: exiting cleanly.
Sep 12 12:50:35.222 [notice] Tor 0.2.1.19 opening log file.
Sep 12 12:50:35.234 [notice] Parsing GEOIP file.
Sep 12 12:50:35.710 [notice] We now have enough directory information to build circuits.
Sep 12 12:50:35.710 [notice] Bootstrapped 80%: Connecting to the Tor network.
Sep 12 12:50:35.947 [notice] Bootstrapped 85%: Finishing handshake with first hop.
Sep 12 12:50:37.126 [notice] Bootstrapped 90%: Establishing a Tor circuit.
Sep 12 12:50:39.443 [notice] Tor has successfully opened a circuit. Looks like client functionality is working.
Sep 12 12:50:39.443 [notice] Bootstrapped 100%: Done.
Sep 12 13:20:26.450 [notice] Interrupt: exiting cleanly.

i've talked with Sebastian on #tor and he asked me to file this bug report.

[Automatically added by flyspray2trac: Operating System: Other Linux]

Child Tickets

Change History (5)

comment:1 Changed 10 years ago by Sebastian

So I think there are a few things here:

We're trying to publish to a relay that isn't a hsdir anymore because it was
restarted. In theory, this shouldn't matter, because the other hsdirs were still
up and accepted the descriptor, but it might have influenced the availability
of the hs due to some bug. The log indicates that we're going to "try again
soon" to publish to the hsdir, which seems wrong since it was the hsdir
that told us it didn't want our descriptor.

Also, 4 hours is a long time, during which the hs should have attempted to
publish descriptors quite often, and should have noticed problems more
often, or not?

I think the above calls for a speedier implementation of proposal 143, to
better handle timing issues and edge cases, as well as making sure that a
hsdir that we published to actually serves our descriptor.

I couldn't test much, because when I learned the hs address, it was instantly
reachable :(

Also, our logging doesn't work right. It assumes we'll use the hsdir's dirport,
even if it doesn't have a dirport configured.

comment:2 Changed 10 years ago by Sebastian

If this shows up again, we should ask if the people having trouble to
access the hs are having any Exclude*Nodes options defined.

comment:3 Changed 10 years ago by karsten

I cannot find in the logs that the hidden service took 3-4 hours until
being available for clients. Maybe I'm missing something?

As for Sebastian's comments:

  • Trying again to publish to a hidden service directory that rejected our

descriptor before is simply the result of not trusting anything that a
hidden service directory tells us, even not that it didn't want our
descriptor. (We only believe the network status consensus for telling us
which hidden service directories to publish to.) In this case, we might be
able to mark the hidden service directory as not working, but I don't see
why making another attempt later on does any harm.

  • We're publishing a new descriptor every 1 hour at least.
  • A speedier implementation of proposal 143 would be great, agreed.
  • I've changed the log statement to identify the relay by nickname, IP address and OR port.

In summary, I don't see a reason to keep this bug report open. I'm closing
it. If the problem recurs, someone should re-open or open a new task.

comment:4 Changed 10 years ago by karsten

flyspray2trac: bug closed.

comment:5 Changed 7 years ago by nickm

Component: Tor ClientTor
Note: See TracTickets for help on using tickets.