Skip to content
Snippets Groups Projects

ORPort incorrectly detected as non-reachable in 0.4.5.6/6

    • Open Issue created by rotor @rotor

    Summary

    After my bridge upgrade from 0.4.3.5 to 0.4.5.5 (and now 0.4.5.6 - from your "debian stable main" repository) my ORPort isn't detected as reacheable anymore (a message in logs after 20 minutes). However, when I check it with telnet or even using your TCP reachability test it is completely fine. I suspect, it is a regression related to more aggressive IPv6 mode (I've seen the other issues, but they seemed to be fixed in 0.4.5.6).

    I tried to set ORPort to "55555 IPv4Only", but it does seem to be ignored. I still observe:

    Unable to find IPv4 address for ORPort 55555. You might want to specify IPv4Only to it or set an explicit address or set Address.

    maybe related to #40300 (closed).

    As I run Tor in a container image in Podman, I cannot easily define an IP address in the configuration. In addition the container might support IPv6 at its network interface, but my external (host's) network does not. That might be confusing for Tor and maybe the external checker tries to reach it using IPv6.

    It would be good to be able to simply disable IPv6 globally (IPv4Only in ORPort doesn't work for me). Related to #40208 (closed)? Is there any workaround available right now to make it work again?

    Environment

    Tor 0.4.5.6 from your "debian stable main" repository

    Tor 0.4.5.6 running on Linux with Libevent 2.1.8-stable, OpenSSL 1.1.1d, Zlib 1.2.11, Liblzma 5.2.4, Libzstd 1.3.8 and Glibc 2.28 as libc.

    Edited
    To upload designs, you'll need to enable LFS and have an admin enable hashed storage. More information

    Child items 0

    • No child items are currently assigned. Use child items to break down this issue into smaller parts.

    Activity

    • Nick Mathewson
      Nick Mathewson @nickm ·
      Owner

      Any better luck with 0.4.5.x? We substantially revised that code there.

    • rotor changed title from ORPort incorrectly detected as non-reachable in 0.4.4.5/6 to ORPort incorrectly detected as non-reachable in 0.4.5.6/6

      changed title from ORPort incorrectly detected as non-reachable in 0.4.4.5/6 to ORPort incorrectly detected as non-reachable in 0.4.5.6/6

    • R
      rotor @rotor ·
      Author

      @nickm Thanks for asking about that. Due to a minor version bump by 2 numbers I confused the them. Tested with 0.4.5.5 and 0.4.5.6. I updated the original text.

      Edited by rotor
    • rotor changed the description

      changed the description

    • rotor mentioned in merge request tpo/anti-censorship/docker-obfs4-bridge!2 (merged)

      mentioned in merge request tpo/anti-censorship/docker-obfs4-bridge!2 (merged)

    • David Goulet
      David Goulet @dgoulet ·
      Owner

      @rotor But, hmmm if this is #40300 (closed), relay should still work and publish its descriptor. Do you see that in the logs as in is the relay properly functioning?

    • R
      rotor @rotor ·
      Author

      Full (redacted) logs from the (probably) latest published version of docker-obfs4-bridge which works in my containerized environment:

      Starting tor.
[notice] Tor 0.4.3.5 running on Linux with Libevent 2.1.8-stable, OpenSSL 1.1.1d, Zlib 1.2.11, Liblzma 5.2.4, and Libzstd 1.3.8.
[notice] Tor can't help you if you use it wrong! Learn how to be safe at https://www.torproject.org/download/download#warning
[notice] Read configuration file "/etc/tor/torrc".
Based on detected system memory, MaxMemInQueues is set to xxx MB. You can override this by setting MaxMemInQueues by hand.
Opening OR listener on 0.0.0.0:yyyy1
Opened OR listener on 0.0.0.0:yyyy1
Opening Extended OR listener on 127.0.0.1:0
Extended OR listener listening on port zzzz.
Opened Extended OR listener on 127.0.0.1:zzzz
Parsing GEOIP IPv4 file /usr/share/tor/geoip.
Parsing GEOIP IPv6 file /usr/share/tor/geoip6.
Configured to measure statistics. Look for the *-stats files that will first be written to the data directory in 24 hours from now.
Your Tor server's identity key fingerprint is 'ffff'
Your Tor bridge's hashed identity key fingerprint is 'hhhh'
Bootstrapped 0% (starting): Starting
Starting with guard context "default"
Registered server transport 'obfs4' at '[::]:yyyy2'
Bootstrapped 5% (conn): Connecting to a relay
Bootstrapped 10% (conn_done): Connected to a relay
Bootstrapped 14% (handshake): Handshaking with a relay
Bootstrapped 15% (handshake_done): Handshake with a relay done
Bootstrapped 75% (enough_dirinfo): Loaded enough directory info to build circuits
Bootstrapped 90% (ap_handshake_done): Handshake finished with a relay to build circuits
Bootstrapped 95% (circuit_create): Establishing a Tor circuit
Guessed our IP address as x.x.x.x (source: y.y.y.y).
Bootstrapped 100% (done): Done
Now checking whether ORPort x.x.x.x:yyyy1 is reachable... (this may take up to 20 minutes -- look for log messages indicating success)
Self-testing indicates your ORPort is reachable from the outside. Excellent. Publishing server descriptor.
Performing bandwidth self-test...done.

      And here the image built using the same Dockerfile with the latest (as of last Thursday) Tor deb packages:

      Starting tor.
Tor 0.4.5.6 running on Linux with Libevent 2.1.8-stable, OpenSSL 1.1.1d, Zlib 1.2.11, Liblzma 5.2.4, Libzstd 1.3.8 and Glibc 2.28 as libc.
Tor can't help you if you use it wrong! Learn how to be safe at https://www.torproject.org/download/download#warning
Read configuration file "/etc/tor/torrc".
Based on detected system memory, MaxMemInQueues is set to xxx MB. You can override this by setting MaxMemInQueues by hand.
Opening OR listener on 0.0.0.0:yyyy1
Opened OR listener connection (ready) on 0.0.0.0:yyyy1
Opening Extended OR listener on 127.0.0.1:0
Extended OR listener listening on port zzzz.
Opened Extended OR listener connection (ready) on 127.0.0.1:zzzz
Your Tor server's identity key  fingerprint is 'ffff'
Your Tor bridge's hashed identity key  fingerprint is 'hhhh'
Your Tor server's identity key ed25519 fingerprint is 'ffff9'
Configured hibernation. This interval begins at ... and ends at .... We have no prior estimate for bandwidth, so we will start out awake and hibernate when we exhaust our quota.
Parsing GEOIP IPv4 file /usr/share/tor/geoip.
Parsing GEOIP IPv6 file /usr/share/tor/geoip6.
Configured to measure statistics. Look for the *-stats files that will first be written to the data directory in 24 hours from now.
Bootstrapped 0% (starting): Starting
Starting with guard context "default"
Registered server transport 'obfs4' at '[::]:yyyy2'
Bootstrapped 5% (conn): Connecting to a relay
Unable to find IPv4 address for ORPort yyyy1. You might want to specify IPv4Only to it or set an explicit address or set Address.
Bootstrapped 10% (conn_done): Connected to a relay
Bootstrapped 14% (handshake): Handshaking with a relay
Bootstrapped 15% (handshake_done): Handshake with a relay done
Bootstrapped 75% (enough_dirinfo): Loaded enough directory info to build circuits
Bootstrapped 90% (ap_handshake_done): Handshake finished with a relay to build circuits
Bootstrapped 95% (circuit_create): Establishing a Tor circuit
External address seen and suggested by a directory authority: x.x.x.x
Bootstrapped 100% (done): Done
Not advertising Directory Service support (Reason: AccountingMax enabled)
Now checking whether IPv4 ORPort x.x.x.x:yyyy1 is reachable... (this may take up to 20 minutes -- look for log messages indicating success)
Your server has not managed to confirm reachability for its ORPort(s) at x.x.x.x:yyyy1. Relays do not publish descriptors until their ORPort and DirPort are reachable. Please check your firewalls, ports, address, /etc/hosts file, etc.

      The last message arrived after 19 minutes.

      In the second case, I started with ORPort yyyy1, but the following logs are for ORPort yyy1 IPv4Only. I cannot set IP explicitly due to containerization. I also enabled here rate limiting. However, the rest of the configuration should be the same.

      The IPv4 address and port is reachable from outside (from my local machine and using your TCP reachability test), but for some reasons your automatic check claims it is not. As it is a Podman managed container, there could be some network glitches which can affect the way how Tor perceives the environment. Please let me know if I can check anything else what could be useful for you to triage the reason.

      Edited by rotor
    • David Goulet
      David Goulet @dgoulet ·
      Owner

      This is most peculiar... The reachability tests, if it is using the right IPv4 address as in the working case, should still work, that is one thing we haven't changed with this whole IP discovery change.

      We'll have to check the debug logs here to learn what is failing or not working. Can you provide that for the failing case? Along your torrc please.

    • R
      rotor @rotor ·
      Author

      Following:

      [warn] Your log may contain sensitive information - you're logging more than "notice". Don't log unless it serves an important reason. Overwrite the log afterwards.

      I would prefer not to share my debug log publicly. Below, I extracted lines that were directly connected with port binding and similar. Please take a look. Maybe there will be something interesting. If not, I might share the debug log with you privately.

      As expected Tor is not able to find my external IP address on its own being put in a container. However, xxx.xxx.xxx.xxx in the log is my public IPv4 address correctly resolved using a remote party. I wonder, if:

      ...1:08.000 [debug] parse_addr_policy(): Adding new entry 'reject *4:*'
...1:08.000 [debug] parse_addr_policy(): Adding new entry 'reject *6:*'

      might be important to reject remote connections?

      The log extract:

      ...9:30.154 [notice] Tor 0.4.5.6 running on Linux with Libevent 2.1.8-stable, OpenSSL 1.1.1d, Zlib 1.2.11, Liblzma 5.2.4, Libzstd 1.3.8 and Glibc 2.28 as libc.
...
...9:30.160 [notice] Opening OR listener on 0.0.0.0:XXXX1
...9:30.160 [notice] Opened OR listener connection (ready) on 0.0.0.0:XXXX1
...9:30.160 [notice] Opening OR listener on [::]:XXXX1
...9:30.160 [notice] Opened OR listener connection (ready) on [::]:XXXX1
...9:30.160 [notice] Opening Extended OR listener on 127.0.0.1:0
...9:30.160 [notice] Extended OR listener listening on port ZZZZZ.
...9:30.160 [notice] Opened Extended OR listener connection (ready) on 127.0.0.1:ZZZZZ
...9:30.000 [warn] Your log may contain sensitive information - you're logging more than "notice". Don't log unless it serves an important reason. Overwrite the log afterwards.
...
...0:07.000 [info] connection_or_set_canonical(): Channel 0 chose an idle timeout of 197.
...0:07.000 [debug] connection_add_impl(): new conn type Extended OR, socket 19, address 127.0.0.1, n_conns 4.
...0:07.000 [debug] connection_ext_or_start_auth(): ExtORPort authentication: Sending supported authentication types
...0:07.000 [debug] read_to_chunk(): Read 141 bytes. 141 on inbuf.
...0:07.000 [debug] process_read_lines(): Read line from process: "VERSION 1"
...0:07.000 [info] handle_proxy_line(): Got a line from managed proxy '/usr/bin/obfs4proxy': (VERSION 1)
...0:07.000 [debug] process_read_lines(): Read line from process: "SMETHOD obfs4 [::]:XXXX2 ARGS:cert=...
...
...0:07.000 [info] handle_proxy_line(): Got a line from managed proxy '/usr/bin/obfs4proxy': (SMETHOD obfs4 [::]:XXXX2 ARGS:cert=...
...0:07.000 [debug] parse_method_line_helper(): Got options_string: ARGS:cert=...
...0:07.000 [debug] parse_method_line_helper(): Got ARGS: cert=...
...0:07.000 [info] parse_method_line_helper(): Server transport obfs4 at [::]:XXXX2.
...0:07.000 [debug] process_read_lines(): Read line from process: "SMETHODS DONE"
...0:07.000 [info] handle_proxy_line(): Got a line from managed proxy '/usr/bin/obfs4proxy': (SMETHODS DONE)
...0:07.000 [info] handle_methods_done(): Server managed proxy '/usr/bin/obfs4proxy' configuration completed!
...0:07.000 [info] save_transport_to_state(): Transport seems to have spawned on its usual address:port.
...0:07.000 [notice] Registered server transport 'obfs4' at '[::]:XXXX2'
...0:07.000 [debug] conn_read_callback(): socket 8 wants to read.
...0:07.000 [debug] connection_handle_listener_read(): Connection accepted on socket 20 (child of fd 8).
...0:07.000 [info] connection_or_set_canonical(): Channel 0 chose an idle timeout of 206.
...0:07.000 [debug] connection_add_impl(): new conn type Extended OR, socket 20, address 127.0.0.1, n_conns 5.
...0:07.000 [debug] connection_ext_or_start_auth(): ExtORPort authentication: Sending supported authentication types
...0:07.000 [debug] conn_write_callback(): socket 19 wants to write.
...0:07.000 [debug] conn_read_callback(): socket 19 wants to read.
...0:07.000 [debug] read_to_chunk(): Encountered eof on fd 19
...0:07.000 [debug] connection_ext_or_process_inbuf(): Got Extended ORPort authentication data (0).
...0:07.000 [info] connection_or_reached_eof(): OR connection reached EOF. Closing.
...0:07.000 [debug] conn_close_if_marked(): Cleaning up connection (fd 19).
...0:07.000 [info] connection_or_note_state_when_broken(): Connection died in state 'waiting for authentication type with SSL state (No SSL object)'
...0:07.000 [debug] connection_remove(): removing socket 19 (type Extended OR), n_conns now 5
...0:07.000 [debug] connection_free_minimal(): closing fd 19.
...0:07.000 [debug] conn_write_callback(): socket 20 wants to write.
...0:07.000 [debug] conn_read_callback(): socket 20 wants to read.
...0:07.000 [debug] read_to_chunk(): Encountered eof on fd 20
...0:07.000 [debug] connection_ext_or_process_inbuf(): Got Extended ORPort authentication data (0).
...0:07.000 [info] connection_or_reached_eof(): OR connection reached EOF. Closing.
...0:07.000 [debug] conn_close_if_marked(): Cleaning up connection (fd 20).
...0:07.000 [info] connection_or_note_state_when_broken(): Connection died in state 'waiting for authentication type with SSL state (No SSL object)'
...0:07.000 [debug] connection_remove(): removing socket 20 (type Extended OR), n_conns now 4
...0:07.000 [debug] connection_free_minimal(): closing fd 20.
...0:08.000 [debug] periodic_events_rescan_by_roles(): Launching periodic event add_entropy
...0:08.000 [debug] periodic_events_rescan_by_roles(): Launching periodic event heartbeat
...
...0:08.000 [info] router_rebuild_descriptor(): Rebuilding relay descriptor
...0:08.000 [debug] get_address_from_config(): Attempting to get address from configuration
...0:08.000 [info] get_address_from_config(): No Address option found in configuration.
...0:08.000 [debug] get_address_from_orport(): Attempting to get address from ORPort
...0:08.000 [info] address_can_be_used(): Address '0.0.0.0' is a private IP address. Tor relays that use the default DirAuthorities must have public IP addresses.
...0:08.000 [debug] get_address_from_interface(): Attempting to get address from network interface
...0:08.000 [debug] get_interface_address6(): Found internal interface address '10.0.2.100'
...0:08.000 [info] address_can_be_used(): Address '10.0.2.100' is a private IP address. Tor relays that use the default DirAuthorities must have public IP addresses.
...0:08.000 [debug] get_address_from_hostname(): Attempting to get address from local hostname
...0:08.000 [info] tor_getaddrinfo(): (Sandbox) getaddrinfo succeeded.
...0:08.000 [info] address_can_be_used(): Address '127.0.1.1' is a private IP address. Tor relays that use the default DirAuthorities must have public IP addresses.
...0:08.000 [info] find_my_address(): Unable to find our IP address.
...0:08.000 [notice] Unable to find IPv4 address for ORPort XXXX1. You might want to specify IPv4Only to it or set an explicit address or set Address.
...0:08.000 [info] router_build_fresh_unsigned_routerinfo(): Don't know my address while generating descriptor. Launching circuit to authority to learn it.
...
...0:09.000 [info] channel_tls_process_netinfo_cell(): Got good NETINFO cell on OR connection (open) with zzz.zzz.zzz.zzz:443 ID=...; OR connection is now open, using protocol version 5. Its ID digest is ..... Our address is apparently [scrubbed].
...
...1:06.000 [debug] circuit_remove_handled_ports(): Port 443 is already being handled; removing.
...1:07.000 [debug] circuit_remove_handled_ports(): Port 443 is already being handled; removing.
...1:08.000 [info] router_rebuild_descriptor(): Rebuilding relay descriptor
...1:08.000 [debug] get_address_from_config(): Attempting to get address from configuration
...1:08.000 [info] get_address_from_config(): No Address option found in configuration.
...1:08.000 [debug] get_address_from_orport(): Attempting to get address from ORPort
...1:08.000 [info] address_can_be_used(): Address '0.0.0.0' is a private IP address. Tor relays that use the default DirAuthorities must have public IP addresses.
...1:08.000 [debug] get_address_from_interface(): Attempting to get address from network interface
...1:08.000 [debug] get_interface_address6(): Found internal interface address '10.0.2.100'
...1:08.000 [info] address_can_be_used(): Address '10.0.2.100' is a private IP address. Tor relays that use the default DirAuthorities must have public IP addresses.
...1:08.000 [debug] get_address_from_hostname(): Attempting to get address from local hostname
...1:08.000 [info] tor_getaddrinfo(): (Sandbox) getaddrinfo succeeded.
...1:08.000 [info] address_can_be_used(): Address '127.0.1.1' is a private IP address. Tor relays that use the default DirAuthorities must have public IP addresses.
...1:08.000 [info] find_my_address(): Unable to find our IP address.
...1:08.000 [debug] get_address_from_config(): Attempting to get address from configuration
...1:08.000 [info] get_address_from_config(): No Address option found in configuration.
...1:08.000 [debug] get_address_from_orport(): Attempting to get address from ORPort
...1:08.000 [info] address_can_be_used(): Address '::' is a private IP address. Tor relays that use the default DirAuthorities must have public IP addresses.
...1:08.000 [debug] get_address_from_interface(): Attempting to get address from network interface
...1:08.000 [debug] get_interface_address6(): Found internal interface address 'fe80::xxxx:xxxx:xxxx:xxxx'
...1:08.000 [info] address_can_be_used(): Address 'fe80::xxxx:xxxx:xxxx:xxxx' is a private IP address. Tor relays that use the default DirAuthorities must have public IP addresses.
...1:08.000 [debug] get_address_from_hostname(): Attempting to get address from local hostname
...1:08.000 [info] tor_getaddrinfo(): (Sandbox) getaddrinfo failed.
...1:08.000 [info] get_address_from_hostname(): Could not resolve local hostname 'dummyhostname'. Failing.
...1:08.000 [info] find_my_address(): Unable to find our IP address.
...1:08.000 [debug] parse_addr_policy(): Adding new entry 'reject *4:*'
...1:08.000 [debug] parse_addr_policy(): Adding new entry 'reject *6:*'
...1:08.000 [debug] get_address_from_config(): Attempting to get address from configuration
...1:08.000 [info] get_address_from_config(): No Address option found in configuration.
...1:08.000 [debug] get_address_from_orport(): Attempting to get address from ORPort
...1:08.000 [info] address_can_be_used(): Address '0.0.0.0' is a private IP address. Tor relays that use the default DirAuthorities must have public IP addresses.
...1:08.000 [debug] get_address_from_interface(): Attempting to get address from network interface
...1:08.000 [debug] get_interface_address6(): Found internal interface address '10.0.2.100'
...1:08.000 [info] address_can_be_used(): Address '10.0.2.100' is a private IP address. Tor relays that use the default DirAuthorities must have public IP addresses.
...1:08.000 [debug] get_address_from_hostname(): Attempting to get address from local hostname
...1:08.000 [info] tor_getaddrinfo(): (Sandbox) getaddrinfo succeeded.
...1:08.000 [info] address_can_be_used(): Address '127.0.1.1' is a private IP address. Tor relays that use the default DirAuthorities must have public IP addresses.
...1:08.000 [info] find_my_address(): Unable to find our IP address.
...1:08.000 [info] extrainfo_dump_to_string_stats_helper(): Adding stats to extra-info descriptor.
...1:08.000 [debug] file_status(): stat()ing /var/lib/tor/stats/dirreq-stats
...1:08.000 [debug] file_status(): stat()ing /var/lib/tor/stats/hidserv-stats
...1:08.000 [info] router_do_orport_reachability_checks(): Testing reachability of my IPv4 ORPort: xxx.xxx.xxx.xxx:XXXX1.
...1:08.000 [notice] Now checking whether IPv4 ORPort xxx.xxx.xxx.xxx:XXXX1 is reachable... (this may take up to 20 minutes -- look for log messages indicating success)
...1:08.000 [info] origin_circuit_new(): Circuit 7 chose an idle timeout of 3627 based on 3482 seconds of predictive building remaining.
...1:08.000 [debug] new_route_len(): Chosen route length 3 (6620 direct and 6620 indirect routers suitable).
...

      My configuration:

      $ cat /etc/tor/torrc 
RunAsDaemon 0
# We don't need an open SOCKS port.
SocksPort 0
BridgeRelay 1
# A static nickname makes it easy to identify bridges that were set up using
# this Docker image.
Nickname DockerObfs4Bridge
Log notice file /var/log/tor/log
Log notice stdout
ServerTransportPlugin obfs4 exec /usr/bin/obfs4proxy
ExtORPort auto
DataDirectory /var/lib/tor

# The variable "OR_PORT" is replaced with the OR port.
ORPort XXXX1

# The variable "PT_PORT" is replaced with the obfs4 port.
ServerTransportListenAddr obfs4 0.0.0.0:XXXX2

# The variable "EMAIL" is replaced with the operator's email address.
ContactInfo xxx@xxx.xxx

# Additional properties from processed 'OBSFS4V_' environment variables
Log debug file /tmp/debug.log
    • Nick Mathewson changed milestone to %Tor: 0.4.5.x-post-stable

      changed milestone to %Tor: 0.4.5.x-post-stable

    • Nick Mathewson assigned to @dgoulet

      assigned to @dgoulet

    • David Goulet
      David Goulet @dgoulet ·
      Owner

      So the log snippet shows us that you learn your address through the directory authority. So far so good. We need the part of the logs that do the self reachability test and see why it is failing.

      You can send me directly (GPG encrypted) logs if you prefer to dgoulet@torproject.org else post that part only. We need to check what the self reachability test is using to connect back to as in the right IP address or not.

      Edited by David Goulet
    • David Goulet added Needs Information label

      added Needs Information label

    • R
      rotor @rotor ·
      Author

      Here you are - a repeated part with address resolving and one minute of trying to check reachability:

      ...9:30.154 [notice] Tor 0.4.5.6 running on Linux with Libevent 2.1.8-stable, OpenSSL 1.1.1d, Zlib 1.2.11, Liblzma 5.2.4, Libzstd 1.3.8 and Glibc 2.28 as libc.
...
...1:07.000 [debug] circuit_remove_handled_ports(): Port 443 is already being handled; removing.
...1:08.000 [info] router_rebuild_descriptor(): Rebuilding relay descriptor
...1:08.000 [debug] get_address_from_config(): Attempting to get address from configuration
...1:08.000 [info] get_address_from_config(): No Address option found in configuration.
...1:08.000 [debug] get_address_from_orport(): Attempting to get address from ORPort
...1:08.000 [info] address_can_be_used(): Address '0.0.0.0' is a private IP address. Tor relays that use the default DirAuthorities must have public IP addresses.
...1:08.000 [debug] get_address_from_interface(): Attempting to get address from network interface
...1:08.000 [debug] get_interface_address6(): Found internal interface address '10.0.2.100'
...1:08.000 [info] address_can_be_used(): Address '10.0.2.100' is a private IP address. Tor relays that use the default DirAuthorities must have public IP addresses.
...1:08.000 [debug] get_address_from_hostname(): Attempting to get address from local hostname
...1:08.000 [info] tor_getaddrinfo(): (Sandbox) getaddrinfo succeeded.
...1:08.000 [info] address_can_be_used(): Address '127.0.1.1' is a private IP address. Tor relays that use the default DirAuthorities must have public IP addresses.
...1:08.000 [info] find_my_address(): Unable to find our IP address.
...1:08.000 [debug] get_address_from_config(): Attempting to get address from configuration
...1:08.000 [info] get_address_from_config(): No Address option found in configuration.
...1:08.000 [debug] get_address_from_orport(): Attempting to get address from ORPort
...1:08.000 [info] address_can_be_used(): Address '::' is a private IP address. Tor relays that use the default DirAuthorities must have public IP addresses.
...1:08.000 [debug] get_address_from_interface(): Attempting to get address from network interface
...1:08.000 [debug] get_interface_address6(): Found internal interface address 'fe80::xxxx:xxxx:xxxx:xxxx'
...1:08.000 [info] address_can_be_used(): Address 'fe80::xxxx:xxxx:xxxx:xxxx' is a private IP address. Tor relays that use the default DirAuthorities must have public IP addresses.
...1:08.000 [debug] get_address_from_hostname(): Attempting to get address from local hostname
...1:08.000 [info] tor_getaddrinfo(): (Sandbox) getaddrinfo failed.
...1:08.000 [info] get_address_from_hostname(): Could not resolve local hostname 'dummyhostname'. Failing.
...1:08.000 [info] find_my_address(): Unable to find our IP address.
...1:08.000 [debug] parse_addr_policy(): Adding new entry 'reject *4:*'
...1:08.000 [debug] parse_addr_policy(): Adding new entry 'reject *6:*'
...1:08.000 [debug] get_address_from_config(): Attempting to get address from configuration
...1:08.000 [info] get_address_from_config(): No Address option found in configuration.
...1:08.000 [debug] get_address_from_orport(): Attempting to get address from ORPort
...1:08.000 [info] address_can_be_used(): Address '0.0.0.0' is a private IP address. Tor relays that use the default DirAuthorities must have public IP addresses.
...1:08.000 [debug] get_address_from_interface(): Attempting to get address from network interface
...1:08.000 [debug] get_interface_address6(): Found internal interface address '10.0.2.100'
...1:08.000 [info] address_can_be_used(): Address '10.0.2.100' is a private IP address. Tor relays that use the default DirAuthorities must have public IP addresses.
...1:08.000 [debug] get_address_from_hostname(): Attempting to get address from local hostname
...1:08.000 [info] tor_getaddrinfo(): (Sandbox) getaddrinfo succeeded.
...1:08.000 [info] address_can_be_used(): Address '127.0.1.1' is a private IP address. Tor relays that use the default DirAuthorities must have public IP addresses.
...1:08.000 [info] find_my_address(): Unable to find our IP address.
...1:08.000 [info] extrainfo_dump_to_string_stats_helper(): Adding stats to extra-info descriptor.
...1:08.000 [debug] file_status(): stat()ing /var/lib/tor/stats/dirreq-stats
...1:08.000 [debug] file_status(): stat()ing /var/lib/tor/stats/hidserv-stats

...1:08.000 [info] router_do_orport_reachability_checks(): Testing reachability of my IPv4 ORPort: xxx.xxx.xxx.xxx:XXXXX1.
...1:08.000 [notice] Now checking whether IPv4 ORPort xxx.xxx.xxx.xxx:XXXXX1 is reachable... (this may take up to 20 minutes -- look for log messages indicating success)
...1:08.000 [info] origin_circuit_new(): Circuit 7 chose an idle timeout of 3627 based on 3482 seconds of predictive building remaining.
...1:08.000 [debug] new_route_len(): Chosen route length 3 (6620 direct and 6620 indirect routers suitable).
...1:08.000 [info] onion_pick_cpath_exit(): Using requested exit node '$MY_FINGERPRINT~DockerObfs4Bridge [MY_FINGERPRINT_ed25519] at xxx.xxx.xxx.xxx'
...1:08.000 [debug] onion_extend_cpath(): Path is 0 long; we want 3
...1:08.000 [info] select_primary_guard_for_circuit(): Selected primary guard nickname1 ($OTHER_FINGERPRINT1) for circuit from a list size of 1.
...1:08.000 [debug] extend_info_from_node(): using yyy.yyy.yyy.yyy:443 for nickname1
...1:08.000 [info] extend_info_from_node(): Including Ed25519 ID for $OTHER_FINGERPRINT1~nickname1 [OTHER_FINGERPRINT1_ed25519] at yyy.yyy.yyy.yyy
...1:08.000 [debug] onion_extend_cpath(): Chose router $OTHER_FINGERPRINT1~nickname1 [OTHER_FINGERPRINT1_ed25519] at yyy.yyy.yyy.yyy for hop #1 (exit is DockerObfs4Bridge)
...1:08.000 [debug] onion_extend_cpath(): Path is 1 long; we want 3
...1:08.000 [debug] choose_good_middle_server(): Contemplating intermediate hop #2: random choice.
...1:08.000 [debug] router_choose_random_node_helper(): We found 6112 running nodes.
...1:08.000 [debug] compute_weighted_bandwidths(): Generated weighted bandwidths for rule weight as middle node based on weights Wg=0.403200 Wm=1.000000 We=0.000000 Wd=0.000000 with total bw 29531710796.800003
...1:08.000 [debug] extend_info_from_node(): using zzz.zzz.zzz.zzz:ZZZZZ for nickname2
...1:08.000 [info] extend_info_from_node(): Including Ed25519 ID for $OTHER_FINGERPRINT_2~nickname2 [OTHER_FINGERPRINT_2_ed25519] at zzz.zzz.zzz.zzz and [zzzz:zzzz:zzzz]
...1:08.000 [debug] onion_extend_cpath(): Chose router $OTHER_FINGERPRINT_2~nickname2 [OTHER_FINGERPRINT_2_ed25519] at zzz.zzz.zzz.zzz for hop #2 (exit is DockerObfs4Bridge)
...1:08.000 [debug] onion_extend_cpath(): Path is 2 long; we want 3
...1:08.000 [debug] onion_extend_cpath(): Chose router $MY_FINGERPRINT~DockerObfs4Bridge [MY_FINGERPRINT_ed25519] at xxx.xxx.xxx.xxx for hop #3 (exit is DockerObfs4Bridge)
...1:08.000 [debug] onion_extend_cpath(): Path is complete: 3 steps long
...1:08.000 [debug] dispatch_send_msg_unchecked(): Queued: ocirc_cevent (<gid=7 evtype=0 reason=0 onehop=0>) from or, on ocirc.
...1:08.000 [debug] dispatcher_run_msg_cbs(): Delivering: ocirc_cevent (<gid=7 evtype=0 reason=0 onehop=0>) from or, on ocirc:
...1:08.000 [debug] dispatcher_run_msg_cbs():   Delivering to btrack.
...1:08.000 [debug] btc_cevent_rcvr(): CIRC gid=7 evtype=0 reason=0 onehop=0
...1:08.000 [debug] dispatch_send_msg_unchecked(): Queued: ocirc_chan (<gid=7 chan=1 onehop=0>) from or, on ocirc.
...1:08.000 [debug] dispatcher_run_msg_cbs(): Delivering: ocirc_chan (<gid=7 chan=1 onehop=0>) from or, on ocirc:
...1:08.000 [debug] dispatcher_run_msg_cbs():   Delivering to btrack.
...1:08.000 [debug] dispatcher_run_msg_cbs():   Delivering to btrack.
...1:08.000 [debug] btc_chan_rcvr(): CIRC gid=7 chan=1 onehop=0
...1:08.000 [debug] circuit_handle_first_hop(): Conn open for [scrubbed]. Delivering first onion skin.
...1:08.000 [debug] circuit_send_first_onion_skin(): First skin; sending create cell.
...1:08.000 [debug] circuit_get_by_circid_channel_impl(): circuit_get_by_circid_channel_impl() found nothing for circ_id 1111111111, channel ID 1 (0x2222222222)
...1:08.000 [debug] circuit_deliver_create_cell(): Chosen circID 1111111111.
...1:08.000 [debug] circuitmux_attach_circuit(): Attaching circuit 1111111111 on channel 1 to cmux 0x3333333333
...1:08.000 [debug] append_cell_to_circuit_queue(): Made a circuit active.
...1:08.000 [debug] scheduler_set_channel_state(): chan 1 changed from scheduler state WAITING_FOR_CELLS to PENDING
...1:08.000 [debug] dispatch_send_msg_unchecked(): Queued: ocirc_state (<gid=7 state=0 onehop=0>) from or, on ocirc.
...1:08.000 [debug] dispatcher_run_msg_cbs(): Delivering: ocirc_state (<gid=7 state=0 onehop=0>) from or, on ocirc:
...1:08.000 [debug] dispatcher_run_msg_cbs():   Delivering to btrack.
...1:08.000 [debug] btc_state_rcvr(): CIRC gid=7 state=0 onehop=0
...1:08.000 [info] circuit_send_first_onion_skin(): First hop: finished sending CREATE cell to '$OTHER_FINGERPRINT1~nickname1 [OTHER_FINGERPRINT1_ed25519] at yyy.yyy.yyy.yyy'
...1:08.000 [info] update_consensus_router_descriptor_downloads(): 0 router descriptors downloadable. 0 delayed; 6620 present (0 of those were in old_routers); 0 would_reject; 0 wouldnt_use; 0 in progress.
...1:08.000 [debug] scheduler_evt_callback(): Scheduler event callback called
...1:08.000 [debug] update_socket_info(): chan=1 updated socket info, limit: 655340, cwnd: 10, unacked: 0, notsent: 0, mss: 32767
...1:08.000 [debug] kist_scheduler_run(): Running the scheduler. 1 channels pending
...1:08.000 [debug] outbuf_table_add(): scheduler init outbuf info for chan=1
...1:08.000 [debug] channel_write_packed_cell(): Writing 0x9999999999 to channel 0x2222222222 with global ID 1
...1:08.000 [debug] channel_flush_from_first_active_circuit(): Made a circuit inactive.
...1:08.000 [debug] update_socket_written(): chan=1 wrote 543 bytes, old was 0
...1:08.000 [debug] scheduler_set_channel_state(): chan 1 changed from scheduler state PENDING to WAITING_FOR_CELLS
...1:08.000 [debug] channel_write_to_kernel(): Writing 514 bytes to kernel for chan 1
...1:08.000 [debug] flush_chunk_tls(): flushed 514 bytes, 0 remain.
...1:08.000 [debug] connection_handle_write_impl(): After TLS write of 514: 0 read, 543 written
...1:08.000 [debug] free_outbuf_info_by_ent(): Freeing outbuf table entry from chan=1
...1:08.000 [debug] kist_scheduler_run(): len pending=0, len to_readd=-1
...1:08.000 [debug] conn_read_callback(): socket 19 wants to read.
...1:08.000 [debug] connection_buf_read_from_socket(): 19: starting, inbuf_datalen 0 (0 pending in tls object). at_most 16448.
...1:08.000 [debug] tor_tls_read(): read returned r=-1, err=-2
...1:08.000 [debug] connection_buf_read_from_socket(): After TLS read of 514: 543 read, 0 written
...1:08.000 [debug] connection_or_process_cells_from_inbuf(): 19: starting, inbuf_datalen 514 (0 pending in tls object).
...1:08.000 [debug] channel_process_cell(): Processing incoming cell_t 0x444444444 for channel 0x2222222222 (global ID 1)
...1:08.000 [debug] circuit_get_by_circid_channel_impl(): circuit_get_by_circid_channel_impl() returning circuit 0x55555555 for circ_id 1111111111, channel ID 1 (0x2222222222)
...1:08.000 [debug] command_process_created_cell(): at OP. Finishing handshake.
...1:08.000 [info] circuit_finish_handshake(): Finished building circuit hop:
...1:08.000 [info] internal circ (length 3, last hop DockerObfs4Bridge): $OTHER_FINGERPRINT1(open) $OTHER_FINGERPRINT_2(closed) $MY_FINGERPRINT(closed)
...1:08.000 [debug] dispatch_send_msg_unchecked(): Queued: ocirc_cevent (<gid=7 evtype=2 reason=0 onehop=0>) from or, on ocirc.
...1:08.000 [debug] dispatcher_run_msg_cbs(): Delivering: ocirc_cevent (<gid=7 evtype=2 reason=0 onehop=0>) from or, on ocirc:
...1:08.000 [debug] dispatcher_run_msg_cbs():   Delivering to btrack.
...1:08.000 [debug] btc_cevent_rcvr(): CIRC gid=7 evtype=2 reason=0 onehop=0
...1:08.000 [debug] command_process_created_cell(): Moving to next skin.
...1:08.000 [debug] circuit_send_intermediate_onion_skin(): starting to send subsequent skin.
...1:08.000 [info] circuit_send_intermediate_onion_skin(): Sending extend relay cell.
...1:08.000 [debug] relay_send_command_from_edge_(): delivering 14 cell forward.
...1:08.000 [debug] relay_send_command_from_edge_(): Sending a RELAY_EARLY cell; 7 remaining.
...1:08.000 [debug] relay_encrypt_cell_outbound(): encrypting a layer of the relay cell.
...1:08.000 [debug] append_cell_to_circuit_queue(): Made a circuit active.
...1:08.000 [debug] scheduler_set_channel_state(): chan 1 changed from scheduler state WAITING_FOR_CELLS to PENDING
...1:08.000 [debug] connection_or_process_cells_from_inbuf(): 19: starting, inbuf_datalen 0 (0 pending in tls object).
...1:08.000 [debug] circuit_remove_handled_ports(): Port 443 is already being handled; removing.
...1:08.000 [debug] scheduler_evt_callback(): Scheduler event callback called
...1:08.000 [debug] update_socket_info(): chan=1 updated socket info, limit: 655340, cwnd: 10, unacked: 0, notsent: 0, mss: 32767
...1:08.000 [debug] kist_scheduler_run(): Running the scheduler. 1 channels pending
...1:08.000 [debug] outbuf_table_add(): scheduler init outbuf info for chan=1
...1:08.000 [debug] channel_write_packed_cell(): Writing 0x9999999999 to channel 0x2222222222 with global ID 1
...1:08.000 [debug] channel_flush_from_first_active_circuit(): Made a circuit inactive.
...1:08.000 [debug] update_socket_written(): chan=1 wrote 543 bytes, old was 0
...1:08.000 [debug] scheduler_set_channel_state(): chan 1 changed from scheduler state PENDING to WAITING_FOR_CELLS
...1:08.000 [debug] channel_write_to_kernel(): Writing 514 bytes to kernel for chan 1
...1:08.000 [debug] flush_chunk_tls(): flushed 514 bytes, 0 remain.
...1:08.000 [debug] connection_handle_write_impl(): After TLS write of 514: 0 read, 543 written
...1:08.000 [debug] free_outbuf_info_by_ent(): Freeing outbuf table entry from chan=1
...1:08.000 [debug] kist_scheduler_run(): len pending=0, len to_readd=-1
...1:08.000 [debug] conn_read_callback(): socket 19 wants to read.
...1:08.000 [debug] connection_buf_read_from_socket(): 19: starting, inbuf_datalen 0 (0 pending in tls object). at_most 16448.
...1:08.000 [debug] tor_tls_read(): read returned r=-1, err=-2
...1:08.000 [debug] connection_buf_read_from_socket(): After TLS read of 514: 543 read, 0 written
...1:08.000 [debug] connection_or_process_cells_from_inbuf(): 19: starting, inbuf_datalen 514 (0 pending in tls object).
...1:08.000 [debug] channel_process_cell(): Processing incoming cell_t 0x444444444 for channel 0x2222222222 (global ID 1)
...1:08.000 [debug] circuit_get_by_circid_channel_impl(): circuit_get_by_circid_channel_impl() returning circuit 0x55555555 for circ_id 1111111111, channel ID 1 (0x2222222222)
...1:08.000 [debug] circuit_receive_relay_cell(): Sending to origin.
...1:08.000 [debug] connection_edge_process_relay_cell(): Now seen 11 relay cells here (command 15, stream 0).
...1:08.000 [debug] handle_relay_cell_command(): Got an extended cell! Yay.
...1:08.000 [info] circuit_finish_handshake(): Finished building circuit hop:
...1:08.000 [info] internal circ (length 3, last hop DockerObfs4Bridge): $OTHER_FINGERPRINT1(open) $OTHER_FINGERPRINT_2(open) $MY_FINGERPRINT(closed)
...1:08.000 [debug] dispatch_send_msg_unchecked(): Queued: ocirc_cevent (<gid=7 evtype=2 reason=0 onehop=0>) from or, on ocirc.
...1:08.000 [debug] dispatcher_run_msg_cbs(): Delivering: ocirc_cevent (<gid=7 evtype=2 reason=0 onehop=0>) from or, on ocirc:
...1:08.000 [debug] dispatcher_run_msg_cbs():   Delivering to btrack.
...1:08.000 [debug] btc_cevent_rcvr(): CIRC gid=7 evtype=2 reason=0 onehop=0
...1:08.000 [debug] circuit_send_intermediate_onion_skin(): starting to send subsequent skin.
...1:08.000 [info] circuit_send_intermediate_onion_skin(): Sending extend relay cell.
...1:08.000 [debug] relay_send_command_from_edge_(): delivering 14 cell forward.
...1:08.000 [debug] relay_send_command_from_edge_(): Sending a RELAY_EARLY cell; 6 remaining.
...1:08.000 [debug] relay_encrypt_cell_outbound(): encrypting a layer of the relay cell.
...1:08.000 [debug] relay_encrypt_cell_outbound(): encrypting a layer of the relay cell.
...1:08.000 [debug] append_cell_to_circuit_queue(): Made a circuit active.
...1:08.000 [debug] scheduler_set_channel_state(): chan 1 changed from scheduler state WAITING_FOR_CELLS to PENDING
...1:08.000 [debug] connection_or_process_cells_from_inbuf(): 19: starting, inbuf_datalen 0 (0 pending in tls object).
...1:08.000 [debug] scheduler_evt_callback(): Scheduler event callback called
...1:08.000 [debug] update_socket_info(): chan=1 updated socket info, limit: 655340, cwnd: 10, unacked: 0, notsent: 0, mss: 32767
...1:08.000 [debug] kist_scheduler_run(): Running the scheduler. 1 channels pending
...1:08.000 [debug] outbuf_table_add(): scheduler init outbuf info for chan=1
...1:08.000 [debug] channel_write_packed_cell(): Writing 0x9999999999 to channel 0x2222222222 with global ID 1
...1:08.000 [debug] channel_flush_from_first_active_circuit(): Made a circuit inactive.
...1:08.000 [debug] update_socket_written(): chan=1 wrote 543 bytes, old was 0
...1:08.000 [debug] scheduler_set_channel_state(): chan 1 changed from scheduler state PENDING to WAITING_FOR_CELLS
...1:08.000 [debug] channel_write_to_kernel(): Writing 514 bytes to kernel for chan 1
...1:08.000 [debug] flush_chunk_tls(): flushed 514 bytes, 0 remain.
...1:08.000 [debug] connection_handle_write_impl(): After TLS write of 514: 0 read, 543 written
...1:08.000 [debug] free_outbuf_info_by_ent(): Freeing outbuf table entry from chan=1
...1:08.000 [debug] kist_scheduler_run(): len pending=0, len to_readd=-1
...1:09.000 [debug] conn_read_callback(): socket 6 wants to read.
...1:09.000 [debug] connection_handle_listener_read(): Connection accepted on socket 21 (child of fd 6).
...1:09.000 [info] connection_or_set_canonical(): Channel 0 chose an idle timeout of 187.
...1:09.000 [debug] connection_add_impl(): new conn type OR, socket 21, address 10.0.2.100, n_conns 6.
...1:09.000 [debug] dispatch_send_msg_unchecked(): Queued: orconn_status (<gid=8 status=4 reason=0>) from or, on orconn.
...1:09.000 [debug] dispatcher_run_msg_cbs(): Delivering: orconn_status (<gid=8 status=4 reason=0>) from or, on orconn:
...1:09.000 [debug] dispatcher_run_msg_cbs():   Delivering to btrack.
...1:09.000 [debug] channel_tls_start_listener(): Starting TLS channel listener 0x6666666666 with global id 3
...1:09.000 [debug] channel_listener_register(): Registering channel listener 0x6666666666 (ID 3) in state listening (1)
...1:09.000 [debug] channel_listener_set_listener_fn(): Setting listener callback for channel listener 0x6666666666 (global ID 3) to 0x7777777777
...1:09.000 [debug] channel_listener_process_incoming(): Processing queue of incoming connections for channel listener 0x6666666666 (global ID 3)
...1:09.000 [debug] channel_tls_handle_incoming(): Marking new incoming channel 4 at 0x8888888888 as local
...1:09.000 [debug] channel_register(): Registering channel 0x8888888888 (ID 4) in state opening (1) with digest 0000000000000000000000000000000000000000
...1:09.000 [info] channel_register(): Channel 0x8888888888 (global ID 4) in state opening (1) registered with no identity digest
...1:09.000 [debug] channel_listener_queue_incoming(): Queueing incoming channel 0x8888888888 (global ID 4) on channel listener 0x6666666666 (global ID 3)
...1:09.000 [debug] channel_set_cell_handlers(): Setting cell_handler callback for channel 0x8888888888 to 0x4444455555
...1:09.000 [debug] dispatch_send_msg_unchecked(): Queued: orconn_state (<gid=8 chan=4 proxy_type=0 state=3>) from or, on orconn.
...1:09.000 [debug] dispatcher_run_msg_cbs(): Delivering: orconn_state (<gid=8 chan=4 proxy_type=0 state=3>) from or, on orconn:
...1:09.000 [debug] dispatcher_run_msg_cbs():   Delivering to btrack.
...1:09.000 [debug] bto_state_rcvr(): ORCONN gid=8 chan=4 proxy_type=0 state=3
...1:09.000 [debug] connection_tls_start_handshake(): starting TLS handshake on fd 21
...1:09.000 [debug] tor_tls_handshake(): About to call SSL_accept on 0x5555566666 (before SSL initialization)
...1:09.000 [debug] tor_tls_debug_state_callback(): SSL 0x0009998887 is now in state before SSL initialization [type=16,val=1].
...1:09.000 [debug] tor_tls_debug_state_callback(): SSL 0x0009998887 is now in state before SSL initialization [type=8193,val=1].
...1:09.000 [debug] tor_tls_debug_state_callback(): SSL 0x0009998887 is now in state before SSL initialization [type=8193,val=1].
...1:09.000 [debug] tor_tls_debug_state_callback(): SSL 0x0009998887 is now in state SSLv3/TLS read client hello [type=8193,val=1].
...1:09.000 [debug] tor_tls_debug_state_callback(): SSL 0x0009998887 is now in state SSLv3/TLS write server hello [type=8193,val=1].
...1:09.000 [debug] tor_tls_classify_client_ciphers(): Got a non-version-1 cipher called 'TLS_AES_256_GCM_SHA384'
...1:09.000 [debug] tor_tls_classify_client_ciphers(): Got a real V2/V3 cipher list from [scrubbed].  It is: 'TLS_AES_256_GCM_SHA384:TLS_CHACHA20_POLY1305_SHA256:TLS_AES_128_GCM_SHA256:ECDHE-ECDSA-AES128-GCM-SHA256:ECDHE-RSA-AES128-GCM-SHA256:ECDHE-ECDSA-CHACHA20-POLY1305:ECDHE-RSA-CHACHA20-POLY1305:ECDHE-ECDSA-AES256-GCM-SHA384:ECDHE-RSA-AES256-GCM-SHA384:ECDHE-ECDSA-AES256-SHA:ECDHE-ECDSA-AES128-SHA:ECDHE-RSA-AES128-SHA:ECDHE-RSA-AES256-SHA:DHE-RSA-AES128-SHA:DHE-RSA-AES256-SHA:AES128-SHA:AES256-SHA'
...1:09.000 [debug] tor_tls_debug_state_callback(): SSL 0x0009998887 is now in state SSLv3/TLS write change cipher spec [type=8193,val=1].
...1:09.000 [debug] tor_tls_debug_state_callback(): SSL 0x0009998887 is now in state TLSv1.3 write encrypted extensions [type=8193,val=1].
...1:09.000 [debug] tor_tls_debug_state_callback(): SSL 0x0009998887 is now in state SSLv3/TLS write certificate [type=8193,val=1].
...1:09.000 [debug] tor_tls_debug_state_callback(): SSL 0x0009998887 is now in state TLSv1.3 write server certificate verify [type=8193,val=1].
...1:09.000 [debug] tor_tls_debug_state_callback(): SSL 0x0009998887 is now in state SSLv3/TLS write finished [type=8193,val=1].
...1:09.000 [debug] tor_tls_debug_state_callback(): SSL 0x0009998887 is now in state TLSv1.3 early data [type=8193,val=1].
...1:09.000 [debug] tor_tls_debug_state_callback(): SSL 0x0009998887 is now in state TLSv1.3 early data [type=8194,val=-1].
...1:09.000 [debug] tor_tls_handshake(): After call, 0x5555566666 was in state TLSv1.3 early data
...1:09.000 [debug] connection_tls_continue_handshake(): wanted read
...1:09.000 [debug] conn_read_callback(): socket 21 wants to read.
...1:09.000 [debug] tor_tls_handshake(): About to call SSL_accept on 0x5555566666 (TLSv1.3 early data)
...1:09.000 [debug] tor_tls_debug_state_callback(): SSL 0x0009998887 is now in state TLSv1.3 early data [type=8193,val=1].
...1:09.000 [debug] tor_tls_debug_state_callback(): SSL 0x0009998887 is now in state SSLv3/TLS read finished [type=8193,val=1].
...1:09.000 [debug] tor_tls_debug_state_callback(): SSL 0x0009998887 is now in state SSLv3/TLS write session ticket [type=32,val=1].
...1:09.000 [debug] tor_tls_debug_state_callback(): SSL 0x0009998887 is now in state SSLv3/TLS write session ticket [type=8193,val=1].
...1:09.000 [debug] tor_tls_debug_state_callback(): SSL 0x0009998887 is now in state SSLv3/TLS write session ticket [type=8193,val=1].
...1:09.000 [debug] tor_tls_debug_state_callback(): SSL 0x0009998887 is now in state SSL negotiation finished successfully [type=8194,val=1].
...1:09.000 [debug] tor_tls_handshake(): After call, 0x5555566666 was in state SSL negotiation finished successfully
...1:09.000 [debug] tor_tls_finish_handshake(): Completed V2 TLS handshake with client; waiting for renegotiation.
...1:09.000 [debug] connection_tls_continue_handshake(): Done with initial SSL handshake (server-side). Expecting renegotiation or VERSIONS cell
...1:09.000 [debug] dispatch_send_msg_unchecked(): Queued: orconn_state (<gid=8 chan=4 proxy_type=0 state=5>) from or, on orconn.
...1:09.000 [debug] dispatcher_run_msg_cbs(): Delivering: orconn_state (<gid=8 chan=4 proxy_type=0 state=5>) from or, on orconn:
...1:09.000 [debug] dispatcher_run_msg_cbs():   Delivering to btrack.
...1:09.000 [debug] bto_state_rcvr(): ORCONN gid=8 chan=4 proxy_type=0 state=5
...1:09.000 [debug] connection_or_process_cells_from_inbuf(): 21: starting, inbuf_datalen 0 (0 pending in tls object).
...1:09.000 [debug] conn_read_callback(): socket 21 wants to read.
...1:09.000 [debug] connection_buf_read_from_socket(): 21: starting, inbuf_datalen 0 (0 pending in tls object). at_most 16384.
...1:09.000 [debug] tor_tls_read(): read returned r=-1, err=-2
...1:09.000 [debug] connection_buf_read_from_socket(): After TLS read of 11: 436 read, 1320 written
...1:09.000 [debug] connection_or_process_cells_from_inbuf(): 21: starting, inbuf_datalen 11 (0 pending in tls object).
...1:09.000 [debug] dispatch_send_msg_unchecked(): Queued: orconn_state (<gid=8 chan=4 proxy_type=0 state=7>) from or, on orconn.
...1:09.000 [debug] dispatcher_run_msg_cbs(): Delivering: orconn_state (<gid=8 chan=4 proxy_type=0 state=7>) from or, on orconn:
...1:09.000 [debug] dispatcher_run_msg_cbs():   Delivering to btrack.
...1:09.000 [debug] bto_state_rcvr(): ORCONN gid=8 chan=4 proxy_type=0 state=7
...1:09.000 [info] channel_tls_process_versions_cell(): Negotiated version 5 with on OR connection (handshaking (Tor, v3 handshake)) with [scrubbed]; Sending cells: VERSIONS CERTS AUTH_CHALLENGE NETINFO
...1:09.000 [debug] connection_or_process_cells_from_inbuf(): 21: starting, inbuf_datalen 0 (0 pending in tls object).
...1:09.000 [debug] conn_write_callback(): socket 21 wants to write.
...1:09.000 [debug] flush_chunk_tls(): flushed 2016 bytes, 0 remain.
...1:09.000 [debug] connection_handle_write_impl(): After TLS write of 2016: 0 read, 2038 written
...1:09.000 [debug] scheduler_set_channel_state(): chan 4 changed from scheduler state IDLE to WAITING_FOR_CELLS
...1:09.000 [debug] conn_read_callback(): socket 21 wants to read.
...1:09.000 [debug] connection_buf_read_from_socket(): 21: starting, inbuf_datalen 0 (0 pending in tls object). at_most 16384.
...1:09.000 [debug] tor_tls_read(): read returned r=-1, err=-2
...1:09.000 [debug] connection_buf_read_from_socket(): After TLS read of 0: 1448 read, 0 written
...1:09.000 [debug] connection_or_process_cells_from_inbuf(): 21: starting, inbuf_datalen 0 (0 pending in tls object).
...1:09.000 [debug] conn_read_callback(): socket 21 wants to read.
...1:09.000 [debug] connection_buf_read_from_socket(): 21: starting, inbuf_datalen 0 (0 pending in tls object). at_most 16384.
...1:09.000 [debug] tor_tls_read(): read returned r=-1, err=-2
...1:09.000 [debug] connection_buf_read_from_socket(): After TLS read of 2722: 1296 read, 0 written
...1:09.000 [debug] connection_or_process_cells_from_inbuf(): 21: starting, inbuf_datalen 2722 (0 pending in tls object).
...1:09.000 [info] channel_tls_process_certs_cell(): Got some good RSA and Ed25519 certificates on OR connection (handshaking (Tor, v3 handshake)) with [scrubbed]. Waiting for AUTHENTICATE.
...1:09.000 [debug] connection_or_process_cells_from_inbuf(): 21: starting, inbuf_datalen 1391 (0 pending in tls object).
...1:09.000 [debug] channel_tls_process_authenticate_cell(): Calling connection_or_init_conn_from_address on OR connection (handshaking (Tor, v3 handshake)) with [scrubbed]  from channel_tls_process_authenticate_cell, with ed25519 id.
...1:09.000 [debug] connection_or_init_conn_from_address(): init conn from address 10.0.2.100: OTHER_FINGERPRINT_2, OTHER_FINGERPRINT_2_ed25519 (0)
...1:09.000 [info] connection_or_set_identity_digest(): Set identity digest for OR connection (handshaking (Tor, v3 handshake)) with [scrubbed] at 0x5627ee40e5b0: OTHER_FINGERPRINT_2 OTHER_FINGERPRINT_2_ed25519.
...1:09.000 [info] connection_or_set_identity_digest():    (Previously: 0000000000000000000000000000000000000000 <unset>)
...1:09.000 [debug] channel_set_identity_digest(): Setting remote endpoint digest on channel 0x8888888888 with global ID 4 to digest OTHER_FINGERPRINT_2
...1:09.000 [debug] channel_add_to_digest_map(): Added channel 0x8888888888 (global ID 4) to identity map in state opening (1) with digest OTHER_FINGERPRINT_2
...1:09.000 [debug] channel_tls_process_authenticate_cell(): Got an AUTHENTICATE cell on OR connection (handshaking (Tor, v3 handshake)) with 10.0.2.100:58062 ID=OTHER_FINGERPRINT_2_ed25519 RSA_ID=OTHER_FINGERPRINT_2 canonical_addr=zzz.zzz.zzz.zzz:ZZZZZ, type 3: Looks good.
...1:09.000 [debug] connection_or_process_cells_from_inbuf(): 21: starting, inbuf_datalen 1028 (0 pending in tls object).
...1:09.000 [debug] dispatch_send_msg_unchecked(): Queued: orconn_state (<gid=8 chan=4 proxy_type=0 state=8>) from or, on orconn.
...1:09.000 [debug] dispatcher_run_msg_cbs(): Delivering: orconn_state (<gid=8 chan=4 proxy_type=0 state=8>) from or, on orconn:
...1:09.000 [debug] dispatcher_run_msg_cbs():   Delivering to btrack.
...1:09.000 [debug] bto_state_rcvr(): ORCONN gid=8 chan=4 proxy_type=0 state=8
...1:09.000 [debug] channel_change_state_(): Changing state of channel 0x8888888888 (global ID 4) from "opening" to "open"
...1:09.000 [debug] circuit_n_chan_done(): chan to 10.0.2.100:58062 ID=OTHER_FINGERPRINT_2_ed25519 RSA_ID=OTHER_FINGERPRINT_2 canonical_addr=zzz.zzz.zzz.zzz:ZZZZZ, status=1
...1:09.000 [debug] dispatch_send_msg_unchecked(): Queued: orconn_status (<gid=8 status=1 reason=0>) from or, on orconn.
...1:09.000 [debug] dispatcher_run_msg_cbs(): Delivering: orconn_status (<gid=8 status=1 reason=0>) from or, on orconn:
...1:09.000 [debug] dispatcher_run_msg_cbs():   Delivering to btrack.
...1:09.000 [info] channel_tls_process_netinfo_cell(): Got good NETINFO cell on OR connection (open) with 10.0.2.100:58062 ID=OTHER_FINGERPRINT_2_ed25519 RSA_ID=OTHER_FINGERPRINT_2 canonical_addr=zzz.zzz.zzz.zzz:ZZZZZ; OR connection is now open, using protocol version 5. Its ID digest is OTHER_FINGERPRINT_2. Our address is apparently [scrubbed].
...1:09.000 [debug] connection_or_process_cells_from_inbuf(): 21: starting, inbuf_datalen 514 (0 pending in tls object).
...1:09.000 [debug] channel_process_cell(): Processing incoming cell_t 0x444444444 for channel 0x8888888888 (global ID 4)
...1:09.000 [debug] command_process_create_cell(): Got a CREATE cell for circ_id 7777788888 on channel 4 (0x8888888888)
...1:09.000 [debug] circuit_get_by_circid_channel_impl(): circuit_get_by_circid_channel_impl() found nothing for circ_id 7777788888, channel ID 4 (0x8888888888)
...1:09.000 [debug] circuitmux_attach_circuit(): Attaching circuit 7777788888 on channel 4 to cmux 0x8888899999
...1:09.000 [debug] cpuworker_onion_handshake_threadfn(): onion_skin_server_handshake succeeded.
...1:09.000 [debug] assign_onionskin_to_cpuworker(): Queued task 0x9999900000 (qe=0x1111122222, circ=0x2222233333)
...1:09.000 [debug] command_process_create_cell(): success: handed off onionskin.
...1:09.000 [debug] connection_or_process_cells_from_inbuf(): 21: starting, inbuf_datalen 0 (0 pending in tls object).
...1:09.000 [debug] cpuworker_onion_handshake_replyfn(): Unpacking cpuworker reply 0x9999900000, circ=0x2222233333, success=1
...1:09.000 [debug] onionskin_answer(): init digest forward 0x55443322, backward 0x55441100.
...1:09.000 [debug] append_cell_to_circuit_queue(): Made a circuit active.
...1:09.000 [debug] scheduler_set_channel_state(): chan 4 changed from scheduler state WAITING_FOR_CELLS to PENDING
...1:09.000 [debug] onionskin_answer(): Finished sending 'created' cell.
...1:09.000 [debug] cpuworker_onion_handshake_replyfn(): onionskin_answer succeeded. Yay.
...1:09.000 [debug] scheduler_evt_callback(): Scheduler event callback called
...1:09.000 [debug] init_socket_info(): scheduler init socket info for chan=4
...1:09.000 [debug] update_socket_info(): chan=4 updated socket info, limit: 655360, cwnd: 10, unacked: 0, notsent: 0, mss: 32768
...1:09.000 [debug] kist_scheduler_run(): Running the scheduler. 1 channels pending
...1:09.000 [debug] outbuf_table_add(): scheduler init outbuf info for chan=4
...1:09.000 [debug] channel_write_packed_cell(): Writing 0x3333344444 to channel 0x8888888888 with global ID 4
...1:09.000 [debug] channel_flush_from_first_active_circuit(): Made a circuit inactive.
...1:09.000 [debug] update_socket_written(): chan=4 wrote 543 bytes, old was 0
...1:09.000 [debug] scheduler_set_channel_state(): chan 4 changed from scheduler state PENDING to WAITING_FOR_CELLS
...1:09.000 [debug] channel_write_to_kernel(): Writing 514 bytes to kernel for chan 4
...1:09.000 [debug] flush_chunk_tls(): flushed 514 bytes, 0 remain.
...1:09.000 [debug] connection_handle_write_impl(): After TLS write of 514: 0 read, 536 written
...1:09.000 [debug] free_outbuf_info_by_ent(): Freeing outbuf table entry from chan=4
...1:09.000 [debug] kist_scheduler_run(): len pending=0, len to_readd=-1
...1:09.000 [debug] conn_read_callback(): socket 19 wants to read.
...1:09.000 [debug] connection_buf_read_from_socket(): 19: starting, inbuf_datalen 0 (0 pending in tls object). at_most 16448.
...1:09.000 [debug] tor_tls_read(): read returned r=-1, err=-2
...1:09.000 [debug] connection_buf_read_from_socket(): After TLS read of 514: 543 read, 0 written
...1:09.000 [debug] connection_or_process_cells_from_inbuf(): 19: starting, inbuf_datalen 514 (0 pending in tls object).
...1:09.000 [debug] channel_process_cell(): Processing incoming cell_t 0x444444444 for channel 0x2222222222 (global ID 1)
...1:09.000 [debug] circuit_get_by_circid_channel_impl(): circuit_get_by_circid_channel_impl() returning circuit 0x55555555 for circ_id 1111111111, channel ID 1 (0x2222222222)
...1:09.000 [debug] circuit_receive_relay_cell(): Sending to origin.
...1:09.000 [debug] connection_edge_process_relay_cell(): Now seen 12 relay cells here (command 15, stream 0).
...1:09.000 [debug] handle_relay_cell_command(): Got an extended cell! Yay.
...1:09.000 [info] circuit_finish_handshake(): Finished building circuit hop:
...1:09.000 [info] internal circ (length 3, last hop DockerObfs4Bridge): $OTHER_FINGERPRINT1(open) $OTHER_FINGERPRINT_2(open) $MY_FINGERPRINT(open)
...1:09.000 [debug] dispatch_send_msg_unchecked(): Queued: ocirc_cevent (<gid=7 evtype=2 reason=0 onehop=0>) from or, on ocirc.
...1:09.000 [debug] dispatcher_run_msg_cbs(): Delivering: ocirc_cevent (<gid=7 evtype=2 reason=0 onehop=0>) from or, on ocirc:
...1:09.000 [debug] dispatcher_run_msg_cbs():   Delivering to btrack.
...1:09.000 [debug] btc_cevent_rcvr(): CIRC gid=7 evtype=2 reason=0 onehop=0
...1:09.000 [debug] circuit_build_times_add_time(): Adding circuit build time 928
...1:09.000 [info] circuit_build_times_get_xm(): Xm mode #0: 225 218
...1:09.000 [info] circuit_build_times_get_xm(): Xm mode #1: 275 169
...1:09.000 [info] circuit_build_times_get_xm(): Xm mode #2: 225 218
...1:09.000 [info] circuit_build_times_set_timeout(): Set buildtimeout to low value 453.163082ms. Setting to 1500ms
...1:09.000 [info] circuit_build_times_set_timeout(): Set circuit build timeout to 2s (1500.000000ms, 60000.000000ms, Xm: 238, a: 2.499199, r: 0.032000) based on 1000 circuit times
...1:09.000 [info] entry_guards_note_guard_success(): Recorded success for primary confirmed guard nickname1 ($OTHER_FINGERPRINT1)
...1:09.000 [debug] dispatch_send_msg_unchecked(): Queued: ocirc_state (<gid=7 state=4 onehop=0>) from or, on ocirc.
...1:09.000 [debug] dispatcher_run_msg_cbs(): Delivering: ocirc_state (<gid=7 state=4 onehop=0>) from or, on ocirc:
...1:09.000 [debug] dispatcher_run_msg_cbs():   Delivering to btrack.
...1:09.000 [debug] btc_state_rcvr(): CIRC gid=7 state=4 onehop=0
...1:09.000 [info] circuit_build_no_more_hops(): circuit built!
...1:09.000 [debug] dispatch_send_msg_unchecked(): Queued: ocirc_cevent (<gid=7 evtype=1 reason=0 onehop=0>) from or, on ocirc.
...1:09.000 [debug] dispatcher_run_msg_cbs(): Delivering: ocirc_cevent (<gid=7 evtype=1 reason=0 onehop=0>) from or, on ocirc:
...1:09.000 [debug] dispatcher_run_msg_cbs():   Delivering to btrack.
...1:09.000 [debug] btc_cevent_rcvr(): CIRC gid=7 evtype=1 reason=0 onehop=0
...1:09.000 [debug] circuit_get_by_circid_channel_impl(): circuit_get_by_circid_channel_impl() returning circuit 0x55555555 for circ_id 1111111111, channel ID 1 (0x2222222222)
...1:09.000 [info] circuit_mark_for_close_(): Circuit 1111111111 (id: 7) marked for close at ../src/core/or/circuituse.c:1660 (orig reason: -1, new reason: 0)
...1:09.000 [debug] connection_or_process_cells_from_inbuf(): 19: starting, inbuf_datalen 0 (0 pending in tls object).
...1:09.000 [debug] dispatch_send_msg_unchecked(): Queued: ocirc_cevent (<gid=7 evtype=4 reason=-1 onehop=0>) from or, on ocirc.
...1:09.000 [debug] dispatcher_run_msg_cbs(): Delivering: ocirc_cevent (<gid=7 evtype=4 reason=-1 onehop=0>) from or, on ocirc:
...1:09.000 [debug] dispatcher_run_msg_cbs():   Delivering to btrack.
...1:09.000 [debug] btc_cevent_rcvr(): CIRC gid=7 evtype=4 reason=-1 onehop=0
...1:09.000 [debug] circuit_get_by_circid_channel_impl(): circuit_get_by_circid_channel_impl() returning circuit 0x55555555 for circ_id 1111111111, channel ID 1 (0x2222222222)
...1:09.000 [debug] circuitmux_append_destroy_cell(): Cmux at 0x3333333333 queued a destroy for circ 1111111111, cmux counter is now 1, global counter is now 1
...1:09.000 [debug] circuitmux_append_destroy_cell(): Primed a buffer.
...1:09.000 [debug] channel_write_packed_cell(): Writing 0x3333344444 to channel 0x2222222222 with global ID 1
...1:09.000 [debug] circuit_get_by_circid_channel_impl(): circuit_get_by_circid_channel_impl() returning circuit 0x55555555 for circ_id 1111111111, channel ID 1 (0x2222222222)
...1:09.000 [debug] circuitmux_notify_xmit_destroy(): Cmux at 0x3333333333 sent a destroy, cmux counter is now 0, global counter is now 0
...1:09.000 [debug] channel_send_destroy(): Sending destroy (circID 1111111111) on channel 0x2222222222 (global ID 1)
...1:09.000 [info] circuit_free_(): Circuit 0 (id: 7) has been freed.
...1:09.000 [debug] conn_write_callback(): socket 19 wants to write.
...1:09.000 [debug] flush_chunk_tls(): flushed 514 bytes, 0 remain.
...1:09.000 [debug] connection_handle_write_impl(): After TLS write of 514: 0 read, 543 written
...1:09.000 [debug] conn_read_callback(): socket 21 wants to read.
...1:09.000 [debug] connection_buf_read_from_socket(): 21: starting, inbuf_datalen 0 (0 pending in tls object). at_most 1073741824.
...1:09.000 [debug] tor_tls_read(): read returned r=-1, err=-2
...1:09.000 [debug] connection_buf_read_from_socket(): After TLS read of 514: 536 read, 0 written
...1:09.000 [debug] connection_or_process_cells_from_inbuf(): 21: starting, inbuf_datalen 514 (0 pending in tls object).
...1:09.000 [debug] channel_process_cell(): Processing incoming cell_t 0x444444444 for channel 0x8888888888 (global ID 4)
...1:09.000 [debug] circuit_get_by_circid_channel_impl(): circuit_get_by_circid_channel_impl() returning circuit 0x2222233333 for circ_id 7777788888, channel ID 4 (0x8888888888)
...1:09.000 [debug] command_process_destroy_cell(): Received for circID 7777788888.
...1:09.000 [info] circuit_mark_for_close_(): Circuit 0 (id: 0) marked for close at ../src/core/or/command.c:634 (orig reason: 512, new reason: 0)
...1:09.000 [debug] connection_or_process_cells_from_inbuf(): 21: starting, inbuf_datalen 0 (0 pending in tls object).
...1:09.000 [info] circuit_free_(): Circuit 0 (id: 0) has been freed.
...1:09.000 [debug] circuit_remove_handled_ports(): Port 443 is already being handled; removing.
...1:10.000 [debug] pathbias_count_circs_in_states(): Found opened circuit 1 in path_state build succeeded
...1:10.000 [debug] pathbias_count_circs_in_states(): Found opened circuit 3 in path_state build succeeded
...1:10.000 [debug] pathbias_count_circs_in_states(): Found opened circuit 4 in path_state build succeeded
...1:10.000 [debug] pathbias_count_circs_in_states(): Found opened circuit 5 in path_state build succeeded
...1:10.000 [debug] pathbias_count_circs_in_states(): Found opened circuit 6 in path_state build succeeded
...1:10.000 [debug] tor_rename(): Renaming /var/lib/tor/state.tmp to /var/lib/tor/state
...1:10.000 [info] or_state_save(): Saved state to "/var/lib/tor/state"
...1:10.000 [debug] circuit_remove_handled_ports(): Port 443 is already being handled; removing.
...1:11.000 [debug] conn_read_callback(): socket 20 wants to read.
...1:11.000 [debug] connection_buf_read_from_socket(): 20: starting, inbuf_datalen 0 (0 pending in tls object). at_most 16448.
...1:11.000 [debug] tor_tls_read(): read returned r=-1, err=-2
...1:11.000 [debug] connection_buf_read_from_socket(): After TLS read of 514: 536 read, 0 written
...1:11.000 [debug] connection_or_process_cells_from_inbuf(): 20: starting, inbuf_datalen 514 (0 pending in tls object).
...1:11.000 [debug] channel_process_cell(): Processing incoming cell_t 0x444444444 for channel 0x2222211111 (global ID 2)
...1:11.000 [debug] circuit_get_by_circid_channel_impl(): circuit_get_by_circid_channel_impl() returning circuit 0x5627ec66e410 for circ_id 2222333344, channel ID 2 (0x2222211111)
...1:11.000 [debug] command_process_destroy_cell(): Received for circID 2222333344.
...1:11.000 [info] circuit_mark_for_close_(): Circuit 0 (id: 2) marked for close at ../src/core/or/command.c:638 (orig reason: 521, new reason: 0)
...1:11.000 [debug] connection_or_process_cells_from_inbuf(): 20: starting, inbuf_datalen 0 (0 pending in tls object).
...1:11.000 [debug] dispatch_send_msg_unchecked(): Queued: ocirc_cevent (<gid=2 evtype=4 reason=521 onehop=1>) from or, on ocirc.
...1:11.000 [debug] dispatcher_run_msg_cbs(): Delivering: ocirc_cevent (<gid=2 evtype=4 reason=521 onehop=1>) from or, on ocirc:
...1:11.000 [debug] dispatcher_run_msg_cbs():   Delivering to btrack.
...1:11.000 [debug] btc_cevent_rcvr(): CIRC gid=2 evtype=4 reason=521 onehop=1
...1:11.000 [info] circuit_free_(): Circuit 0 (id: 2) has been freed.
...1:11.000 [debug] circuit_remove_handled_ports(): Port 443 is already being handled; removing.
...1:12.000 [debug] circuit_remove_handled_ports(): Port 443 is already being handled; removing.
...1:13.000 [debug] circuit_remove_handled_ports(): Port 443 is already being handled; removing.
...1:14.000 [debug] circuit_remove_handled_ports(): Port 443 is already being handled; removing.
...1:15.000 [debug] conn_read_callback(): socket 19 wants to read.
...1:15.000 [debug] connection_buf_read_from_socket(): 19: starting, inbuf_datalen 0 (0 pending in tls object). at_most 16448.
...1:15.000 [debug] tor_tls_read(): read returned r=-1, err=-2
...1:15.000 [debug] connection_buf_read_from_socket(): After TLS read of 514: 543 read, 0 written
...1:15.000 [debug] connection_or_process_cells_from_inbuf(): 19: starting, inbuf_datalen 514 (0 pending in tls object).
...1:15.000 [debug] connection_or_process_cells_from_inbuf(): 19: starting, inbuf_datalen 0 (0 pending in tls object).
...1:15.000 [debug] circuit_remove_handled_ports(): Port 443 is already being handled; removing.
...1:16.000 [debug] circuit_remove_handled_ports(): Port 443 is already being handled; removing.
...1:17.000 [debug] circuit_remove_handled_ports(): Port 443 is already being handled; removing.
...1:18.000 [debug] circuit_remove_handled_ports(): Port 443 is already being handled; removing.
...1:19.000 [debug] circuit_remove_handled_ports(): Port 443 is already being handled; removing.
...1:20.000 [debug] conn_read_callback(): socket 19 wants to read.
...1:20.000 [debug] connection_buf_read_from_socket(): 19: starting, inbuf_datalen 0 (0 pending in tls object). at_most 16448.
...1:20.000 [debug] tor_tls_read(): read returned r=-1, err=-2
...1:20.000 [debug] connection_buf_read_from_socket(): After TLS read of 514: 543 read, 0 written
...1:20.000 [debug] connection_or_process_cells_from_inbuf(): 19: starting, inbuf_datalen 514 (0 pending in tls object).
...1:20.000 [debug] connection_or_process_cells_from_inbuf(): 19: starting, inbuf_datalen 0 (0 pending in tls object).
...1:20.000 [debug] circuit_remove_handled_ports(): Port 443 is already being handled; removing.
...1:21.000 [debug] circuit_remove_handled_ports(): Port 443 is already being handled; removing.
...1:22.000 [debug] circuit_remove_handled_ports(): Port 443 is already being handled; removing.
...1:23.000 [debug] circuit_remove_handled_ports(): Port 443 is already being handled; removing.
...1:24.000 [debug] circuit_remove_handled_ports(): Port 443 is already being handled; removing.
...1:25.000 [debug] circuit_remove_handled_ports(): Port 443 is already being handled; removing.
...1:26.000 [debug] circuit_remove_handled_ports(): Port 443 is already being handled; removing.
...1:27.000 [info] channelpadding_send_padding_cell_for_callback(): Sending netflow keepalive on 1 to [scrubbed] ([scrubbed]) after 6975 ms. Delta 2ms
...1:27.000 [debug] conn_write_callback(): socket 19 wants to write.
...1:27.000 [debug] flush_chunk_tls(): flushed 514 bytes, 0 remain.
...1:27.000 [debug] connection_handle_write_impl(): After TLS write of 514: 0 read, 543 written
...1:27.000 [debug] circuit_remove_handled_ports(): Port 443 is already being handled; removing.
...1:28.000 [debug] circuit_remove_handled_ports(): Port 443 is already being handled; removing.
...1:29.000 [debug] circuit_remove_handled_ports(): Port 443 is already being handled; removing.
...1:30.000 [debug] circuit_remove_handled_ports(): Port 443 is already being handled; removing.
...1:31.000 [debug] circuit_remove_handled_ports(): Port 443 is already being handled; removing.
...1:32.000 [debug] circuit_remove_handled_ports(): Port 443 is already being handled; removing.
...1:33.000 [debug] circuit_remove_handled_ports(): Port 443 is already being handled; removing.
...1:34.000 [info] channelpadding_send_padding_cell_for_callback(): Sending netflow keepalive on 1 to [scrubbed] ([scrubbed]) after 6804 ms. Delta 1ms
...1:34.000 [debug] conn_write_callback(): socket 19 wants to write.
...1:34.000 [debug] flush_chunk_tls(): flushed 514 bytes, 0 remain.
...1:34.000 [debug] connection_handle_write_impl(): After TLS write of 514: 0 read, 543 written
...1:34.000 [debug] circuit_remove_handled_ports(): Port 443 is already being handled; removing.
...1:35.000 [debug] circuit_remove_handled_ports(): Port 443 is already being handled; removing.
...1:36.000 [debug] circuit_remove_handled_ports(): Port 443 is already being handled; removing.
...1:37.000 [debug] circuit_remove_handled_ports(): Port 443 is already being handled; removing.
...1:38.000 [debug] circuit_remove_handled_ports(): Port 443 is already being handled; removing.
...1:39.000 [info] channelpadding_send_padding_cell_for_callback(): Sending netflow keepalive on 1 to [scrubbed] ([scrubbed]) after 5119 ms. Delta 1ms
...1:39.000 [debug] conn_write_callback(): socket 19 wants to write.
...1:39.000 [debug] flush_chunk_tls(): flushed 514 bytes, 0 remain.
...1:39.000 [debug] connection_handle_write_impl(): After TLS write of 514: 0 read, 543 written
...1:39.000 [debug] circuit_remove_handled_ports(): Port 443 is already being handled; removing.
...1:40.000 [debug] circuit_remove_handled_ports(): Port 443 is already being handled; removing.
...1:41.000 [debug] circuit_remove_handled_ports(): Port 443 is already being handled; removing.
...1:42.000 [debug] circuit_remove_handled_ports(): Port 443 is already being handled; removing.
...1:43.000 [debug] circuit_remove_handled_ports(): Port 443 is already being handled; removing.
...1:44.000 [debug] circuit_remove_handled_ports(): Port 443 is already being handled; removing.
...1:45.000 [debug] circuit_remove_handled_ports(): Port 443 is already being handled; removing.
...1:46.000 [debug] circuit_remove_handled_ports(): Port 443 is already being handled; removing.
...1:47.000 [info] channelpadding_send_padding_cell_for_callback(): Sending netflow keepalive on 1 to [scrubbed] ([scrubbed]) after 7752 ms. Delta 2ms
...1:47.000 [debug] conn_write_callback(): socket 19 wants to write.
...1:47.000 [debug] flush_chunk_tls(): flushed 514 bytes, 0 remain.
...1:47.000 [debug] connection_handle_write_impl(): After TLS write of 514: 0 read, 543 written
...1:47.000 [debug] circuit_remove_handled_ports(): Port 443 is already being handled; removing.
...1:48.000 [debug] circuit_remove_handled_ports(): Port 443 is already being handled; removing.
...1:49.000 [debug] conn_read_callback(): socket 19 wants to read.
...1:49.000 [debug] connection_buf_read_from_socket(): 19: starting, inbuf_datalen 0 (0 pending in tls object). at_most 16448.
...1:49.000 [debug] tor_tls_read(): read returned r=-1, err=-2
...1:49.000 [debug] connection_buf_read_from_socket(): After TLS read of 514: 543 read, 0 written
...1:49.000 [debug] connection_or_process_cells_from_inbuf(): 19: starting, inbuf_datalen 514 (0 pending in tls object).
...1:49.000 [debug] connection_or_process_cells_from_inbuf(): 19: starting, inbuf_datalen 0 (0 pending in tls object).
...1:49.000 [debug] circuit_remove_handled_ports(): Port 443 is already being handled; removing.
...1:50.000 [debug] circuit_remove_handled_ports(): Port 443 is already being handled; removing.
...1:51.000 [debug] circuit_remove_handled_ports(): Port 443 is already being handled; removing.
...1:52.000 [debug] circuit_remove_handled_ports(): Port 443 is already being handled; removing.
...1:53.000 [debug] circuit_remove_handled_ports(): Port 443 is already being handled; removing.
...1:54.000 [debug] circuit_remove_handled_ports(): Port 443 is already being handled; removing.
...1:55.000 [debug] circuit_remove_handled_ports(): Port 443 is already being handled; removing.
...1:56.000 [info] channelpadding_send_padding_cell_for_callback(): Sending netflow keepalive on 1 to [scrubbed] ([scrubbed]) after 7214 ms. Delta 1ms
...1:56.000 [debug] conn_write_callback(): socket 19 wants to write.
...1:56.000 [debug] flush_chunk_tls(): flushed 514 bytes, 0 remain.
...1:56.000 [debug] connection_handle_write_impl(): After TLS write of 514: 0 read, 543 written
...1:56.000 [debug] circuit_remove_handled_ports(): Port 443 is already being handled; removing.
...1:57.000 [debug] circuit_remove_handled_ports(): Port 443 is already being handled; removing.
...1:58.000 [debug] circuit_remove_handled_ports(): Port 443 is already being handled; removing.
...1:59.000 [debug] circuit_remove_handled_ports(): Port 443 is already being handled; removing.
...2:00.000 [debug] circuit_remove_handled_ports(): Port 443 is already being handled; removing.
...2:01.000 [debug] circuit_remove_handled_ports(): Port 443 is already being handled; removing.
...2:02.000 [debug] circuit_remove_handled_ports(): Port 443 is already being handled; removing.
...2:03.000 [debug] circuit_remove_handled_ports(): Port 443 is already being handled; removing.
...2:04.000 [debug] circuit_remove_handled_ports(): Port 443 is already being handled; removing.
...2:04.000 [debug] conn_read_callback(): socket 19 wants to read.
...2:04.000 [debug] connection_buf_read_from_socket(): 19: starting, inbuf_datalen 0 (0 pending in tls object). at_most 16448.
...2:04.000 [debug] tor_tls_read(): read returned r=-1, err=-2
...2:04.000 [debug] connection_buf_read_from_socket(): After TLS read of 514: 543 read, 0 written
...2:04.000 [debug] connection_or_process_cells_from_inbuf(): 19: starting, inbuf_datalen 514 (0 pending in tls object).
...2:04.000 [debug] connection_or_process_cells_from_inbuf(): 19: starting, inbuf_datalen 0 (0 pending in tls object).
...2:05.000 [debug] circuit_remove_handled_ports(): Port 443 is already being handled; removing.
...2:06.000 [debug] circuit_remove_handled_ports(): Port 443 is already being handled; removing.
...2:07.000 [debug] circuit_remove_handled_ports(): Port 443 is already being handled; removing.
...2:08.000 [info] update_consensus_router_descriptor_downloads(): 0 router descriptors downloadable. 0 delayed; 6620 present (0 of those were in old_routers); 0 would_reject; 0 wouldnt_use; 0 in progress.

...2:08.000 [info] router_do_orport_reachability_checks(): Testing reachability of my IPv4 ORPort: xxx.xxx.xxx.xxx:XXXXX1.

      Let me know if you need anything else.

    • David Goulet
      David Goulet @dgoulet ·
      Owner

      Logs shows it is reachable. I do see a private address in the logs also (10.0.0.0/8 network) so I think for the relay to be considered reachable, you might need to set ExtendAllowPrivateAddresses if you are on an internal network. Else I think the code path for reachability from the selftest doesn't trigger.

      But all in all, this obfs4 bridge should work does it?

    • R
      rotor @rotor ·
      Author

      you might need to set ExtendAllowPrivateAddresses if you are on an internal network

      I'm definitely on an internal Podman network which is used by my container to have networking. I've checked with ExtendAllowPrivateAddresses and it worked:

      Self-testing indicates your ORPort xxx.xxx.xxx.xxx.XXXXX is reachable from the outside. Excellent. Publishing server descriptor.

      :thumbsup:

      However, based on the manual:

      Enabling this option can create security issues; you should probably leave it off.

      It would be nice to have possible without that option. Especially, that it worked fine with 0.4.3.5.

      But all in all, this obfs4 bridge should work does it?

      Yes, I've just checked it with a TorBrowser (without ExtendAllowPrivateAddresses) and I was able to use my bridge. Nevertheless, it doesn't seem to be published, so nobody knows about it.

      Edited by rotor
    • R
      rotor @rotor ·
      Author

      @dgoulet In relation to my recent email message: DD0F A338 5A9C DDE5 BF4D 1914 DA9F F1A2 30A9 7717

    • M
      maha @maha ·

      Downstream bug report for Fedora 33 - https://bugzilla.redhat.com/show_bug.cgi?id=1941197

    • David Goulet added Backlog label

      added Backlog label

    • Loading
    • Loading
    • Loading
    • Loading
    • Loading
    • Loading
    • Loading
    • Loading
    • Loading
    • Loading
    Please register or sign in to reply