Opened 6 months ago

Last modified 9 days ago

#28229 new defect

Possible race condition opening SOCKS Port in test_rebind.py

Reported by: teor Owned by: rl1987
Priority: Low Milestone: Tor: 0.4.1.x-final
Component: Core Tor/Tor Version: Tor: 0.3.5.1-alpha
Severity: Normal Keywords: tor-ci, rare?, 035-backport, 040-backport
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

Change History (24)

comment:1 Changed 6 months ago by rl1987

Owner: set to rl1987
Status: newaccepted

Will try to look into this in next few days.

comment:2 Changed 5 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 5 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 5 months ago by dgoulet

Reviewer: catalyst

comment:5 in reply to:  2 Changed 5 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 5 months ago by nickm

Keywords: 035-can added

comment:7 Changed 5 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 5 months ago by rl1987

Status: needs_revisionneeds_review

comment:9 Changed 5 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 5 months ago by teor

Status: needs_reviewmerge_ready

This change seems fine to me.

comment:11 Changed 5 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 5 months ago by nickm

Status: assignednew

comment:13 Changed 5 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 5 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 5 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 5 months ago by rl1987

Status: newneeds_review

comment:17 Changed 5 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 4 months ago by nickm

Status: merge_readyassigned

Merged to master, not closed.

comment:19 Changed 4 months ago by nickm

Status: assignednew

comment:20 Changed 3 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 3 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 3 weeks 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 3 weeks 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 9 days 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

Note: See TracTickets for help on using tickets.