Possible race condition opening SOCKS Port in test_rebind.py

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 (moved), 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.

changed milestone to %Tor: unspecified

added 035-backport 040-backport 041-deferred-20190719 component::core tor/tor milestone::Tor: unspecified owner::rl1987 points::1 priority::medium rare? severity::normal status::new tor-ci type::defect version::tor 0.3.5.1-alpha labels

Will try to look into this in next few days.

Trac:
Owner: N/A to rl1987
Status: new to accepted

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.

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

Trac:
Status: accepted to needs_review

Trac:
Reviewer: N/A to catalyst

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).

Trac:
Status: needs_review to merge_ready

Trac:
Keywords: N/A deleted, 035-can added

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.

Trac:
Status: merge_ready to needs_revision

Trac:
Status: needs_revision to needs_review

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

Trac:
Reviewer: catalyst to teor

This change seems fine to me.

Trac:
Status: needs_review to merge_ready

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.

Trac:
Status: merge_ready to assigned

Trac:
Status: assigned to new

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

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.

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.

Trac:
Status: new to needs_review

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

Trac:
Status: needs_review to merge_ready

Merged to master, not closed.

Trac:
Status: merge_ready to assigned