GoogleCloudPlatform / GoogleCloudPlatform/gsutil

Gsutil sometimes deadlocks in to threading/multiprocessing Queue get() under Python 3.5

Open
#829 3 comments 2 reactions 0 assignees View on GitHub
Dominant language
Python
Stars
918
Forks
335
PR merge metrics
No merged PRs in 30d

Description

I'm mostly writing this issue to provide context in case others see this problem.

The commands below were run on Google Compute Engine VM running Debian 9.

In our v4.40 prerelease candidate, we can consistently get gsutil to hang in specific integration tests. These include tests where parallelism (the -m flag) is used, and where a nonexistent bucket is passed as an argument:

- gslib.tests.test_iam.TestIamCh.test_patch_multithreaded_error
- gslib.tests.test_iam.TestIamSet.test_set_multithreaded_error
- For internal Google devs, a sample log ID is 5d47c6a8-4862-4b85-a77e-9da75d0e69ff
- gslib.tests.test_rsync.TestRsync.test_rsync_from_nonexistent_bucket
- For internal Google devs, a sample log ID is f0ea91c1-4326-45b8-a8cf-1260c332903f

Looking further at the IAM test as an example, I believe this is a race condition that only occurs under heavy load with multiple processes competing for CPU time (thus potentially altering the order in which processes/threads and their associated queues are operated on); I cannot get this failure to occur when running the test on its own, even after running it hundreds of times in a row:

```
$ for i in {1..200}; do
LC_ALL=en_US.UTF-8 python3 ./gsutil -D test -p 1 iam.TestIamSet.test_set_multithreaded_error;
if [[ $? -ne 0 ]]; then break; fi;
done
```

I can, however, get this to happen if I run the entire set of IAM tests, parallelized across a high number of processes:

**EDIT: This will no longer hang in Python 3 after we added this commit -- https://github.com/GoogleCloudPlatform/gsutil/commit/ad38858001425df5f7bc325828b746a7945a337c -- you should remove that timeout argument if you want to reproduce this bug within integration tests.**

```
$ for i in {1..400}; do
echo "Running iteration $i";
LC_ALL=en_US.UTF-8 python3 ./gsutil -D test -p 32 iam;
if [[ $? -eq 0 ]]; then clear; else break; fi;
done
```

Once I got an invocation to hang, I verified that it was indeed hanging on one of the tests where a nonexistent bucket was being passed as an arg to the command being run (it hung on test_patch_multithreaded_error), then I installed gdb with python extensions:

```
sudo apt-get install gdb python3.5-dbg
```

I then grabbed the PIDs of running Python processes so I could find the "youngest" one (this will be the subprocess invoked by the `RunGsUtil()` command within the test) and attach gdb to it:

