Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Ordering issue with child reaping in tether #2330

Closed
hickeng opened this issue Sep 15, 2016 · 3 comments
Closed

Ordering issue with child reaping in tether #2330

hickeng opened this issue Sep 15, 2016 · 3 comments
Assignees
@caglar10ur
Labels
component/tether kind/defect Behavior that is inconsistent with what's intended
Milestone
VIC GA Release

Comments

@hickeng
Copy link
Member

hickeng commented Sep 15, 2016 

time="2016-09-14T20:13:52Z" level=info msg="Started test setup for github.com/vmware/vic/lib/tether.TestPathLookup" 
time="2016-09-14T20:13:52Z" level=debug msg="Test configuration: (func(string, string) error)(0x496a10)" 
time="2016-09-14T20:13:52Z" level=info msg="Registering tether extension Mocker" 
time="2016-09-14T20:13:52Z" level=debug msg="[BEGIN] [github.com/vmware/vic/lib/tether.(*tether).Start] main tether loop" 
time="2016-09-14T20:13:52Z" level=debug msg="[BEGIN] [github.com/vmware/vic/lib/tether.(*tether).setup] main tether setup" 
time="2016-09-14T20:13:52Z" level=info msg="Started reaping child processes" 
time="2016-09-14T20:13:52Z" level=info msg="Starting extension Mocker" 
time="2016-09-14T20:13:52Z" level=info msg="listen tcp 0.0.0.0:6060: bind: address already in use" 
time="2016-09-14T20:13:52Z" level=debug msg="[ END ] [github.com/vmware/vic/lib/tether.(*tether).setup] [598.298µs] main tether setup" 
time="2016-09-14T20:13:52Z" level=info msg="Loading main configuration" 
time="2016-09-14T20:13:52Z" level=info msg="Loaded executor config" 
time="2016-09-14T20:13:52Z" level=debug msg="[BEGIN] [github.com/vmware/vic/lib/tether.(*Mocker).SetHostname] mocking hostname to pathlookup" 
time="2016-09-14T20:13:52Z" level=debug msg="[ END ] [github.com/vmware/vic/lib/tether.(*Mocker).SetHostname] [440ns] mocking hostname to pathlookup" 
time="2016-09-14T20:13:52Z" level=debug msg="Processing config for session pathlookup" 
time="2016-09-14T20:13:52Z" level=info msg="Launching process for session pathlookup" 
time="2016-09-14T20:13:52Z" level=debug msg="[BEGIN] [github.com/vmware/vic/lib/tether.(*tether).launch] launching session pathlookup" 
time="2016-09-14T20:13:52Z" level=debug msg="[0xc42000d100] created multireader" 
time="2016-09-14T20:13:52Z" level=debug msg="Resolved date to /bin/date" 
time="2016-09-14T20:13:52Z" level=debug msg="Launched command with pid 24408" 
time="2016-09-14T20:13:52Z" level=debug msg="[ END ] [github.com/vmware/vic/lib/tether.(*tether).launch] [908.356µs] launching session pathlookup" 
time="2016-09-14T20:13:52Z" level=info msg="Passing config to Mocker" 
time="2016-09-14T20:13:52Z" level=debug msg="[0xc420232ee0] writing \"Wed Sep 14 20:03:25 UTC 2016\n\" to 1 writers" 
time="2016-09-14T20:13:52Z" level=debug msg="Inspecting children with status change" 
time="2016-09-14T20:13:52Z" level=debug msg="Reaped process 24408, return code: 0" 
time="2016-09-14T20:13:52Z" level=debug msg="[BEGIN] [github.com/vmware/vic/lib/tether.(*tether).handleSessionExit] handling exit of session pathlookup" 
time="2016-09-14T20:13:52Z" level=debug msg="[0xc42000d100] read \"\" from 0 readers" 
time="2016-09-14T20:13:52Z" level=info msg="pathlookup exit code: 0" 
time="2016-09-14T20:13:52Z" level=debug msg="[BEGIN] [github.com/vmware/vic/lib/tether.(*tether).Stop]" 
time="2016-09-14T20:13:52Z" level=debug msg="[ END ] [github.com/vmware/vic/lib/tether.(*tether).Stop] [14.353µs] " 
time="2016-09-14T20:13:52Z" level=debug msg="[ END ] [github.com/vmware/vic/lib/tether.(*tether).handleSessionExit] [314.284µs] handling exit of session pathlookup" 
time="2016-09-14T20:13:52Z" level=debug msg="Inspecting children with status change" 
time="2016-09-14T20:13:52Z" level=debug msg="No more child processes to reap" 
time="2016-09-14T20:13:52Z" level=debug msg="[BEGIN] [github.com/vmware/vic/lib/tether.(*tether).cleanup] main tether cleanup" 
time="2016-09-14T20:13:52Z" level=debug msg="[BEGIN] [github.com/vmware/vic/lib/tether.(*tether).stopReaper] Shutting down child reaping" 
time="2016-09-14T20:13:52Z" level=info msg="Shutting down reaper" 
time="2016-09-14T20:13:52Z" level=debug msg="[ END ] [github.com/vmware/vic/lib/tether.(*tether).stopReaper] [76.181µs] Shutting down child reaping" 
time="2016-09-14T20:13:52Z" level=info msg="Stopping extension Mocker" 
time="2016-09-14T20:13:52Z" level=debug msg="[ END ] [github.com/vmware/vic/lib/tether.(*tether).cleanup] [144.214µs] main tether cleanup" 
time="2016-09-14T20:13:52Z" level=debug msg="[ END ] [github.com/vmware/vic/lib/tether.(*tether).Start] [3.229146ms] main tether loop" 
time="2016-09-14T20:13:52Z" level=info msg="Finished test teardown for github.com/vmware/vic/lib/tether.TestPathLookup" 
time="2016-09-14T20:13:52Z" level=info msg="Started test setup for github.com/vmware/vic/lib/tether.TestRelativePath" 
time="2016-09-14T20:13:52Z" level=debug msg="Test configuration: (func(string, string) error)(0x496a10)" 
time="2016-09-14T20:13:52Z" level=info msg="Registering tether extension Mocker" 
time="2016-09-14T20:13:52Z" level=debug msg="[BEGIN] [github.com/vmware/vic/lib/tether.(*tether).Start] main tether loop" 
time="2016-09-14T20:13:52Z" level=debug msg="[BEGIN] [github.com/vmware/vic/lib/tether.(*tether).setup] main tether setup" 
time="2016-09-14T20:13:52Z" level=info msg="Started reaping child processes" 
time="2016-09-14T20:13:52Z" level=info msg="Starting extension Mocker" 
time="2016-09-14T20:13:52Z" level=info msg="listen tcp 0.0.0.0:6060: bind: address already in use" 
time="2016-09-14T20:13:52Z" level=debug msg="[ END ] [github.com/vmware/vic/lib/tether.(*tether).setup] [282.167µs] main tether setup" 
time="2016-09-14T20:13:52Z" level=info msg="Loading main configuration" 
time="2016-09-14T20:13:52Z" level=info msg="Loaded executor config" 
time="2016-09-14T20:13:52Z" level=debug msg="[BEGIN] [github.com/vmware/vic/lib/tether.(*Mocker).SetHostname] mocking hostname to relpath" 
time="2016-09-14T20:13:52Z" level=debug msg="[ END ] [github.com/vmware/vic/lib/tether.(*Mocker).SetHostname] [356ns] mocking hostname to relpath" 
time="2016-09-14T20:13:52Z" level=debug msg="Processing config for session relpath" 
time="2016-09-14T20:13:52Z" level=info msg="Launching process for session relpath" 
time="2016-09-14T20:13:52Z" level=debug msg="[BEGIN] [github.com/vmware/vic/lib/tether.(*tether).launch] launching session relpath" 
time="2016-09-14T20:13:52Z" level=debug msg="[0xc420266940] created multireader" 
time="2016-09-14T20:13:52Z" level=debug msg="Resolved ./date to /bin/./date" 
time="2016-09-14T20:13:52Z" level=debug msg="Launched command with pid 24409" 
time="2016-09-14T20:13:52Z" level=debug msg="[ END ] [github.com/vmware/vic/lib/tether.(*tether).launch] [570.121µs] launching session relpath" 
time="2016-09-14T20:13:52Z" level=info msg="Passing config to Mocker" 
time="2016-09-14T20:13:52Z" level=debug msg="[0xc420272360] writing \"Wed Sep 14 20:03:25 UTC 2016\n\" to 1 writers" 
time="2016-09-14T20:13:52Z" level=debug msg="Inspecting children with status change" 
time="2016-09-14T20:13:52Z" level=debug msg="Reaped process 24409, return code: 0" 
time="2016-09-14T20:13:52Z" level=debug msg="[BEGIN] [github.com/vmware/vic/lib/tether.(*tether).handleSessionExit] handling exit of session relpath" 
time="2016-09-14T20:13:52Z" level=debug msg="[0xc420266940] read \"\" from 0 readers" 
time="2016-09-14T20:13:52Z" level=info msg="relpath exit code: 0" 
time="2016-09-14T20:13:52Z" level=debug msg="[BEGIN] [github.com/vmware/vic/lib/tether.(*tether).Stop]" 
time="2016-09-14T20:13:52Z" level=debug msg="[ END ] [github.com/vmware/vic/lib/tether.(*tether).Stop] [8.415µs] " 
time="2016-09-14T20:13:52Z" level=debug msg="[BEGIN] [github.com/vmware/vic/lib/tether.(*tether).cleanup] main tether cleanup" 
time="2016-09-14T20:13:52Z" level=debug msg="[BEGIN] [github.com/vmware/vic/lib/tether.(*tether).stopReaper] Shutting down child reaping" 
time="2016-09-14T20:13:52Z" level=info msg="Shutting down reaper" 
time="2016-09-14T20:13:52Z" level=debug msg="[ END ] [github.com/vmware/vic/lib/tether.(*tether).handleSessionExit] [246.065µs] handling exit of session relpath" 
time="2016-09-14T20:13:52Z" level=debug msg="[ END ] [github.com/vmware/vic/lib/tether.(*tether).stopReaper] [43.392µs] Shutting down child reaping" 
time="2016-09-14T20:13:52Z" level=info msg="Stopping extension Mocker" 
time="2016-09-14T20:13:52Z" level=debug msg="[ END ] [github.com/vmware/vic/lib/tether.(*tether).cleanup] [70.452µs] main tether cleanup" 
time="2016-09-14T20:13:52Z" level=debug msg="[ END ] [github.com/vmware/vic/lib/tether.(*tether).Start] [1.905807ms] main tether loop" 
time="2016-09-14T20:13:52Z" level=info msg="Finished test teardown for github.com/vmware/vic/lib/tether.TestRelativePath" 
time="2016-09-14T20:13:52Z" level=info msg="Started test setup for github.com/vmware/vic/lib/tether.TestAbsPath" 
time="2016-09-14T20:13:52Z" level=debug msg="Test configuration: (func(string, string) error)(0x496a10)" 
time="2016-09-14T20:13:52Z" level=info msg="Registering tether extension Mocker" 
time="2016-09-14T20:13:52Z" level=debug msg="[BEGIN] [github.com/vmware/vic/lib/tether.(*tether).Start] main tether loop" 
time="2016-09-14T20:13:52Z" level=debug msg="[BEGIN] [github.com/vmware/vic/lib/tether.(*tether).setup] main tether setup" 
time="2016-09-14T20:13:52Z" level=info msg="Started reaping child processes" 
time="2016-09-14T20:13:52Z" level=info msg="Starting extension Mocker" 
time="2016-09-14T20:13:52Z" level=debug msg="[ END ] [github.com/vmware/vic/lib/tether.(*tether).setup] [144.044µs] main tether setup" 
time="2016-09-14T20:13:52Z" level=info msg="Loading main configuration" 
time="2016-09-14T20:13:52Z" level=info msg="Loaded executor config" 
time="2016-09-14T20:13:52Z" level=debug msg="[BEGIN] [github.com/vmware/vic/lib/tether.(*Mocker).SetHostname] mocking hostname to abspath" 
time="2016-09-14T20:13:52Z" level=debug msg="[ END ] [github.com/vmware/vic/lib/tether.(*Mocker).SetHostname] [345ns] mocking hostname to abspath" 
time="2016-09-14T20:13:52Z" level=debug msg="Processing config for session abspath" 
time="2016-09-14T20:13:52Z" level=info msg="Launching process for session abspath" 
time="2016-09-14T20:13:52Z" level=debug msg="[BEGIN] [github.com/vmware/vic/lib/tether.(*tether).launch] launching session abspath" 
time="2016-09-14T20:13:52Z" level=debug msg="[0xc420267e80] created multireader" 
time="2016-09-14T20:13:52Z" level=debug msg="Resolved /bin/date to /bin/date" 
time="2016-09-14T20:13:52Z" level=debug msg="Inspecting children with status change" 
time="2016-09-14T20:13:52Z" level=debug msg="Reaped process 24410, return code: 0" 
time="2016-09-14T20:13:52Z" level=info msg="Reaped zombie process PID 24410\n" 
time="2016-09-14T20:13:52Z" level=debug msg="Inspecting children with status change" 
time="2016-09-14T20:13:52Z" level=debug msg="No more child processes to reap" 
time="2016-09-14T20:13:52Z" level=debug msg="[0xc4202a1a80] writing \"Wed Sep 14 20:03:25 UTC 2016\n\" to 1 writers" 
time="2016-09-14T20:13:52Z" level=info msg="listen tcp 0.0.0.0:6060: bind: address already in use" 
time="2016-09-14T20:13:52Z" level=debug msg="Launched command with pid 24410" 
time="2016-09-14T20:13:52Z" level=debug msg="Inspecting children with status change" 
time="2016-09-14T20:13:52Z" level=debug msg="[ END ] [github.com/vmware/vic/lib/tether.(*tether).launch] [1.068905ms] launching session abspath" 
time="2016-09-14T20:13:52Z" level=info msg="Passing config to Mocker" 
SIGQUIT: quit
PC=0x4615a3 m=2

