Opened 12 months ago

Last modified 3 months ago

#28229 new defect

Possible race condition opening SOCKS Port in test_rebind.py

Reported by: teor Owned by: rl1987
Priority: Medium Milestone: Tor: unspecified
Component: Core Tor/Tor Version: Tor: 0.3.5.1-alpha
Severity: Normal Keywords: tor-ci, rare?, 035-backport, 040-backport, 041-deferred-20190719
Cc: Actual Points:
Parent ID: Points: 1
Reviewer: Sponsor:

Description

test_rebind.py failed in master because the SOCKSPort wasn't open when the python script tried to connect:
https://travis-ci.org/torproject/tor/builds/448008717

When we merge #27968, we'll get better debugging. But we should also print all the tor logs to the console, particularly when there is a failure.

And we should print the test_rebind.py logs with timestamps.

Child Tickets

TicketStatusOwnerSummaryComponent
#30713closedteorDisable or allow_fail test_rebind.py in macOS TravisCore Tor/Tor

Change History (34)

comment:1 Changed 12 months ago by rl1987

Owner: set to rl1987
Status: newaccepted

Will try to look into this in next few days.

comment:2 Changed 12 months ago by rl1987

Patch for diagnostics: https://github.com/torproject/tor/pull/473

This should help with digging up the root cause of the failure, if it happens again.

comment:3 Changed 12 months ago by teor

Status: acceptedneeds_review

We should review and merge this patch, then leave the ticket open for further analysis.

comment:4 Changed 12 months ago by dgoulet

Reviewer: catalyst

comment:5 in reply to:  2 Changed 11 months ago by catalyst

Status: needs_reviewmerge_ready

Replying to rl1987:

Patch for diagnostics: https://github.com/torproject/tor/pull/473

This should help with digging up the root cause of the failure, if it happens again.

Thanks for the patch! I left a minor comment on the pull request, which you may address if you like (timestamp redundancy).

comment:6 Changed 11 months ago by nickm

Keywords: 035-can added

comment:7 Changed 11 months ago by teor

Status: merge_readyneeds_revision

The logging needs millisecond resolution: second resolution is not enough to reassemble the script and tor logs in the correct order.

I left some detailed notes on the pull request.

comment:8 Changed 11 months ago by rl1987

Status: needs_revisionneeds_review

comment:9 Changed 11 months ago by catalyst

Reviewer: catalystteor

Reviewer to teor because they made the most recent round of review feedback. Please feel free to toss back to me if necessary.

comment:10 Changed 11 months ago by teor

Status: needs_reviewmerge_ready

This change seems fine to me.

comment:11 Changed 11 months ago by nickm

Status: merge_readyassigned

I've squashed and rebased the branch as bug28229_diag_035, and merged it to 0.3.5.

Since this is a diagnostic patch, I assume I should not actually close this issue. setting it to new again.

comment:12 Changed 11 months ago by nickm

Status: assignednew

comment:13 Changed 11 months ago by nickm

I think this build log might have an example of the failure: https://travis-ci.org/torproject/tor/jobs/462336253

comment:14 Changed 11 months ago by rl1987

Some notes about the above CI log:

  • test_rebind.py fails to connect to SOCKS listener after rebinding - it succeeds connecting the first time.
  • There's no log messages about closing the 127.0.0.1:13790 listener, or the new listener being replaced by new one. Weird.

comment:15 Changed 11 months ago by rl1987

One more pull request for diagnostics: https://github.com/torproject/tor/pull/560

  • This time, let's use getsockopt() to check if new listener is actually listening.
  • Let's log some stuff when socket rebinding is supposed to happen.
  • Let's log the proper error message when socket.connect_ex() fails on Python side.

comment:16 Changed 11 months ago by rl1987

Status: newneeds_review

comment:17 Changed 11 months ago by teor

Status: needs_reviewmerge_ready

Looks good to me, but it's a diagnostic, so we shouldn't close the ticket.

comment:18 Changed 11 months ago by nickm

Status: merge_readyassigned

Merged to master, not closed.

comment:19 Changed 11 months ago by nickm

Status: assignednew

comment:20 Changed 9 months ago by rl1987

https://travis-ci.org/rl1987/tor/jobs/481321719

Hmmm....

2019-01-18 11:58:35.059 Tor logged: "Jan 18 11:58:35.059 [info] set_max_file_descriptors: Raising max file descriptors from 10208 to 9223372036854775807.", waiting for "Opened Socks listener"
2019-01-18 11:58:35.059 Tor logged: "Jan 18 11:58:35.059 [info] set_max_file_descriptors: Dropped connection limit to 10208 based on OPEN_MAX (10240); Apparently, 9223372036854775807 was too high and rlimit lied to us.", waiting for "Opened Socks listener"
2019-01-18 11:58:35.059 Tor logged: "Jan 18 11:58:35.059 [warn] You specified a public address '0.0.0.0:58579' for SocksPort. Other people on the Internet might find your computer and use it as an open proxy. Please don't allow this unless you have a good reason.", waiting for "Opened Socks listener"
2019-01-18 11:58:35.060 Tor logged: "Jan 18 11:58:35.059 [debug] retry_all_listeners: 1 replacements - starting rebinding loop.", waiting for "Opened Socks listener"
2019-01-18 11:58:35.060 Tor logged: "Jan 18 11:58:35.060 [notice] Opening Socks listener on 0.0.0.0:58579", waiting for "Opened Socks listener"
2019-01-18 11:58:35.060 Tor logged: "Jan 18 11:58:35.060 [debug] connection_add_impl: new conn type Socks listener, socket 7, address 0.0.0.0, n_conns 4.", waiting for "Opened Socks listener"
2019-01-18 11:58:35.060 Tor logged: "Jan 18 11:58:35.060 [debug] connection_listener_new: Socks listener listening on port 58579.", waiting for "Opened Socks listener"
2019-01-18 11:58:35.060 Tor logged: "Jan 18 11:58:35.060 [notice] Opened Socks listener on 0.0.0.0:58579"
2019-01-18 11:58:35.060 FAIL
Cannot connect to SOCKSPort: error Connection reset by peer