```
$ ps -aux | grep python
root 1132 0.0 0.0 54748 20096 ? Ss Jun21 0:14 /usr/bin/python /usr/bin/google_network_daemon
root 1134 0.0 0.0 54744 20004 ? Ss Jun21 0:07 /usr/bin/python /usr/bin/google_clock_skew_daemon
root 1139 0.0 0.0 55052 20664 ? Ss Jun21 0:35 /usr/bin/python /usr/bin/google_accounts_daemon
houglum 11511 0.0 0.0 98188 40708 pts/0 T Jun22 0:36 python3 ./gsutil -D test -p 32 iam
houglum 11515 0.0 0.0 244952 33012 pts/0 Tl Jun22 0:27 python3 ./gsutil -D test -p 32 iam
houglum 11517 0.0 0.0 236756 33032 pts/0 Tl Jun22 0:27 python3 ./gsutil -D test -p 32 iam
houglum 11616 0.0 0.0 104608 41568 pts/0 T Jun22 0:00 /usr/bin/python3 /home/houglum/rchoug/gsutil/gsutil -o GSUtil:default_project_id= test --sequential_only iam.TestIamCh.test_patch_multithreaded_error
houglum 11782 0.0 0.0 310484 32932 pts/0 Tl Jun22 0:27 /usr/bin/python3 /home/houglum/rchoug/gsutil/gsutil -o GSUtil:default_project_id= test --sequential_only iam.TestIamCh.test_patch_multithreaded_error
houglum 11795 0.0 0.0 310484 32952 pts/0 Tl Jun22 0:27 /usr/bin/python3 /home/houglum/rchoug/gsutil/gsutil -o GSUtil:default_project_id= test --sequential_only iam.TestIamCh.test_patch_multithreaded_error
houglum 19220 0.0 0.0 12780 956 pts/0 R+ 17:26 0:00 grep python
houglum 25628 0.0 0.0 327948 41888 pts/0 T Jun22 0:00 /usr/bin/python3 /home/houglum/rchoug/gsutil/gsutil --testexceptiontraces -o GSUtil:default_project_id= -m iam ch -r user:foo@bar.com:legacyObjectReader gs://nonexistent-bucket-foobar.gmail.com gs://gsutil-test-test-patch-multithreaded-error-bucket-e312ec2d/
houglum 29862 0.0 0.0 472884 36720 pts/0 Sl Jun22 0:00 /usr/bin/python3 /home/houglum/rchoug/gsutil/gsutil --testexceptiontraces -o GSUtil:default_project_id= -m iam ch -r user:foo@bar.com:legacyObjectReader gs://nonexistent-bucket-foobar.gmail.com gs://gsutil-test-test-patch-multithreaded-error-bucket-e312ec2d/
```

... and then attached gdb and grabbed the py backtrace for all threads:

```
$ gdb python3 29862
(gdb) thread apply all py-bt

Thread 6 (Thread 0x7fc51a7fc700 (LWP 3526)):
Traceback (most recent call first):

File "/usr/lib/python3.5/threading.py", line 293, in wait
waiter.acquire()
File "/usr/lib/python3.5/queue.py", line 164, in get
self.not_empty.wait()
File "/home/houglum/rchoug/gsutil/gslib/command.py", line 2337, in run
task = self.task_queue.get()
File "/usr/lib/python3.5/threading.py", line 914, in _bootstrap_inner
self.run()
File "/usr/lib/python3.5/threading.py", line 882, in _bootstrap
self._bootstrap_inner()

Thread 5 (Thread 0x7fc51affd700 (LWP 3491)):
Traceback (most recent call first):

File "/usr/lib/python3.5/threading.py", line 293, in wait
waiter.acquire()
File "/usr/lib/python3.5/queue.py", line 164, in get
self.not_empty.wait()
File "/home/houglum/rchoug/gsutil/gslib/command.py", line 2337, in run
task = self.task_queue.get()
File "/usr/lib/python3.5/threading.py", line 914, in _bootstrap_inner
self.run()
File "/usr/lib/python3.5/threading.py", line 882, in _bootstrap
self._bootstrap_inner()

Thread 4 (Thread 0x7fc51b7fe700 (LWP 3460)):
Traceback (most recent call first):

File "/usr/lib/python3.5/threading.py", line 293, in wait
waiter.acquire()
File "/usr/lib/python3.5/queue.py", line 164, in get
self.not_empty.wait()
File "/home/houglum/rchoug/gsutil/gslib/command.py", line 2337, in run
task = self.task_queue.get()
File "/usr/lib/python3.5/threading.py", line 914, in _bootstrap_inner
self.run()
File "/usr/lib/python3.5/threading.py", line 882, in _bootstrap
self._bootstrap_inner()

Thread 3 (Thread 0x7fc51bfff700 (LWP 3445)):
Traceback (most recent call first):

File "/usr/lib/python3.5/threading.py", line 293, in wait
waiter.acquire()
File "/usr/lib/python3.5/queue.py", line 164, in get
self.not_empty.wait()
File "/home/houglum/rchoug/gsutil/gslib/command.py", line 2337, in run
task = self.task_queue.get()
File "/usr/lib/python3.5/threading.py", line 914, in _bootstrap_inner
self.run()
File "/usr/lib/python3.5/threading.py", line 882, in _bootstrap
self._bootstrap_inner()

Thread 2 (Thread 0x7fc52091d700 (LWP 3442)):
Traceback (most recent call first):

File "/usr/lib/python3.5/threading.py", line 293, in wait
waiter.acquire()
File "/usr/lib/python3.5/queue.py", line 164, in get
self.not_empty.wait()
File "/home/houglum/rchoug/gsutil/gslib/command.py", line 2337, in run
task = self.task_queue.get()
File "/usr/lib/python3.5/threading.py", line 914, in _bootstrap_inner
self.run()
File "/usr/lib/python3.5/threading.py", line 882, in _bootstrap
self._bootstrap_inner()

---Type to continue, or q to quit---
Thread 1 (Thread 0x7fc525ead700 (LWP 29862)):
Traceback (most recent call first):

File "/usr/lib/python3.5/multiprocessing/synchronize.py", line 96, in __enter__
return self._semlock.__enter__()
File "/usr/lib/python3.5/multiprocessing/queues.py", line 93, in get
with self._rlock:
File "/home/houglum/rchoug/gsutil/gslib/command.py", line 1901, in _ApplyThreads
task = task_queue.get()
File "/usr/lib/python3.5/multiprocessing/process.py", line 93, in run
self._target(*self._args, **self._kwargs)
File "/usr/lib/python3.5/multiprocessing/process.py", line 249, in _bootstrap
self.run()
File "/usr/lib/python3.5/multiprocessing/popen_fork.py", line 74, in _launch
code = process_obj._bootstrap()
File "/usr/lib/python3.5/multiprocessing/popen_fork.py", line 20, in __init__
self._launch(process_obj)
File "/usr/lib/python3.5/multiprocessing/context.py", line 267, in _Popen
return Popen(process_obj)
File "/usr/lib/python3.5/multiprocessing/context.py", line 212, in _Popen
return _default_context.get_context().Process._Popen(process_obj)
File "/usr/lib/python3.5/multiprocessing/process.py", line 105, in start
self._popen = self._Popen(self)
File "/home/houglum/rchoug/gsutil/gslib/command.py", line 1384, in _CreateNewConsumerPool
p.start()
File "/home/houglum/rchoug/gsutil/gslib/command.py", line 1720, in _ParallelApply
glob_status_queue)
File "/home/houglum/rchoug/gsutil/gslib/command.py", line 1510, in Apply
parallel_operations_override=parallel_operations_override)
File "/home/houglum/rchoug/gsutil/gslib/commands/iam.py", line 557, in _PatchIam
seek_ahead_iterator=seek_ahead_iterator)
File "/home/houglum/rchoug/gsutil/gslib/commands/iam.py", line 694, in RunCommand
self._PatchIam()
File "/home/houglum/rchoug/gsutil/gslib/command_runner.py", line 411, in RunNamedCommand
return_code = command_inst.RunCommand()
File "/home/houglum/rchoug/gsutil/gslib/__main__.py", line 626, in _RunNamedCommandAndHandleExceptions
user_project=user_project)
File "/home/houglum/rchoug/gsutil/gslib/__main__.py", line 431, in main
user_project=user_project)
File "/home/houglum/rchoug/gsutil/gsutil.py", line 129, in RunMain
sys.exit(gslib.__main__.main())
File "/home/houglum/rchoug/gsutil/gsutil", line 21, in
gsutil.RunMain()
```

I also did this for the parent PID, which was (unsurprisingly) stuck waiting for all the child processes to finish and join():

```
$ gdb python3 25628
(gdb) py-bt
Traceback (most recent call first):

File "/usr/lib/python3.5/multiprocessing/popen_fork.py", line 29, in poll
pid, sts = os.waitpid(self.pid, flag)
File "/usr/lib/python3.5/multiprocessing/popen_fork.py", line 51, in wait
return self.poll(os.WNOHANG if timeout == 0.0 else 0)
File "/usr/lib/python3.5/multiprocessing/process.py", line 121, in join
res = self._popen.wait(timeout)
File "/usr/lib/python3.5/multiprocessing/util.py", line 311, in _exit_function
p.join()
```

Contributor guide

Open the contributing guide

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.