The final test in that set:

time="2016-09-14T20:13:52Z" level=info msg="Started test setup for github.com/vmware/vic/lib/tether.TestAbsPath" 
...
time="2016-09-14T20:13:52Z" level=info msg="Passing config to Mocker"

shows us reaping pid 24410 as a zombie, meaning that we didn't have it present in the pid map for the child reaper. We later see the launch message for 24410.
@hickeng hickeng added kind/defect Behavior that is inconsistent with what's intended component/tether labels Sep 15, 2016
@mdubya66 mdubya66 added this to the VIC GA Release milestone Sep 16, 2016
@hickeng hickeng assigned caglar10ur and unassigned hickeng Oct 7, 2016
@hickeng
Copy link
Member Author

hickeng commented Oct 7, 2016 •
edited
Loading

Think this is already in progress with #858

@hickeng
Copy link
Member Author

hickeng commented Oct 9, 2016

We can try making https://github.com/vmware/vic/blob/master/lib/tether/config.go#L38 a pointer instead - @casualjim mentioned that he's seen something like this before with a copy occurring somewhere in our paths. I don't see one, but...

@mhagen-vmware mhagen-vmware mentioned this issue Oct 12, 2016
Closed
@caglar10ur caglar10ur mentioned this issue Oct 12, 2016
Merged
caglar10ur added a commit that referenced this issue Oct 15, 2016
@caglar10ur
[full ci] Fix multiple data races reported by race detector (#2702)
b28bd24 
* Fix multiple data races reported by race detector

- attachServerSSH uses sync/atomic to get/set enabled value as there was
a race between stop and run

- underlying *net.Conn is now protected by its own mutex as there was a
race between stop and run

- *ssh.ServerConn is now protected by its own mutex as we are sending
it to channel mux (as a part of the cleanup function)

- incoming signals channel in tether is now accompanied by another
channel called done. Its whole purpose is to stop the reaper loop after we
close the incoming channel. Without this we keep reading from it.

Fixes #2647, #2646 and #2330
@anchal-agrawal
Copy link
Contributor

Closing via #2702

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@caglar10ur caglar10ur

Labels
component/tether kind/defect Behavior that is inconsistent with what's intended
Projects
None yet
Milestone
VIC GA Release
Development

No branches or pull requests
4 participants
@caglar10ur @hickeng @anchal-agrawal @mdubya66