setrlimit() failed to raise number of open file descriptors we can have. Note that it tries to raise it to LLONG_MAX (http://pubs.opengroup.org/onlinepubs/009604499/basedefs/limits.h.html), which is suspicious. Perhaps that causes listener failure to happen? Perhaps we should sanity check rlim.rlim_max that we get from getrlimit() before trying to use it?

comment:21 Changed 9 months ago by teor

I thought we already checked rlim_max, particularly on Apple.
But maybe some of our recent changes have skipped that check?

comment:22 Changed 7 months ago by teor

There's another failure here:
https://travis-ci.org/torproject/tor/jobs/511356805#L3986

I'm not sure why it failed, there's no error.

comment:23 Changed 7 months ago by teor

Keywords: 035-can removed
Milestone: Tor: 0.3.5.x-finalTor: unspecified
Priority: HighLow

This failure seems to be infrequent enough. It's not a high priority.

comment:24 Changed 6 months ago by teor

Keywords: rare? 035-backport 040-backport added
Milestone: Tor: unspecifiedTor: 0.4.1.x-final
Points: 1
Reviewer: teor

release-0.4.0 failed with this issue today:

FAIL: src/test/test_rebind.sh
=============================
++uname -s
++cut -d_ -f1
+UNAME_OS=Darwin
+test Darwin = CYGWIN
+test Darwin = MSYS
+test Darwin = MINGW
+exitcode=0
+tmpdir=
+trap clean EXIT HUP INT TERM
++mktemp -d -t tor_rebind_test.XXXXXX
+tmpdir=/var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/tor_rebind_test.XXXXXX.d7UUkHM4
+'[' -z /var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/tor_rebind_test.XXXXXX.d7UUkHM4 ']'
+'[' '!' -d /var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/tor_rebind_test.XXXXXX.d7UUkHM4 ']'
+python3 /Users/travis/build/torproject/tor/src/test/test_rebind.py ./src/app/tor /var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/tor_rebind_test.XXXXXX.d7UUkHM4
2019-04-09 02:19:57.210 Tor logged: "Apr 09 02:19:57.207 [notice] Tor 0.4.0.3-alpha-dev (git-2fd02c82edbf98f1) running on Darwin with Libevent 2.1.8-stable, OpenSSL 1.0.2o, Zlib 1.2.11, Liblzma 5.2.4, and Libzstd 1.3.4.", waiting for "Opened Control listener on"
2019-04-09 02:19:57.211 Tor logged: "Apr 09 02:19:57.209 [notice] Tor can't help you if you use it wrong! Learn how to be safe at https://www.torproject.org/download/download#warning", waiting for "Opened Control listener on"
2019-04-09 02:19:57.211 Tor logged: "Apr 09 02:19:57.209 [notice] This version is not a stable Tor release. Expect more bugs than usual.", waiting for "Opened Control listener on"
2019-04-09 02:19:57.211 Tor logged: "Apr 09 02:19:57.209 [notice] Configuration file "/usr/local/etc/tor/torrc" not present, using reasonable defaults.", waiting for "Opened Control listener on"
2019-04-09 02:19:57.224 Tor logged: "Apr 09 02:19:57.224 [warn] ControlPort is open, but no authentication method has been configured.  This means that any program on your computer can reconfigure your Tor.  That's bad!  You should upgrade your Tor controller as soon as possible.", waiting for "Opened Control listener on"
2019-04-09 02:19:57.227 Tor logged: "Apr 09 02:19:57.227 [notice] Opening Socks listener on 127.0.0.1:14394", waiting for "Opened Control listener on"
2019-04-09 02:19:57.227 Tor logged: "Apr 09 02:19:57.227 [notice] Opened Socks listener on 127.0.0.1:14394", waiting for "Opened Control listener on"
2019-04-09 02:19:57.227 Tor logged: "Apr 09 02:19:57.227 [notice] Opening Control listener on 127.0.0.1:17557", waiting for "Opened Control listener on"
2019-04-09 02:19:57.227 Tor logged: "Apr 09 02:19:57.227 [notice] Opened Control listener on 127.0.0.1:17557"
2019-04-09 02:19:57.228 Tor logged: "Apr 09 02:19:57.228 [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.", waiting for "Opened Socks listener"
2019-04-09 02:19:57.228 Tor logged: "Apr 09 02:19:57.228 [info] options_act_reversible: Recomputed OOS thresholds: ConnLimit 1000, ConnLimit_ 10176, ConnLimit_high_thresh 10112, ConnLimit_low_thresh 7632", waiting for "Opened Socks listener"
2019-04-09 02:19:57.228 Tor logged: "Apr 09 02:19:57.228 [debug] tor_disable_debugger_attach: Attemping to disable debugger attachment to Tor for unprivileged users.", waiting for "Opened Socks listener"
2019-04-09 02:19:57.228 Tor logged: "Apr 09 02:19:57.228 [info] tor_lockfile_lock: Locking "/var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/tor_rebind_test.XXXXXX.d7UUkHM4/lock"", waiting for "Opened Socks listener"
2019-04-09 02:19:57.231 Tor logged: "Apr 09 02:19:57.230 [debug] parse_dir_authority_line: Trusted 100 dirserver at 128.31.0.39:9131 (9695)", waiting for "Opened Socks listener"
2019-04-09 02:19:57.231 Tor logged: "Apr 09 02:19:57.231 [debug] parse_dir_authority_line: Trusted 100 dirserver at 86.59.21.38:80 (847B)", waiting for "Opened Socks listener"
2019-04-09 02:19:57.231 Tor logged: "Apr 09 02:19:57.231 [debug] parse_dir_authority_line: Trusted 100 dirserver at 194.109.206.212:80 (7EA6)", waiting for "Opened Socks listener"
2019-04-09 02:19:57.231 Tor logged: "Apr 09 02:19:57.231 [debug] parse_dir_authority_line: Trusted 16 dirserver at 66.111.2.131:9030 (BA44)", waiting for "Opened Socks listener"
2019-04-09 02:19:57.231 Tor logged: "Apr 09 02:19:57.231 [debug] parse_dir_authority_line: Trusted 100 dirserver at 131.188.40.189:80 (F204)", waiting for "Opened Socks listener"
2019-04-09 02:19:57.231 Tor logged: "Apr 09 02:19:57.231 [debug] parse_dir_authority_line: Trusted 100 dirserver at 193.23.244.244:80 (7BE6)", waiting for "Opened Socks listener"
2019-04-09 02:19:57.231 Tor logged: "Apr 09 02:19:57.231 [debug] parse_dir_authority_line: Trusted 100 dirserver at 171.25.193.9:443 (BD6A)", waiting for "Opened Socks listener"
2019-04-09 02:19:57.232 Tor logged: "Apr 09 02:19:57.231 [debug] parse_dir_authority_line: Trusted 100 dirserver at 154.35.175.225:80 (CF6D)", waiting for "Opened Socks listener"
2019-04-09 02:19:57.232 Tor logged: "Apr 09 02:19:57.231 [debug] parse_dir_authority_line: Trusted 100 dirserver at 199.58.81.140:80 (74A9)", waiting for "Opened Socks listener"
2019-04-09 02:19:57.232 Tor logged: "Apr 09 02:19:57.231 [debug] parse_dir_authority_line: Trusted 100 dirserver at 204.13.164.118:80 (24E2)", waiting for "Opened Socks listener"
2019-04-09 02:19:57.232 Tor logged: "Apr 09 02:19:57.231 [debug] file_status: stat()ing /var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/tor_rebind_test.XXXXXX.d7UUkHM4/state", waiting for "Opened Socks listener"
2019-04-09 02:19:57.232 Tor logged: "Apr 09 02:19:57.231 [info] or_state_load: Initialized state", waiting for "Opened Socks listener"
2019-04-09 02:19:57.232 Tor logged: "Apr 09 02:19:57.231 [info] circuit_build_times_parse_state: Adding 0 timeouts.", waiting for "Opened Socks listener"
2019-04-09 02:19:57.233 Tor logged: "Apr 09 02:19:57.231 [info] circuit_build_times_parse_state: Loaded 0/0 values from 0 lines in circuit time histogram", waiting for "Opened Socks listener"
2019-04-09 02:19:57.233 Tor logged: "Apr 09 02:19:57.233 [debug] tor_rename: Renaming /var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/tor_rebind_test.XXXXXX.d7UUkHM4/state.tmp to /var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/tor_rebind_test.XXXXXX.d7UUkHM4/state", waiting for "Opened Socks listener"
2019-04-09 02:19:57.233 Tor logged: "Apr 09 02:19:57.233 [info] or_state_save: Saved state to "/var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/tor_rebind_test.XXXXXX.d7UUkHM4/state"", waiting for "Opened Socks listener"
2019-04-09 02:19:57.233 Tor logged: "Apr 09 02:19:57.233 [info] read_file_to_str: Could not open "/var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/tor_rebind_test.XXXXXX.d7UUkHM4/router-stability": No such file or directory", waiting for "Opened Socks listener"
2019-04-09 02:19:57.234 Tor logged: "Apr 09 02:19:57.234 [info] select_scheduler: Scheduler type KIST not built in", waiting for "Opened Socks listener"
2019-04-09 02:19:57.234 Tor logged: "Apr 09 02:19:57.234 [info] scheduler_kist_set_lite_mode: Setting KIST scheduler without kernel support (KISTLite mode)", waiting for "Opened Socks listener"
2019-04-09 02:19:57.234 Tor logged: "Apr 09 02:19:57.234 [debug] kist_scheduler_run_interval: KISTSchedRunInterval=0, turning to the consensus.", waiting for "Opened Socks listener"
2019-04-09 02:19:57.234 Tor logged: "Apr 09 02:19:57.234 [info] cmux_ewma_set_options: Enabled cell_ewma algorithm because of value in CircuitPriorityHalflifeMsec in consensus; scale factor is 0.793701 per 10 seconds", waiting for "Opened Socks listener"
2019-04-09 02:19:57.234 Tor logged: "Apr 09 02:19:57.234 [info] geoip_load_file: Failed to open GEOIP file /usr/local/share/tor/geoip.", waiting for "Opened Socks listener"
2019-04-09 02:19:57.234 Tor logged: "Apr 09 02:19:57.234 [info] geoip_load_file: Failed to open GEOIP file /usr/local/share/tor/geoip6.", waiting for "Opened Socks listener"
2019-04-09 02:19:57.234 Tor logged: "Apr 09 02:19:57.234 [info] add_predicted_port: New port prediction added. Will continue predictive circ building for 2364 more seconds.", waiting for "Opened Socks listener"
2019-04-09 02:19:57.234 Tor logged: "Apr 09 02:19:57.234 [info] crypto_openssl_late_init: NOT using OpenSSL engine support.", waiting for "Opened Socks listener"
2019-04-09 02:19:57.234 Tor logged: "Apr 09 02:19:57.234 [info] evaluate_evp_for_aes: This version of OpenSSL has a known-good EVP counter-mode implementation. Using it.", waiting for "Opened Socks listener"
2019-04-09 02:19:57.234 Tor logged: "Apr 09 02:19:57.234 [debug] file_status: stat()ing /var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/tor_rebind_test.XXXXXX.d7UUkHM4/unparseable-descs", waiting for "Opened Socks listener"
2019-04-09 02:19:57.244 Tor logged: "Apr 09 02:19:57.244 [notice] Bootstrapped 0% (starting): Starting", waiting for "Opened Socks listener"
2019-04-09 02:19:57.245 Tor logged: "Apr 09 02:19:57.245 [info] read_file_to_str: Could not open "/var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/tor_rebind_test.XXXXXX.d7UUkHM4/cached-certs": No such file or directory", waiting for "Opened Socks listener"
2019-04-09 02:19:57.245 Tor logged: "Apr 09 02:19:57.245 [info] tor_mmap_file: Could not open "/var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/tor_rebind_test.XXXXXX.d7UUkHM4/cached-consensus" for mmap(): No such file or directory", waiting for "Opened Socks listener"
2019-04-09 02:19:57.245 Tor logged: "Apr 09 02:19:57.245 [info] tor_mmap_file: Could not open "/var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/tor_rebind_test.XXXXXX.d7UUkHM4/unverified-consensus" for mmap(): No such file or directory", waiting for "Opened Socks listener"
2019-04-09 02:19:57.245 Tor logged: "Apr 09 02:19:57.245 [info] tor_mmap_file: Could not open "/var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/tor_rebind_test.XXXXXX.d7UUkHM4/cached-microdesc-consensus" for mmap(): No such file or directory", waiting for "Opened Socks listener"
2019-04-09 02:19:57.245 Tor logged: "Apr 09 02:19:57.245 [info] tor_mmap_file: Could not open "/var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/tor_rebind_test.XXXXXX.d7UUkHM4/unverified-microdesc-consensus" for mmap(): No such file or directory", waiting for "Opened Socks listener"
2019-04-09 02:19:57.246 Tor logged: "Apr 09 02:19:57.245 [info] tor_mmap_file: Could not open "/var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/tor_rebind_test.XXXXXX.d7UUkHM4/cached-microdescs" for mmap(): No such file or directory", waiting for "Opened Socks listener"
2019-04-09 02:19:57.246 Tor logged: "Apr 09 02:19:57.245 [info] read_file_to_str: Could not open "/var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/tor_rebind_test.XXXXXX.d7UUkHM4/cached-microdescs.new": No such file or directory", waiting for "Opened Socks listener"
2019-04-09 02:19:57.246 Tor logged: "Apr 09 02:19:57.245 [info] microdesc_cache_reload: Reloaded microdescriptor cache. Found 0 descriptors.", waiting for "Opened Socks listener"
2019-04-09 02:19:57.246 Tor logged: "Apr 09 02:19:57.245 [info] tor_mmap_file: Could not open "/var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/tor_rebind_test.XXXXXX.d7UUkHM4/cached-descriptors" for mmap(): No such file or directory", waiting for "Opened Socks listener"
2019-04-09 02:19:57.246 Tor logged: "Apr 09 02:19:57.245 [debug] file_status: stat()ing /var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/tor_rebind_test.XXXXXX.d7UUkHM4/cached-descriptors.new", waiting for "Opened Socks listener"
2019-04-09 02:19:57.246 Tor logged: "Apr 09 02:19:57.245 [info] tor_mmap_file: Could not open "/var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/tor_rebind_test.XXXXXX.d7UUkHM4/cached-extrainfo" for mmap(): No such file or directory", waiting for "Opened Socks listener"
2019-04-09 02:19:57.247 Tor logged: "Apr 09 02:19:57.245 [debug] file_status: stat()ing /var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/tor_rebind_test.XXXXXX.d7UUkHM4/cached-extrainfo.new", waiting for "Opened Socks listener"
2019-04-09 02:19:57.247 Tor logged: "Apr 09 02:19:57.245 [notice] Starting with guard context "default"", waiting for "Opened Socks listener"
2019-04-09 02:19:57.247 Tor logged: "Apr 09 02:19:57.245 [debug] get_guard_selection_by_name: Creating a guard selection called default", waiting for "Opened Socks listener"
2019-04-09 02:19:57.247 Tor logged: "Apr 09 02:19:57.245 [info] sampled_guards_update_from_consensus: Not updating the sample guard set; we have no reasonably live consensus.", waiting for "Opened Socks listener"
2019-04-09 02:19:57.247 Tor logged: "Apr 09 02:19:57.245 [info] sample_reachable_filtered_entry_guards: Trying to sample a reachable guard: We know of 0 in the USABLE_FILTERED set.", waiting for "Opened Socks listener"
2019-04-09 02:19:57.247 Tor logged: "Apr 09 02:19:57.245 [info] sample_reachable_filtered_entry_guards:   (That isn't enough. Trying to expand the sample.)", waiting for "Opened Socks listener"
2019-04-09 02:19:57.247 Tor logged: "Apr 09 02:19:57.245 [info] entry_guards_expand_sample: Not expanding the sample guard set; we have no reasonably live consensus.", waiting for "Opened Socks listener"
2019-04-09 02:19:57.247 Tor logged: "Apr 09 02:19:57.245 [info] sample_reachable_filtered_entry_guards:   (After filters [b], we have 0 guards to consider.)", waiting for "Opened Socks listener"
2019-04-09 02:19:57.247 Tor logged: "Apr 09 02:19:57.245 [info] I learned some more directory information, but not enough to build a circuit: We have no usable consensus.", waiting for "Opened Socks listener"
2019-04-09 02:19:57.247 Tor logged: "Apr 09 02:19:57.245 [debug] conn_read_callback: socket 4 wants to read.", waiting for "Opened Socks listener"
2019-04-09 02:19:57.248 Tor logged: "Apr 09 02:19:57.246 [debug] connection_handle_listener_read: Connection accepted on socket 7 (child of fd 4).", waiting for "Opened Socks listener"
2019-04-09 02:19:57.248 Tor logged: "Apr 09 02:19:57.246 [info] connection_handle_listener_read: New SOCKS connection opened from 127.0.0.1.", waiting for "Opened Socks listener"
2019-04-09 02:19:57.248 Tor logged: "Apr 09 02:19:57.246 [debug] connection_add_impl: new conn type Socks, socket 7, address 127.0.0.1, n_conns 3.", waiting for "Opened Socks listener"
2019-04-09 02:19:57.248 Tor logged: "Apr 09 02:19:57.246 [debug] conn_read_callback: socket 5 wants to read.", waiting for "Opened Socks listener"
2019-04-09 02:19:57.248 Tor logged: "Apr 09 02:19:57.246 [debug] connection_handle_listener_read: Connection accepted on socket 8 (child of fd 5).", waiting for "Opened Socks listener"
2019-04-09 02:19:57.248 Tor logged: "Apr 09 02:19:57.246 [notice] New control connection opened from 127.0.0.1.", waiting for "Opened Socks listener"
2019-04-09 02:19:57.248 Tor logged: "Apr 09 02:19:57.246 [debug] connection_add_impl: new conn type Control, socket 8, address 127.0.0.1, n_conns 4.", waiting for "Opened Socks listener"
2019-04-09 02:19:57.248 Tor logged: "Apr 09 02:19:57.246 [debug] conn_read_callback: socket 7 wants to read.", waiting for "Opened Socks listener"
2019-04-09 02:19:57.248 Tor logged: "Apr 09 02:19:57.246 [debug] read_to_chunk: Encountered eof on fd 7", waiting for "Opened Socks listener"
2019-04-09 02:19:57.248 Tor logged: "Apr 09 02:19:57.246 [debug] connection_ap_handshake_process_socks: entered.", waiting for "Opened Socks listener"
2019-04-09 02:19:57.248 Tor logged: "Apr 09 02:19:57.246 [debug] connection_ap_handshake_process_socks: socks handshake not all here yet.", waiting for "Opened Socks listener"
2019-04-09 02:19:57.249 Tor logged: "Apr 09 02:19:57.246 [info] connection_edge_reached_eof: conn (fd 7) reached eof. Closing.", waiting for "Opened Socks listener"
2019-04-09 02:19:57.249 Tor logged: "Apr 09 02:19:57.246 [debug] connection_edge_end: No circ to send end on conn (fd 7).", waiting for "Opened Socks listener"
2019-04-09 02:19:57.249 Tor logged: "Apr 09 02:19:57.246 [debug] conn_close_if_marked: Cleaning up connection (fd 7).", waiting for "Opened Socks listener"
2019-04-09 02:19:57.249 Tor logged: "Apr 09 02:19:57.246 [debug] connection_remove: removing socket 7 (type Socks), n_conns now 4", waiting for "Opened Socks listener"
2019-04-09 02:19:57.249 Tor logged: "Apr 09 02:19:57.246 [debug] connection_free_minimal: closing fd 7.", waiting for "Opened Socks listener"
2019-04-09 02:19:57.249 Tor logged: "Apr 09 02:19:57.247 [debug] conn_read_callback: socket 8 wants to read.", waiting for "Opened Socks listener"
2019-04-09 02:19:57.249 Tor logged: "Apr 09 02:19:57.247 [debug] read_to_chunk: Read 48 bytes. 48 on inbuf.", waiting for "Opened Socks listener"
2019-04-09 02:19:57.249 Tor logged: "Apr 09 02:19:57.247 [info] handle_control_authenticate: Authenticated control connection (8)", waiting for "Opened Socks listener"
2019-04-09 02:19:57.259 Tor logged: "Apr 09 02:19:57.259 [warn] ControlPort is open, but no authentication method has been configured.  This means that any program on your computer can reconfigure your Tor.  That's bad!  You should upgrade your Tor controller as soon as possible.", waiting for "Opened Socks listener"
2019-04-09 02:19:57.259 Tor logged: "Apr 09 02:19:57.259 [debug] parse_addr_policy: Adding new entry 'reject *4:*'", waiting for "Opened Socks listener"
2019-04-09 02:19:57.259 Tor logged: "Apr 09 02:19:57.259 [debug] parse_addr_policy: Adding new entry 'reject *6:*'", waiting for "Opened Socks listener"
2019-04-09 02:19:57.260 Tor logged: "Apr 09 02:19:57.260 [info] set_max_file_descriptors: Raising max file descriptors from 10208 to 9223372036854775807.", waiting for "Opened Socks listener"
2019-04-09 02:19:57.261 Tor logged: "Apr 09 02:19:57.261 [info] set_max_file_descriptors: Dropped connection limit to 10208 based on OPEN_MAX (10240); Apparently, 9223372036854775807 was too high and rlimit lied to us.", waiting for "Opened Socks listener"
2019-04-09 02:19:57.261 Tor logged: "Apr 09 02:19:57.261 [warn] You specified a public address '0.0.0.0:14394' for SocksPort. Other people on the Internet might find your computer and use it as an open proxy. Please don't allow this unless you have a good reason.", waiting for "Opened Socks listener"
2019-04-09 02:19:57.261 Tor logged: "Apr 09 02:19:57.261 [debug] retry_all_listeners: 1 replacements - starting rebinding loop.", waiting for "Opened Socks listener"
2019-04-09 02:19:57.261 Tor logged: "Apr 09 02:19:57.261 [notice] Opening Socks listener on 0.0.0.0:14394", waiting for "Opened Socks listener"
2019-04-09 02:19:57.262 Tor logged: "Apr 09 02:19:57.262 [debug] connection_add_impl: new conn type Socks listener, socket 7, address 0.0.0.0, n_conns 4.", waiting for "Opened Socks listener"
2019-04-09 02:19:57.262 Tor logged: "Apr 09 02:19:57.262 [debug] connection_listener_new: Socks listener listening on port 14394.", waiting for "Opened Socks listener"
2019-04-09 02:19:57.262 Tor logged: "Apr 09 02:19:57.262 [notice] Opened Socks listener on 0.0.0.0:14394"
2019-04-09 02:19:57.262 FAIL
Cannot connect to SOCKSPort: error Connection reset by peer
+exitcode=1
+exit 1
+clean
+test -n /var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/tor_rebind_test.XXXXXX.d7UUkHM4
+test -d /var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/tor_rebind_test.XXXXXX.d7UUkHM4
+rm -rf /var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/tor_rebind_test.XXXXXX.d7UUkHM4
FAIL src/test/test_rebind.sh (exit status: 1)

https://travis-ci.org/torproject/tor/jobs/517569095#L4221

comment:25 Changed 5 months ago by catalyst

Keywords: tor-ci-fail-sometimes added

Got another failure on Travis on macOS:

FAIL: src/test/test_rebind.sh
=============================
++uname -s
++cut -d_ -f1
+UNAME_OS=Darwin
+test Darwin = CYGWIN
+test Darwin = MSYS
+test Darwin = MINGW
+exitcode=0
+tmpdir=
+trap clean EXIT HUP INT TERM
++mktemp -d -t tor_rebind_test.XXXXXX
+tmpdir=/var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/tor_rebind_test.XXXXXX.wLtKk8iu
+'[' -z /var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/tor_rebind_test.XXXXXX.wLtKk8iu ']'
+'[' '!' -d /var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/tor_rebind_test.XXXXXX.wLtKk8iu ']'
+python3 /Users/travis/build/torproject/tor/src/test/test_rebind.py ./src/app/tor /var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/tor_rebind_test.XXXXXX.wLtKk8iu
2019-05-15 00:25:42.573 Tor logged: "May 15 00:25:42.561 [notice] Tor 0.4.1.0-alpha-dev (git-cef1fd32f6ca00b3) running on Darwin with Libevent 2.1.8-stable, OpenSSL 1.0.2o, Zlib 1.2.11, Liblzma 5.2.4, and Libzstd 1.3.4.", waiting for "Opened Control listener on"
2019-05-15 00:25:42.573 Tor logged: "May 15 00:25:42.563 [notice] Tor can't help you if you use it wrong! Learn how to be safe at https://www.torproject.org/download/download#warning", waiting for "Opened Control listener on"
2019-05-15 00:25:42.573 Tor logged: "May 15 00:25:42.563 [notice] This version is not a stable Tor release. Expect more bugs than usual.", waiting for "Opened Control listener on"
2019-05-15 00:25:42.574 Tor logged: "May 15 00:25:42.563 [notice] Tor is running with Rust integration. Please report any bugs you encounter.", waiting for "Opened Control listener on"
2019-05-15 00:25:42.574 Tor logged: "May 15 00:25:42.563 [notice] Configuration file "/usr/local/etc/tor/torrc" not present, using reasonable defaults.", waiting for "Opened Control listener on"
2019-05-15 00:25:42.574 Tor logged: "May 15 00:25:42.570 [warn] ControlPort is open, but no authentication method has been configured.  This means that any program on your computer can reconfigure your Tor.  That's bad!  You should upgrade your Tor controller as soon as possible.", waiting for "Opened Control listener on"
2019-05-15 00:25:42.574 Tor logged: "May 15 00:25:42.572 [notice] Opening Socks listener on 127.0.0.1:35673", waiting for "Opened Control listener on"
2019-05-15 00:25:42.574 Tor logged: "May 15 00:25:42.573 [notice] Opened Socks listener on 127.0.0.1:35673", waiting for "Opened Control listener on"
2019-05-15 00:25:42.574 Tor logged: "May 15 00:25:42.573 [notice] Opening Control listener on 127.0.0.1:44218", waiting for "Opened Control listener on"
2019-05-15 00:25:42.574 Tor logged: "May 15 00:25:42.573 [notice] Opened Control listener on 127.0.0.1:44218"
2019-05-15 00:25:42.575 Tor logged: "May 15 00:25:42.573 [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.", waiting for "Opened Socks listener"
2019-05-15 00:25:42.575 Tor logged: "May 15 00:25:42.573 [info] options_act_reversible: Recomputed OOS thresholds: ConnLimit 1000, ConnLimit_ 10176, ConnLimit_high_thresh 10112, ConnLimit_low_thresh 7632", waiting for "Opened Socks listener"
2019-05-15 00:25:42.575 Tor logged: "May 15 00:25:42.573 [debug] tor_disable_debugger_attach: Attemping to disable debugger attachment to Tor for unprivileged users.", waiting for "Opened Socks listener"
2019-05-15 00:25:42.576 Tor logged: "May 15 00:25:42.573 [info] tor_lockfile_lock: Locking "/var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/tor_rebind_test.XXXXXX.wLtKk8iu/lock"", waiting for "Opened Socks listener"
2019-05-15 00:25:42.576 Tor logged: "May 15 00:25:42.576 [debug] parse_dir_authority_line: Trusted 100 dirserver at 128.31.0.39:9131 (9695)", waiting for "Opened Socks listener"
2019-05-15 00:25:42.576 Tor logged: "May 15 00:25:42.576 [debug] parse_dir_authority_line: Trusted 100 dirserver at 86.59.21.38:80 (847B)", waiting for "Opened Socks listener"
2019-05-15 00:25:42.576 Tor logged: "May 15 00:25:42.576 [debug] parse_dir_authority_line: Trusted 100 dirserver at 194.109.206.212:80 (7EA6)", waiting for "Opened Socks listener"
2019-05-15 00:25:42.576 Tor logged: "May 15 00:25:42.576 [debug] parse_dir_authority_line: Trusted 16 dirserver at 66.111.2.131:9030 (BA44)", waiting for "Opened Socks listener"
2019-05-15 00:25:42.576 Tor logged: "May 15 00:25:42.576 [debug] parse_dir_authority_line: Trusted 100 dirserver at 131.188.40.189:80 (F204)", waiting for "Opened Socks listener"
2019-05-15 00:25:42.577 Tor logged: "May 15 00:25:42.576 [debug] parse_dir_authority_line: Trusted 100 dirserver at 193.23.244.244:80 (7BE6)", waiting for "Opened Socks listener"
2019-05-15 00:25:42.577 Tor logged: "May 15 00:25:42.576 [debug] parse_dir_authority_line: Trusted 100 dirserver at 171.25.193.9:443 (BD6A)", waiting for "Opened Socks listener"
2019-05-15 00:25:42.577 Tor logged: "May 15 00:25:42.576 [debug] parse_dir_authority_line: Trusted 100 dirserver at 154.35.175.225:80 (CF6D)", waiting for "Opened Socks listener"
2019-05-15 00:25:42.577 Tor logged: "May 15 00:25:42.576 [debug] parse_dir_authority_line: Trusted 100 dirserver at 199.58.81.140:80 (74A9)", waiting for "Opened Socks listener"
2019-05-15 00:25:42.577 Tor logged: "May 15 00:25:42.576 [debug] parse_dir_authority_line: Trusted 100 dirserver at 204.13.164.118:80 (24E2)", waiting for "Opened Socks listener"
2019-05-15 00:25:42.577 Tor logged: "May 15 00:25:42.576 [debug] file_status: stat()ing /var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/tor_rebind_test.XXXXXX.wLtKk8iu/state", waiting for "Opened Socks listener"
2019-05-15 00:25:42.577 Tor logged: "May 15 00:25:42.576 [info] or_state_load: Initialized state", waiting for "Opened Socks listener"
2019-05-15 00:25:42.578 Tor logged: "May 15 00:25:42.576 [info] circuit_build_times_parse_state: Adding 0 timeouts.", waiting for "Opened Socks listener"
2019-05-15 00:25:42.578 Tor logged: "May 15 00:25:42.576 [info] circuit_build_times_parse_state: Loaded 0/0 values from 0 lines in circuit time histogram", waiting for "Opened Socks listener"
2019-05-15 00:25:42.578 Tor logged: "May 15 00:25:42.578 [debug] tor_rename: Renaming /var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/tor_rebind_test.XXXXXX.wLtKk8iu/state.tmp to /var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/tor_rebind_test.XXXXXX.wLtKk8iu/state", waiting for "Opened Socks listener"
2019-05-15 00:25:42.578 Tor logged: "May 15 00:25:42.578 [info] or_state_save: Saved state to "/var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/tor_rebind_test.XXXXXX.wLtKk8iu/state"", waiting for "Opened Socks listener"
2019-05-15 00:25:42.578 Tor logged: "May 15 00:25:42.578 [info] read_file_to_str: Could not open "/var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/tor_rebind_test.XXXXXX.wLtKk8iu/router-stability": No such file or directory", waiting for "Opened Socks listener"
2019-05-15 00:25:42.579 Tor logged: "May 15 00:25:42.578 [info] select_scheduler: Scheduler type KIST not built in", waiting for "Opened Socks listener"
2019-05-15 00:25:42.579 Tor logged: "May 15 00:25:42.578 [info] scheduler_kist_set_lite_mode: Setting KIST scheduler without kernel support (KISTLite mode)", waiting for "Opened Socks listener"
2019-05-15 00:25:42.579 Tor logged: "May 15 00:25:42.578 [debug] kist_scheduler_run_interval: KISTSchedRunInterval=0, turning to the consensus.", waiting for "Opened Socks listener"
2019-05-15 00:25:42.579 Tor logged: "May 15 00:25:42.579 [info] cmux_ewma_set_options: Enabled cell_ewma algorithm because of value in CircuitPriorityHalflifeMsec in consensus; scale factor is 0.793701 per 10 seconds", waiting for "Opened Socks listener"
2019-05-15 00:25:42.579 Tor logged: "May 15 00:25:42.579 [info] geoip_load_file: Failed to open GEOIP file /usr/local/share/tor/geoip.", waiting for "Opened Socks listener"
2019-05-15 00:25:42.579 Tor logged: "May 15 00:25:42.579 [info] geoip_load_file: Failed to open GEOIP file /usr/local/share/tor/geoip6.", waiting for "Opened Socks listener"
2019-05-15 00:25:42.579 Tor logged: "May 15 00:25:42.579 [info] add_predicted_port: New port prediction added. Will continue predictive circ building for 2550 more seconds.", waiting for "Opened Socks listener"
2019-05-15 00:25:42.580 Tor logged: "May 15 00:25:42.579 [info] crypto_openssl_late_init: NOT using OpenSSL engine support.", waiting for "Opened Socks listener"
2019-05-15 00:25:42.580 Tor logged: "May 15 00:25:42.579 [info] evaluate_evp_for_aes: This version of OpenSSL has a known-good EVP counter-mode implementation. Using it.", waiting for "Opened Socks listener"
2019-05-15 00:25:42.580 Tor logged: "May 15 00:25:42.579 [debug] file_status: stat()ing /var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/tor_rebind_test.XXXXXX.wLtKk8iu/unparseable-descs", waiting for "Opened Socks listener"
2019-05-15 00:25:42.607 Tor logged: "May 15 00:25:42.607 [notice] Bootstrapped 0% (starting): Starting", waiting for "Opened Socks listener"
2019-05-15 00:25:42.607 Tor logged: "May 15 00:25:42.607 [info] read_file_to_str: Could not open "/var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/tor_rebind_test.XXXXXX.wLtKk8iu/cached-certs": No such file or directory", waiting for "Opened Socks listener"
2019-05-15 00:25:42.608 Tor logged: "May 15 00:25:42.607 [info] tor_mmap_file: Could not open "/var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/tor_rebind_test.XXXXXX.wLtKk8iu/cached-consensus" for mmap(): No such file or directory", waiting for "Opened Socks listener"
2019-05-15 00:25:42.608 Tor logged: "May 15 00:25:42.608 [info] tor_mmap_file: Could not open "/var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/tor_rebind_test.XXXXXX.wLtKk8iu/unverified-consensus" for mmap(): No such file or directory", waiting for "Opened Socks listener"
2019-05-15 00:25:42.608 Tor logged: "May 15 00:25:42.608 [info] tor_mmap_file: Could not open "/var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/tor_rebind_test.XXXXXX.wLtKk8iu/cached-microdesc-consensus" for mmap(): No such file or directory", waiting for "Opened Socks listener"
2019-05-15 00:25:42.608 Tor logged: "May 15 00:25:42.608 [info] tor_mmap_file: Could not open "/var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/tor_rebind_test.XXXXXX.wLtKk8iu/unverified-microdesc-consensus" for mmap(): No such file or directory", waiting for "Opened Socks listener"
2019-05-15 00:25:42.608 Tor logged: "May 15 00:25:42.608 [info] tor_mmap_file: Could not open "/var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/tor_rebind_test.XXXXXX.wLtKk8iu/cached-microdescs" for mmap(): No such file or directory", waiting for "Opened Socks listener"
2019-05-15 00:25:42.608 Tor logged: "May 15 00:25:42.608 [info] read_file_to_str: Could not open "/var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/tor_rebind_test.XXXXXX.wLtKk8iu/cached-microdescs.new": No such file or directory", waiting for "Opened Socks listener"
2019-05-15 00:25:42.609 Tor logged: "May 15 00:25:42.609 [info] microdesc_cache_reload: Reloaded microdescriptor cache. Found 0 descriptors.", waiting for "Opened Socks listener"
2019-05-15 00:25:42.609 Tor logged: "May 15 00:25:42.609 [info] tor_mmap_file: Could not open "/var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/tor_rebind_test.XXXXXX.wLtKk8iu/cached-descriptors" for mmap(): No such file or directory", waiting for "Opened Socks listener"
2019-05-15 00:25:42.609 Tor logged: "May 15 00:25:42.609 [debug] file_status: stat()ing /var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/tor_rebind_test.XXXXXX.wLtKk8iu/cached-descriptors.new", waiting for "Opened Socks listener"
2019-05-15 00:25:42.610 Tor logged: "May 15 00:25:42.609 [info] tor_mmap_file: Could not open "/var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/tor_rebind_test.XXXXXX.wLtKk8iu/cached-extrainfo" for mmap(): No such file or directory", waiting for "Opened Socks listener"
2019-05-15 00:25:42.610 Tor logged: "May 15 00:25:42.610 [debug] file_status: stat()ing /var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/tor_rebind_test.XXXXXX.wLtKk8iu/cached-extrainfo.new", waiting for "Opened Socks listener"
2019-05-15 00:25:42.610 Tor logged: "May 15 00:25:42.610 [notice] Starting with guard context "default"", waiting for "Opened Socks listener"
2019-05-15 00:25:42.610 Tor logged: "May 15 00:25:42.610 [debug] get_guard_selection_by_name: Creating a guard selection called default", waiting for "Opened Socks listener"
2019-05-15 00:25:42.610 Tor logged: "May 15 00:25:42.610 [info] sampled_guards_update_from_consensus: Not updating the sample guard set; we have no reasonably live consensus.", waiting for "Opened Socks listener"
2019-05-15 00:25:42.611 Tor logged: "May 15 00:25:42.611 [info] sample_reachable_filtered_entry_guards: Trying to sample a reachable guard: We know of 0 in the USABLE_FILTERED set.", waiting for "Opened Socks listener"
2019-05-15 00:25:42.611 Tor logged: "May 15 00:25:42.611 [info] sample_reachable_filtered_entry_guards:   (That isn't enough. Trying to expand the sample.)", waiting for "Opened Socks listener"
2019-05-15 00:25:42.611 Tor logged: "May 15 00:25:42.611 [info] entry_guards_expand_sample: Not expanding the sample guard set; we have no reasonably live consensus.", waiting for "Opened Socks listener"
2019-05-15 00:25:42.611 Tor logged: "May 15 00:25:42.611 [info] sample_reachable_filtered_entry_guards:   (After filters [b], we have 0 guards to consider.)", waiting for "Opened Socks listener"
2019-05-15 00:25:42.612 Tor logged: "May 15 00:25:42.612 [info] I learned some more directory information, but not enough to build a circuit: We have no usable consensus.", waiting for "Opened Socks listener"
2019-05-15 00:25:42.612 Tor logged: "May 15 00:25:42.612 [debug] conn_read_callback: socket 4 wants to read.", waiting for "Opened Socks listener"
2019-05-15 00:25:42.612 Tor logged: "May 15 00:25:42.612 [debug] connection_handle_listener_read: Connection accepted on socket 7 (child of fd 4).", waiting for "Opened Socks listener"
2019-05-15 00:25:42.613 Tor logged: "May 15 00:25:42.613 [info] connection_handle_listener_read: New SOCKS connection opened from 127.0.0.1.", waiting for "Opened Socks listener"
2019-05-15 00:25:42.613 Tor logged: "May 15 00:25:42.613 [debug] connection_add_impl: new conn type Socks, socket 7, address 127.0.0.1, n_conns 3.", waiting for "Opened Socks listener"
2019-05-15 00:25:42.613 Tor logged: "May 15 00:25:42.613 [debug] conn_read_callback: socket 5 wants to read.", waiting for "Opened Socks listener"
2019-05-15 00:25:42.613 Tor logged: "May 15 00:25:42.613 [debug] connection_handle_listener_read: Connection accepted on socket 8 (child of fd 5).", waiting for "Opened Socks listener"
2019-05-15 00:25:42.613 Tor logged: "May 15 00:25:42.613 [notice] New control connection opened from 127.0.0.1.", waiting for "Opened Socks listener"
2019-05-15 00:25:42.614 Tor logged: "May 15 00:25:42.614 [debug] connection_add_impl: new conn type Control, socket 8, address 127.0.0.1, n_conns 4.", waiting for "Opened Socks listener"
2019-05-15 00:25:42.614 Tor logged: "May 15 00:25:42.614 [debug] conn_read_callback: socket 7 wants to read.", waiting for "Opened Socks listener"
2019-05-15 00:25:42.614 Tor logged: "May 15 00:25:42.614 [debug] read_to_chunk: Encountered eof on fd 7", waiting for "Opened Socks listener"
2019-05-15 00:25:42.615 Tor logged: "May 15 00:25:42.614 [debug] connection_ap_handshake_process_socks: entered.", waiting for "Opened Socks listener"
2019-05-15 00:25:42.615 Tor logged: "May 15 00:25:42.615 [debug] connection_ap_handshake_process_socks: socks handshake not all here yet.", waiting for "Opened Socks listener"
2019-05-15 00:25:42.615 Tor logged: "May 15 00:25:42.615 [info] connection_edge_reached_eof: conn (fd 7) reached eof. Closing.", waiting for "Opened Socks listener"
2019-05-15 00:25:42.615 Tor logged: "May 15 00:25:42.615 [debug] connection_edge_end: No circ to send end on conn (fd 7).", waiting for "Opened Socks listener"
2019-05-15 00:25:42.615 Tor logged: "May 15 00:25:42.615 [debug] conn_close_if_marked: Cleaning up connection (fd 7).", waiting for "Opened Socks listener"
2019-05-15 00:25:42.616 Tor logged: "May 15 00:25:42.616 [debug] connection_remove: removing socket 7 (type Socks), n_conns now 4", waiting for "Opened Socks listener"
2019-05-15 00:25:42.616 Tor logged: "May 15 00:25:42.616 [debug] connection_free_minimal: closing fd 7.", waiting for "Opened Socks listener"
2019-05-15 00:25:42.616 Tor logged: "May 15 00:25:42.616 [debug] conn_read_callback: socket 8 wants to read.", waiting for "Opened Socks listener"
2019-05-15 00:25:42.616 Tor logged: "May 15 00:25:42.616 [debug] read_to_chunk: Read 48 bytes. 48 on inbuf.", waiting for "Opened Socks listener"
2019-05-15 00:25:42.617 Tor logged: "May 15 00:25:42.617 [info] handle_control_authenticate: Authenticated control connection (8)", waiting for "Opened Socks listener"
2019-05-15 00:25:42.632 Tor logged: "May 15 00:25:42.632 [warn] ControlPort is open, but no authentication method has been configured.  This means that any program on your computer can reconfigure your Tor.  That's bad!  You should upgrade your Tor controller as soon as possible.", waiting for "Opened Socks listener"
2019-05-15 00:25:42.632 Tor logged: "May 15 00:25:42.632 [debug] parse_addr_policy: Adding new entry 'reject *4:*'", waiting for "Opened Socks listener"
2019-05-15 00:25:42.632 Tor logged: "May 15 00:25:42.632 [debug] parse_addr_policy: Adding new entry 'reject *6:*'", waiting for "Opened Socks listener"
2019-05-15 00:25:42.634 Tor logged: "May 15 00:25:42.634 [info] set_max_file_descriptors: Raising max file descriptors from 10208 to 9223372036854775807.", waiting for "Opened Socks listener"
2019-05-15 00:25:42.634 Tor logged: "May 15 00:25:42.634 [info] set_max_file_descriptors: Dropped connection limit to 10208 based on OPEN_MAX (10240); Apparently, 9223372036854775807 was too high and rlimit lied to us.", waiting for "Opened Socks listener"
2019-05-15 00:25:42.634 Tor logged: "May 15 00:25:42.634 [warn] You specified a public address '0.0.0.0:35673' for SocksPort. Other people on the Internet might find your computer and use it as an open proxy. Please don't allow this unless you have a good reason.", waiting for "Opened Socks listener"
2019-05-15 00:25:42.635 Tor logged: "May 15 00:25:42.635 [debug] retry_all_listeners: 1 replacements - starting rebinding loop.", waiting for "Opened Socks listener"
2019-05-15 00:25:42.635 Tor logged: "May 15 00:25:42.635 [notice] Opening Socks listener on 0.0.0.0:35673", waiting for "Opened Socks listener"
2019-05-15 00:25:42.635 Tor logged: "May 15 00:25:42.635 [debug] connection_add_impl: new conn type Socks listener, socket 7, address 0.0.0.0, n_conns 4.", waiting for "Opened Socks listener"
2019-05-15 00:25:42.635 Tor logged: "May 15 00:25:42.635 [debug] connection_listener_new: Socks listener listening on port 35673.", waiting for "Opened Socks listener"
2019-05-15 00:25:42.636 Tor logged: "May 15 00:25:42.636 [notice] Opened Socks listener on 0.0.0.0:35673"
2019-05-15 00:25:42.636 FAIL
Cannot connect to SOCKSPort: error Connection reset by peer
+exitcode=1
+exit 1
+clean
+'[' -n /var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/tor_rebind_test.XXXXXX.wLtKk8iu ']'
+'[' -d /var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/tor_rebind_test.XXXXXX.wLtKk8iu ']'
+rm -rf /var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/tor_rebind_test.XXXXXX.wLtKk8iu
FAIL src/test/test_rebind.sh (exit status: 1)

comment:26 Changed 5 months ago by catalyst

Another test failure on macOS on Travis:
https://api.travis-ci.org/v3/job/538462130/log.txt

FAIL: src/test/test_rebind.sh
=============================
++uname -s
++cut -d_ -f1
+UNAME_OS=Darwin
+test Darwin = CYGWIN
+test Darwin = MSYS
+test Darwin = MINGW
+exitcode=0
+tmpdir=
+trap clean EXIT HUP INT TERM
++mktemp -d -t tor_rebind_test.XXXXXX
+tmpdir=/var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/tor_rebind_test.XXXXXX.eMUA561I
+'[' -z /var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/tor_rebind_test.XXXXXX.eMUA561I ']'
+'[' '!' -d /var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/tor_rebind_test.XXXXXX.eMUA561I ']'
+python3 /Users/travis/build/torproject/tor/src/test/test_rebind.py ./src/app/tor /var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/tor_rebind_test.XXXXXX.eMUA561I
2019-05-28 21:51:15.472 Tor logged: "May 28 21:51:15.470 [notice] Tor 0.4.1.1-alpha-dev (git-3b5e9a0138329440) running on Darwin with Libevent 2.1.8-stable, OpenSSL 1.0.2o, Zlib 1.2.11, Liblzma 5.2.4, and Libzstd 1.3.4.", waiting for "Opened Control listener on"
2019-05-28 21:51:15.473 Tor logged: "May 28 21:51:15.473 [notice] Tor can't help you if you use it wrong! Learn how to be safe at https://www.torproject.org/download/download#warning", waiting for "Opened Control listener on"
2019-05-28 21:51:15.473 Tor logged: "May 28 21:51:15.473 [notice] This version is not a stable Tor release. Expect more bugs than usual.", waiting for "Opened Control listener on"
2019-05-28 21:51:15.473 Tor logged: "May 28 21:51:15.473 [notice] Configuration file "/usr/local/etc/tor/torrc" not present, using reasonable defaults.", waiting for "Opened Control listener on"
2019-05-28 21:51:15.481 Tor logged: "May 28 21:51:15.481 [warn] ControlPort is open, but no authentication method has been configured.  This means that any program on your computer can reconfigure your Tor.  That's bad!  You should upgrade your Tor controller as soon as possible.", waiting for "Opened Control listener on"
2019-05-28 21:51:15.484 Tor logged: "May 28 21:51:15.483 [notice] Opening Socks listener on 127.0.0.1:36475", waiting for "Opened Control listener on"
2019-05-28 21:51:15.485 Tor logged: "May 28 21:51:15.485 [notice] Opened Socks listener on 127.0.0.1:36475", waiting for "Opened Control listener on"
2019-05-28 21:51:15.485 Tor logged: "May 28 21:51:15.485 [notice] Opening Control listener on 127.0.0.1:31888", waiting for "Opened Control listener on"
2019-05-28 21:51:15.485 Tor logged: "May 28 21:51:15.485 [notice] Opened Control listener on 127.0.0.1:31888"
2019-05-28 21:51:15.486 Tor logged: "May 28 21:51:15.486 [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.", waiting for "Opened Socks listener"
2019-05-28 21:51:15.486 Tor logged: "May 28 21:51:15.486 [info] options_act_reversible: Recomputed OOS thresholds: ConnLimit 1000, ConnLimit_ 10176, ConnLimit_high_thresh 10112, ConnLimit_low_thresh 7632", waiting for "Opened Socks listener"
2019-05-28 21:51:15.487 Tor logged: "May 28 21:51:15.486 [debug] tor_disable_debugger_attach: Attemping to disable debugger attachment to Tor for unprivileged users.", waiting for "Opened Socks listener"
2019-05-28 21:51:15.487 Tor logged: "May 28 21:51:15.487 [info] tor_lockfile_lock: Locking "/var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/tor_rebind_test.XXXXXX.eMUA561I/lock"", waiting for "Opened Socks listener"
2019-05-28 21:51:15.490 Tor logged: "May 28 21:51:15.490 [debug] parse_dir_authority_line: Trusted 100 dirserver at 128.31.0.39:9131 (9695)", waiting for "Opened Socks listener"
2019-05-28 21:51:15.490 Tor logged: "May 28 21:51:15.490 [debug] parse_dir_authority_line: Trusted 100 dirserver at 86.59.21.38:80 (847B)", waiting for "Opened Socks listener"
2019-05-28 21:51:15.490 Tor logged: "May 28 21:51:15.490 [debug] parse_dir_authority_line: Trusted 100 dirserver at 194.109.206.212:80 (7EA6)", waiting for "Opened Socks listener"
2019-05-28 21:51:15.493 Tor logged: "May 28 21:51:15.493 [debug] parse_dir_authority_line: Trusted 16 dirserver at 66.111.2.131:9030 (BA44)", waiting for "Opened Socks listener"
2019-05-28 21:51:15.494 Tor logged: "May 28 21:51:15.494 [debug] parse_dir_authority_line: Trusted 100 dirserver at 131.188.40.189:80 (F204)", waiting for "Opened Socks listener"
2019-05-28 21:51:15.494 Tor logged: "May 28 21:51:15.494 [debug] parse_dir_authority_line: Trusted 100 dirserver at 193.23.244.244:80 (7BE6)", waiting for "Opened Socks listener"
2019-05-28 21:51:15.494 Tor logged: "May 28 21:51:15.494 [debug] parse_dir_authority_line: Trusted 100 dirserver at 171.25.193.9:443 (BD6A)", waiting for "Opened Socks listener"
2019-05-28 21:51:15.494 Tor logged: "May 28 21:51:15.494 [debug] parse_dir_authority_line: Trusted 100 dirserver at 154.35.175.225:80 (CF6D)", waiting for "Opened Socks listener"
2019-05-28 21:51:15.494 Tor logged: "May 28 21:51:15.494 [debug] parse_dir_authority_line: Trusted 100 dirserver at 199.58.81.140:80 (74A9)", waiting for "Opened Socks listener"
2019-05-28 21:51:15.495 Tor logged: "May 28 21:51:15.494 [debug] parse_dir_authority_line: Trusted 100 dirserver at 204.13.164.118:80 (24E2)", waiting for "Opened Socks listener"
2019-05-28 21:51:15.495 Tor logged: "May 28 21:51:15.495 [debug] file_status: stat()ing /var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/tor_rebind_test.XXXXXX.eMUA561I/state", waiting for "Opened Socks listener"
2019-05-28 21:51:15.495 Tor logged: "May 28 21:51:15.495 [info] or_state_load: Initialized state", waiting for "Opened Socks listener"
2019-05-28 21:51:15.497 Tor logged: "May 28 21:51:15.495 [info] circuit_build_times_parse_state: Adding 0 timeouts.", waiting for "Opened Socks listener"
2019-05-28 21:51:15.498 Tor logged: "May 28 21:51:15.498 [info] circuit_build_times_parse_state: Loaded 0/0 values from 0 lines in circuit time histogram", waiting for "Opened Socks listener"
2019-05-28 21:51:15.499 Tor logged: "May 28 21:51:15.499 [debug] tor_rename: Renaming /var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/tor_rebind_test.XXXXXX.eMUA561I/state.tmp to /var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/tor_rebind_test.XXXXXX.eMUA561I/state", waiting for "Opened Socks listener"
2019-05-28 21:51:15.500 Tor logged: "May 28 21:51:15.500 [info] or_state_save: Saved state to "/var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/tor_rebind_test.XXXXXX.eMUA561I/state"", waiting for "Opened Socks listener"
2019-05-28 21:51:15.500 Tor logged: "May 28 21:51:15.500 [info] read_file_to_str: Could not open "/var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/tor_rebind_test.XXXXXX.eMUA561I/router-stability": No such file or directory", waiting for "Opened Socks listener"
2019-05-28 21:51:15.503 Tor logged: "May 28 21:51:15.500 [info] select_scheduler: Scheduler type KIST not built in", waiting for "Opened Socks listener"
2019-05-28 21:51:15.503 Tor logged: "May 28 21:51:15.503 [info] scheduler_kist_set_lite_mode: Setting KIST scheduler without kernel support (KISTLite mode)", waiting for "Opened Socks listener"
2019-05-28 21:51:15.503 Tor logged: "May 28 21:51:15.503 [debug] kist_scheduler_run_interval: KISTSchedRunInterval=0, turning to the consensus.", waiting for "Opened Socks listener"
2019-05-28 21:51:15.504 Tor logged: "May 28 21:51:15.503 [info] cmux_ewma_set_options: Enabled cell_ewma algorithm because of value in CircuitPriorityHalflifeMsec in consensus; scale factor is 0.793701 per 10 seconds", waiting for "Opened Socks listener"
2019-05-28 21:51:15.504 Tor logged: "May 28 21:51:15.504 [info] geoip_load_file: Failed to open GEOIP file /usr/local/share/tor/geoip.", waiting for "Opened Socks listener"
2019-05-28 21:51:15.504 Tor logged: "May 28 21:51:15.504 [info] geoip_load_file: Failed to open GEOIP file /usr/local/share/tor/geoip6.", waiting for "Opened Socks listener"
2019-05-28 21:51:15.504 Tor logged: "May 28 21:51:15.504 [info] circpad_machine_client_hide_intro_circuits: Registered client intro point hiding padding machine (0)", waiting for "Opened Socks listener"
2019-05-28 21:51:15.504 Tor logged: "May 28 21:51:15.504 [info] circpad_machine_relay_hide_intro_circuits: Registered relay intro circuit hiding padding machine (0)", waiting for "Opened Socks listener"
2019-05-28 21:51:15.504 Tor logged: "May 28 21:51:15.504 [info] circpad_machine_client_hide_rend_circuits: Registered client rendezvous circuit hiding padding machine (1)", waiting for "Opened Socks listener"
2019-05-28 21:51:15.505 Tor logged: "May 28 21:51:15.505 [info] circpad_machine_relay_hide_rend_circuits: Registered relay rendezvous circuit hiding padding machine (1)", waiting for "Opened Socks listener"
2019-05-28 21:51:15.507 Tor logged: "May 28 21:51:15.505 [info] add_predicted_port: New port prediction added. Will continue predictive circ building for 2911 more seconds.", waiting for "Opened Socks listener"
2019-05-28 21:51:15.507 Tor logged: "May 28 21:51:15.507 [info] crypto_openssl_late_init: NOT using OpenSSL engine support.", waiting for "Opened Socks listener"
2019-05-28 21:51:15.507 Tor logged: "May 28 21:51:15.507 [info] evaluate_evp_for_aes: This version of OpenSSL has a known-good EVP counter-mode implementation. Using it.", waiting for "Opened Socks listener"
2019-05-28 21:51:15.507 Tor logged: "May 28 21:51:15.507 [debug] file_status: stat()ing /var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/tor_rebind_test.XXXXXX.eMUA561I/unparseable-descs", waiting for "Opened Socks listener"
2019-05-28 21:51:15.545 Tor logged: "May 28 21:51:15.544 [notice] Bootstrapped 0% (starting): Starting", waiting for "Opened Socks listener"
2019-05-28 21:51:15.545 Tor logged: "May 28 21:51:15.545 [info] read_file_to_str: Could not open "/var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/tor_rebind_test.XXXXXX.eMUA561I/cached-certs": No such file or directory", waiting for "Opened Socks listener"
2019-05-28 21:51:15.546 Tor logged: "May 28 21:51:15.546 [info] tor_mmap_file: Could not open "/var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/tor_rebind_test.XXXXXX.eMUA561I/cached-consensus" for mmap(): No such file or directory", waiting for "Opened Socks listener"
2019-05-28 21:51:15.546 Tor logged: "May 28 21:51:15.546 [info] tor_mmap_file: Could not open "/var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/tor_rebind_test.XXXXXX.eMUA561I/unverified-consensus" for mmap(): No such file or directory", waiting for "Opened Socks listener"
2019-05-28 21:51:15.546 Tor logged: "May 28 21:51:15.546 [info] tor_mmap_file: Could not open "/var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/tor_rebind_test.XXXXXX.eMUA561I/cached-microdesc-consensus" for mmap(): No such file or directory", waiting for "Opened Socks listener"
2019-05-28 21:51:15.546 Tor logged: "May 28 21:51:15.546 [info] tor_mmap_file: Could not open "/var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/tor_rebind_test.XXXXXX.eMUA561I/unverified-microdesc-consensus" for mmap(): No such file or directory", waiting for "Opened Socks listener"
2019-05-28 21:51:15.549 Tor logged: "May 28 21:51:15.549 [info] tor_mmap_file: Could not open "/var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/tor_rebind_test.XXXXXX.eMUA561I/cached-microdescs" for mmap(): No such file or directory", waiting for "Opened Socks listener"
2019-05-28 21:51:15.549 Tor logged: "May 28 21:51:15.549 [info] read_file_to_str: Could not open "/var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/tor_rebind_test.XXXXXX.eMUA561I/cached-microdescs.new": No such file or directory", waiting for "Opened Socks listener"
2019-05-28 21:51:15.549 Tor logged: "May 28 21:51:15.549 [info] microdesc_cache_reload: Reloaded microdescriptor cache. Found 0 descriptors.", waiting for "Opened Socks listener"
2019-05-28 21:51:15.551 Tor logged: "May 28 21:51:15.551 [info] tor_mmap_file: Could not open "/var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/tor_rebind_test.XXXXXX.eMUA561I/cached-descriptors" for mmap(): No such file or directory", waiting for "Opened Socks listener"
2019-05-28 21:51:15.551 Tor logged: "May 28 21:51:15.551 [debug] file_status: stat()ing /var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/tor_rebind_test.XXXXXX.eMUA561I/cached-descriptors.new", waiting for "Opened Socks listener"
2019-05-28 21:51:15.553 Tor logged: "May 28 21:51:15.553 [info] tor_mmap_file: Could not open "/var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/tor_rebind_test.XXXXXX.eMUA561I/cached-extrainfo" for mmap(): No such file or directory", waiting for "Opened Socks listener"
2019-05-28 21:51:15.553 Tor logged: "May 28 21:51:15.553 [debug] file_status: stat()ing /var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/tor_rebind_test.XXXXXX.eMUA561I/cached-extrainfo.new", waiting for "Opened Socks listener"
2019-05-28 21:51:15.554 Tor logged: "May 28 21:51:15.554 [notice] Starting with guard context "default"", waiting for "Opened Socks listener"
2019-05-28 21:51:15.554 Tor logged: "May 28 21:51:15.554 [debug] get_guard_selection_by_name: Creating a guard selection called default", waiting for "Opened Socks listener"
2019-05-28 21:51:15.554 Tor logged: "May 28 21:51:15.554 [info] sampled_guards_update_from_consensus: Not updating the sample guard set; we have no reasonably live consensus.", waiting for "Opened Socks listener"
2019-05-28 21:51:15.554 Tor logged: "May 28 21:51:15.554 [info] sample_reachable_filtered_entry_guards: Trying to sample a reachable guard: We know of 0 in the USABLE_FILTERED set.", waiting for "Opened Socks listener"
2019-05-28 21:51:15.555 Tor logged: "May 28 21:51:15.555 [info] sample_reachable_filtered_entry_guards:   (That isn't enough. Trying to expand the sample.)", waiting for "Opened Socks listener"
2019-05-28 21:51:15.555 Tor logged: "May 28 21:51:15.555 [info] entry_guards_expand_sample: Not expanding the sample guard set; we have no reasonably live consensus.", waiting for "Opened Socks listener"
2019-05-28 21:51:15.555 Tor logged: "May 28 21:51:15.555 [info] sample_reachable_filtered_entry_guards:   (After filters [b], we have 0 guards to consider.)", waiting for "Opened Socks listener"
2019-05-28 21:51:15.556 Tor logged: "May 28 21:51:15.556 [info] I learned some more directory information, but not enough to build a circuit: We have no usable consensus.", waiting for "Opened Socks listener"
2019-05-28 21:51:15.557 Tor logged: "May 28 21:51:15.557 [debug] conn_read_callback: socket 4 wants to read.", waiting for "Opened Socks listener"
2019-05-28 21:51:15.558 Tor logged: "May 28 21:51:15.558 [debug] connection_handle_listener_read: Connection accepted on socket 7 (child of fd 4).", waiting for "Opened Socks listener"
2019-05-28 21:51:15.559 Tor logged: "May 28 21:51:15.559 [info] connection_handle_listener_read: New SOCKS connection opened from 127.0.0.1.", waiting for "Opened Socks listener"
2019-05-28 21:51:15.559 Tor logged: "May 28 21:51:15.559 [debug] connection_add_impl: new conn type Socks, socket 7, address 127.0.0.1, n_conns 3.", waiting for "Opened Socks listener"
2019-05-28 21:51:15.559 Tor logged: "May 28 21:51:15.559 [debug] conn_read_callback: socket 5 wants to read.", waiting for "Opened Socks listener"
2019-05-28 21:51:15.560 Tor logged: "May 28 21:51:15.560 [debug] connection_handle_listener_read: Connection accepted on socket 8 (child of fd 5).", waiting for "Opened Socks listener"
2019-05-28 21:51:15.560 Tor logged: "May 28 21:51:15.560 [notice] New control connection opened from 127.0.0.1.", waiting for "Opened Socks listener"
2019-05-28 21:51:15.560 Tor logged: "May 28 21:51:15.560 [debug] connection_add_impl: new conn type Control, socket 8, address 127.0.0.1, n_conns 4.", waiting for "Opened Socks listener"
2019-05-28 21:51:15.560 Tor logged: "May 28 21:51:15.560 [debug] conn_read_callback: socket 7 wants to read.", waiting for "Opened Socks listener"
2019-05-28 21:51:15.560 Tor logged: "May 28 21:51:15.560 [debug] read_to_chunk: Encountered eof on fd 7", waiting for "Opened Socks listener"
2019-05-28 21:51:15.563 Tor logged: "May 28 21:51:15.561 [debug] connection_ap_handshake_process_socks: entered.", waiting for "Opened Socks listener"
2019-05-28 21:51:15.571 Tor logged: "May 28 21:51:15.571 [debug] connection_ap_handshake_process_socks: socks handshake not all here yet.", waiting for "Opened Socks listener"
2019-05-28 21:51:15.571 Tor logged: "May 28 21:51:15.571 [info] connection_edge_reached_eof: conn (fd 7) reached eof. Closing.", waiting for "Opened Socks listener"
2019-05-28 21:51:15.571 Tor logged: "May 28 21:51:15.571 [debug] connection_edge_end: No circ to send end on conn (fd 7).", waiting for "Opened Socks listener"
2019-05-28 21:51:15.571 Tor logged: "May 28 21:51:15.571 [debug] conn_close_if_marked: Cleaning up connection (fd 7).", waiting for "Opened Socks listener"
2019-05-28 21:51:15.573 Tor logged: "May 28 21:51:15.572 [debug] connection_remove: removing socket 7 (type Socks), n_conns now 4", waiting for "Opened Socks listener"
2019-05-28 21:51:15.573 Tor logged: "May 28 21:51:15.573 [debug] connection_free_minimal: closing fd 7.", waiting for "Opened Socks listener"
2019-05-28 21:51:15.573 Tor logged: "May 28 21:51:15.573 [debug] conn_read_callback: socket 8 wants to read.", waiting for "Opened Socks listener"
2019-05-28 21:51:15.573 Tor logged: "May 28 21:51:15.573 [debug] read_to_chunk: Read 48 bytes. 48 on inbuf.", waiting for "Opened Socks listener"
2019-05-28 21:51:15.573 Tor logged: "May 28 21:51:15.573 [info] handle_control_authenticate: Authenticated control connection (8)", waiting for "Opened Socks listener"
2019-05-28 21:51:15.579 Tor logged: "May 28 21:51:15.579 [warn] ControlPort is open, but no authentication method has been configured.  This means that any program on your computer can reconfigure your Tor.  That's bad!  You should upgrade your Tor controller as soon as possible.", waiting for "Opened Socks listener"
2019-05-28 21:51:15.579 Tor logged: "May 28 21:51:15.579 [debug] parse_addr_policy: Adding new entry 'reject *4:*'", waiting for "Opened Socks listener"
2019-05-28 21:51:15.580 Tor logged: "May 28 21:51:15.580 [debug] parse_addr_policy: Adding new entry 'reject *6:*'", waiting for "Opened Socks listener"
2019-05-28 21:51:15.581 Tor logged: "May 28 21:51:15.581 [info] set_max_file_descriptors: Raising max file descriptors from 10208 to 9223372036854775807.", waiting for "Opened Socks listener"
2019-05-28 21:51:15.581 Tor logged: "May 28 21:51:15.581 [info] set_max_file_descriptors: Dropped connection limit to 10208 based on OPEN_MAX (10240); Apparently, 9223372036854775807 was too high and rlimit lied to us.", waiting for "Opened Socks listener"
2019-05-28 21:51:15.581 Tor logged: "May 28 21:51:15.581 [warn] You specified a public address '0.0.0.0:36475' for SocksPort. Other people on the Internet might find your computer and use it as an open proxy. Please don't allow this unless you have a good reason.", waiting for "Opened Socks listener"
2019-05-28 21:51:15.581 Tor logged: "May 28 21:51:15.581 [debug] retry_all_listeners: 1 replacements - starting rebinding loop.", waiting for "Opened Socks listener"
2019-05-28 21:51:15.582 Tor logged: "May 28 21:51:15.582 [notice] Opening Socks listener on 0.0.0.0:36475", waiting for "Opened Socks listener"
2019-05-28 21:51:15.582 Tor logged: "May 28 21:51:15.582 [debug] connection_add_impl: new conn type Socks listener, socket 7, address 0.0.0.0, n_conns 4.", waiting for "Opened Socks listener"
2019-05-28 21:51:15.582 Tor logged: "May 28 21:51:15.582 [debug] connection_listener_new: Socks listener listening on port 36475.", waiting for "Opened Socks listener"
2019-05-28 21:51:15.582 Tor logged: "May 28 21:51:15.582 [notice] Opened Socks listener on 0.0.0.0:36475"
2019-05-28 21:51:15.582 FAIL
Cannot connect to SOCKSPort: error Connection reset by peer
+exitcode=1
+exit 1
+clean
+'[' -n /var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/tor_rebind_test.XXXXXX.eMUA561I ']'
+'[' -d /var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/tor_rebind_test.XXXXXX.eMUA561I ']'
+rm -rf /var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/tor_rebind_test.XXXXXX.eMUA561I
FAIL src/test/test_rebind.sh (exit status: 1)

comment:27 Changed 5 months ago by nickm

Keywords: 041-should added

comment:28 Changed 5 months ago by teor

A failure every 2 weeks doesn't seem that bad. But I agree that we should fix this issue if we can.

Can we reduce the frequency of this issue by adding a delay in the script?
Can we bind to localhost, to avoid issues with remote scanners?

comment:29 in reply to:  28 ; Changed 5 months ago by catalyst

Replying to teor:

A failure every 2 weeks doesn't seem that bad. But I agree that we should fix this issue if we can.

I think it's happening more often. I think sometimes people restart or ignore it when it fails. I know I don't always remember to note on the ticket when I see a spurious failure, because I don't always remember to, or sometimes I intend to look up the ticket number end up not doing so.

comment:30 in reply to:  29 Changed 5 months ago by teor

Replying to catalyst:

Replying to teor:

A failure every 2 weeks doesn't seem that bad. But I agree that we should fix this issue if we can.

I think it's happening more often. I think sometimes people restart or ignore it when it fails. I know I don't always remember to note on the ticket when I see a spurious failure, because I don't always remember to, or sometimes I intend to look up the ticket number end up not doing so.

I understand.

It would be great to have a list of all Travis / Appveyor / Jenkins failures in one place, with attribution and ticket numbers. But I'm not sure we have time to build something like that right now.

comment:31 Changed 5 months ago by catalyst

Priority: LowMedium

Bumping priority because it's making Travis fail somewhat often.

comment:32 Changed 4 months ago by teor

Keywords: tor-ci-fail-sometimes removed

Removing from the CI failure tag, because we skipped the failing tests in #30713.

comment:33 Changed 3 months ago by nickm

Keywords: 041-deferred-20190719 added; 041-should removed

Add 041-deferred-20190719 tag to 041-should tickets I am deferring today.

comment:34 Changed 3 months ago by nickm

Milestone: Tor: 0.4.1.x-finalTor: unspecified
Note: See TracTickets for help on using tickets.