swift-object-replicator killing long-running rsync failing to actually kill rsync causing replication backlog

Bug #1691570 reported by Drew Freiberger on 2017-05-17
18
This bug affects 4 people
Affects Status Importance Assigned to Milestone
OpenStack Object Storage (swift)
Undecided
Unassigned
OpenStack swift-storage charm
Undecided
Unassigned

Bug Description

In an environment with 3 swift-storage zones, with 3 hosts in each zone, with 20 x 1TB disk drives and roughly 500million objects, we're finding that object replication is hanging up on one or more of the nodes.

Digging into it more deeply, I find that there are hung rsync processes which appear to be hung trying to write to the pipe opened by swift-object-replicator for IPC. See below:

ubuntu@myhost-cs-011:~$ ps -ef |grep 2993422|cut -c1-230
ubuntu 1987011 1977905 0 20:31 pts/0 00:00:00 grep --color=auto 2993422
swift 2993422 1 0 May11 ? 00:04:06 /usr/bin/python /usr/bin/swift-object-replicator /etc/swift/object-server.conf
swift 2993891 2993422 0 May11 ? 00:14:29 [rsync] <defunct>
swift 2993898 2993422 0 May11 ? 00:15:04 rsync --recursive --whole-file --human-readable --xattrs --itemize-changes --ignore-existing --timeout=30 --contimeout=30 --bwlimit=0 /srv/node/bcache11/objects/250/b3e /srv/node.....
*snip*
swift 3000030 2993422 0 May11 ? 00:19:05 rsync --recursive --whole-file --human-readable --xattrs --itemize-changes --ignore-existing --timeout=30 --contimeout=30 --bwlimit=0 /srv/node/bcache1/objects/226/000 /srv/node/.....

ubuntu@myhost-cs-011:~$ sudo strace -p 2993898
Process 2993898 attached
write(1, "<f+++++++++ 194/fa85c4fdeac6158d"..., 71^CProcess 2993898 detached
 <detached ...>

ubuntu@myhost-cs-011:~$ sudo ls -l /proc/2993898/fd/1
l-wx------ 1 swift swift 64 May 17 20:16 /proc/2993898/fd/1 -> pipe:[70538904]
ubuntu@myhost-cs-011:~$ sudo lsof |grep 70538904|grep -v rsync
swift-obj 2993422 swift 42r FIFO 0,10 0t0 70538904 pipe
swift-obj 2993422 2993435 swift 42r FIFO 0,10 0t0 70538904 pipe
swift-obj 2993422 2993436 swift 42r FIFO 0,10 0t0 70538904 pipe
swift-obj 2993422 2993437 swift 42r FIFO 0,10 0t0 70538904 pipe
*snip*
swift-obj 2993422 2993453 swift 42r FIFO 0,10 0t0 70538904 pipe
swift-obj 2993422 2993454 swift 42r FIFO 0,10 0t0 70538904 pipe

A snippet from syslog appears to show swift-object-replicator tyring to kill these processes:

/var/log/syslog.7.gz:May 11 06:04:52 myhost-cs-011 object-replicator: Killing long-running rsync: ['rsync', '--recursive', '--whole-file', '--human-readable', '--xattrs', '--itemize-changes', '--ignore-existing', '--timeout=30', '--contimeout=30', '--bwlimit=0', u'/srv/node/bcache11/objects/250/b3e', u'/srv/node/bcache11/objects/250/000', u'/srv/node/bcache11/objects/250/001', u'/srv/node/bcache11/objects/250/002', u'/srv/node/bcache11/objects/250/003', u'/srv/node/bcache11/objects/250/004', u'/srv/node/bcache11/objects/250/005', u'/srv/node/bcache11/objects/250/006', u'/srv/node/bcache11/objects/250/007', u'/srv/node/bcache11/objects/250/008', u'/srv/node/bcache11/objects/250/c5d', u'/srv/node/bcache11/objects/250/009', u'/srv/node/bcache11/objects/250/00a', u'/srv/node/bcache11/objects/250/00b', u'/srv/node/bcache11/objects/250/00c', u'/srv/node/bcache11/objects/250/00d', u'/srv/node/bcache11/objects/250/00e', u'/srv/node/bcache11/objects/250/00f', u'/srv/node/bcache11/objects/250/010', u'/srv/node/bcache11/objects/250/011', u'/srv/node/bcache11/objects/250/012', u'/srv/node/bcache11/objects/250/013', u'/srv/node/bcache11/objects/250/014', u'/srv/node/bcache11/objects/250/015', u'/srv/node/bcache11/objects/250/016', u'/srv/node/bcache11/objects/250/017', u'/srv/node/bcache11/objects/250/018', u'/srv/node/bcache11/objects/250/019', u'/srv/node/bcache11/objects/250/01a', u'/srv/node/bcache11/objects/250/01b', u'/srv/node/bcache11/objects/250/01c', u'/srv/node/bcache11/objects/250/01d', u'/srv/node/bcache11/objects/250/01e', u'/srv/node/bcache11/objects/250/01f', u'/srv/node/bcache11/objects/250/020', u'/srv/node/bcache11/objects/250/021', u'/srv/node/bcache11/objects/250/022', u'/srv/node/bcache11/objects/250/023', u'/srv/node/bcache11/objects/250/024', u'/srv/node/bcache11/objects/250/025', u'/srv/node/bcache11/objects/250/026', u'/srv/node/bcache11/objects/250/027', u'/srv/node/bcache11/objects/250/028', u'/srv/node/bcache11/objects/250/029', u'/srv/node/bcache11/objects/250/02a', u'/srv/node/bcache11/objects/250/02b', u'/srv/node/bcache11/objects/250/02c', u'/srv/node/bcache11/objects/250/02d', u'/srv/node/bcache11/objects/250/02e', u'/srv/node/bcache11/objects/250/02f', u'/srv/node/bcache11/objects/250/030', u'/srv/node/bcache11/objects/250/031', u'/srv/node/bcache11/objects/250/032', u'/srv/node/bcache11/objects/250/033', u'/srv/node/bcache11/objects/250/034', u'/srv/node/bcache11/objects/250/035', u'/srv/node/bcache11/objects/250/036', u'/srv/node/bcache11/objects/250/037', u'/srv/node/bcache11/objects/250/038', u'/srv/node/bcache11/objects/250/289', u'/srv/node/bcache11/objects/250/039', u'/srv/node/bcache11/objects/250/03a', u'/srv/node/bcache11/objects/250/03b', u'/srv/node/bcache11/objects/250/03c', u'/srv/node/bcache11/objects/250/03d', u'/srv/node/bcache11/objects/250/03e', u'/srv/node/bcache11/objects/250/03f', u'/srv/node/bcache11/objects/250/040', u'/srv/node/bcache11/objects/250/041', u'/srv/node/bcache11/objects/250/042', u'/srv/node/bcache11/objects/250/043', u'/srv/node/bcache11/objects/250/044', u'/srv/node/bcache11/objects/250/045', u'/srv/node/bcache11/objects/250/046', u'/srv/node/bcache11/objects/250/047', u'/srv/node/bcache11/objects/250/048', u'/srv/node/bcache11/objects/250/049', u'/srv/node/bcache11/objects/250/04a', u'/srv/node/bcache11/objects/250/04b', u'/srv/node/bcache11/objects/250/04c', u'/srv/node/bcache11/objects/250/04d', u'/srv/node/bcache11/objects/250/04e', u'/srv/node/bcache11/objects/250/04f', u'/srv/node/bcache11/objects/250/050', u'/srv/node/bcache11/objects/250/051', u'/srv/node/bcache11/objects/250/052', u'/srv/node/bcache11/objects/250/053', u'/srv/node/bcache11/objects/250/054', u'/srv/node/bcache11/objects/250/055', u'/srv/node/bcache11/objects/250/056', u'/srv/node/bcache11/objects/250/057', u'/srv/node/bcache11/objects/250/058', u'/srv/node/bcache11/objects/250/059', u'/srv/node/bcache11/objects/250/05a', u'/srv/node/bcache11/objects/250/05b', u'/srv/node/bcache11/objects/250/05c', u'/srv/node/bcache11/objects/250/05d', u'/srv/node/bcache11/objects/250/05e', u'/srv/node/bcache11/objects/250/05f', u'/srv/node/bcache11/objects/250/060', u'/srv/node/bcache11/objects/250/061', u'/srv/node/bcache11/objects/250/062', u'/srv/node/bcache11/objects/250/063', u'/srv/node/bcache11/objects/250/064', u'/srv/node/bcache11/objects/250/065', u'/srv/node/bcache11/objects/250/066', u'/srv/node/bcache11/objects/250/067', u'/srv/node/bcache11/objects/250/068', u'/srv/node/bcache11/objects/250/069', u'/srv/node/bcache11/objects/250/06a', u'/srv/node/bcache11/objects/250/06b', u'/srv/node/bcache11/objects/250/06c', u'/srv/node/bcache11/objects/250/06d', u'/srv/node/bcache11/objects/250/06e', u'/srv/node/bcache11/objects/250/06f', u'/srv/node/bcache11/objects/250/070', u'/srv/node/bcache11/objects/250/071', u'/srv/node/bcache11/objects/250/072', u'/srv/node/bcache11/objects/250/073', u'/srv/node/bcache11/objects/250/074', u'/srv/node/bcache11/objects/250/075', u'/srv/node/bcache11/objects/250/076', u'/srv/node/bcache11/objects/250/077', u'/srv/node/bcache11/objects/250/078', u'/srv/node/bcache11/objects/250/079', u'/srv/node/bcache11/objects/250/07a', u'/srv/node/bcache11/objects/250/07b', u'/srv/node/bcache11/objects/250/07c', u'/srv/node/bcache11/objects/250/07d', u'/srv/node/bcache11/objects/250/07e', u'/srv/node/bcache11/objects/250/07f', u'/srv/node/bcache11/objects/250/080', u'/srv/node/bcache11/objects/250/081', u'/srv/node/bcache11/objects/250/082', u'/srv/node/bcache11/objects/250/083', u'/srv/node/bcache11/objects/250/084', u'/srv/node/bcache11/objects/250/085', u'/srv/node/bcache11/objects/250/086', u'/srv/node/bcache11/objects/250/087', u'/srv/node/bcache11/objects/250/088', u'/srv/node/bcache11/objects/250/089', u'/srv/node/bcache11/objects/250/08a', u'/srv/node/bcache11/objects/250/08b', u'/srv/node/bcache11/objects/250/08c', u'/srv/node/bcache11/objects/250/08d', u'/srv/node/bcache11/objects/250/08e', u'/srv/node/bcache11/objects/250/08f', u'/srv/node/bcache11/objects/250/090', u'/srv/node/bcache11/objects/250/091', u'/srv/node/bcache11/objects/250/092', u'/srv/node/bcache11/objects/250/093', u'/srv/node/bcache11/objects/250/094', u'/srv/node/bcache11/objects/250/095', u'/srv/node/bcache11/objects/250/096', u'/srv/node/bcache11/objects/250/097', u'/srv/node/bcache11/objects/250/098', u'/srv/node/bcache11/objects/250/099', u'/srv/node/bcache11/objects/250/09a', u'/srv/node/bcache11/objects/250/09b', u'/srv/node/bcache11/objects/250/09c', u'/srv/node/bcache11/objects/250/09d', u'/srv/node/bcache11/objects/250/09e', u'/srv/node/bcache11/objects/250/09f', u'/srv/node/bcache11/objects/250/0a0', u'/srv/node/bcache11/objects/250/0a1', u'/srv/node/bcache11/objects/250/0a2', u'/srv/node/bcache11/objects/250/0a3', u'/srv/node/bcache11/objects/250/0a4', u'/srv/node/bcache11/objects/250/0a5', u'/srv/node/bcache11/objects/250/0a6', u'/srv/node/bcache11/objects/250/0a7', u'/srv/node/bcache11/objects/250/0a8', u'/srv/node/bcache11/objects/250/0a9', u'/srv/node/bcache11/objects/250/0aa', u'/srv/node/bcache11/objects/250/0ab', u'/srv/node/bcache11/objects/250/0ac', u'/srv/node/bcache11/objects/250/0ad', u'/srv/node/bcache11/objects/250/0ae', u'/srv/node/bcache11/objects/250/0af', u'/srv/node/bcache11/objects/250/0b0', u'/srv/node/bcache11/objects/250/0b1', u'/srv/node/bcache11/objects/250/0b2', u'/srv/node/bcache11/objects/250/0b3', u'/srv/node/bcache11/objects/250/0b4', u'/srv/node/bcache11/objects/250/0b5', u'/srv/node/bcache11/objects/250/0b6', u'/srv/node/bcache11/objects/250/0b7', u'/srv/node/bcache11/objects/250/0b8', u'/srv/node/bcache11/objects/250/0b9', u'/srv/node/bcache11/objects/250/0ba', u'/srv/node/bcache11/objects/250/0bb', u'/srv/node/bcache11/objects/250/0bc', u'/srv/node/bcache11/objects/250/0bd', u'/srv/node/bcache11/objects/250/0be', u'/srv/node/bcache11/objects/250/0bf', u'/srv/node/bcache11/objects/250/0c0', u'/srv/node/bcache11/objects/250/0c1', u'/srv/node/bcache11/objects/250/0c2', u'/srv/node/bcache11/objects/250/0c3', u'/srv/node/bcache11/objects/250/0c4', u'/srv/node/bcache11/objects/250/0c5', u'/srv/node/bcache11/objects/250/0c6', u
/var/log/syslog.7.gz:May 11 06:05:02 myhost-cs-011 object-replicator: STDERR: Traceback (most recent call last):
/var/log/syslog.7.gz:May 11 06:05:02 myhost-cs-011 object-replicator: STDERR: File "/usr/lib/python2.7/logging/handlers.py", line 860, in emit
/var/log/syslog.7.gz:May 11 06:05:02 myhost-cs-011 object-replicator: STDERR: self.socket.send(msg)
/var/log/syslog.7.gz:May 11 06:05:02 myhost-cs-011 object-replicator: STDERR: error: [Errno 105] No buffer space available
/var/log/syslog.7.gz:May 11 06:05:02 myhost-cs-011 object-replicator: STDERR: Logged from file replicator.py, line 185
/var/log/syslog.7.gz:May 11 06:07:05 myhost-cs-011 object-replicator: 118/118 (100.00%) partitions replicated in 3300.93s (0.04/sec, 0s remaining)
/var/log/syslog.7.gz:May 11 06:07:05 myhost-cs-011 object-replicator: 0 successes, 3865 failures

Somehow the kill signal doesn't appear to effectively end this process. this host has 28 such rsync processes stuck.

Full logs available at:
https://pastebin.canonical.com/188526/
https://pastebin.canonical.com/188527/

Trusty/Mitaka

ubuntu@myhost-cs-011:~$ dpkg -l|grep swift-object
ii swift-object 2.7.0-0ubuntu2~cloud0 all distributed virtual object store - object server
ubuntu@myhost-cs-011:~$ swift-recon -r
===============================================================================
--> Starting reconnaissance on 9 hosts
===============================================================================
[2017-05-17 21:18:05] Checking on replication
[replication_failure] low: 180, high: 3689, avg: 569.9, total: 5129, Failed: 0.0%, no_result: 0, reported: 9
[replication_success] low: 0, high: 7, avg: 3.2, total: 29, Failed: 0.0%, no_result: 0, reported: 9
[replication_time] low: 30, high: 90, avg: 61.5, total: 553, Failed: 0.0%, no_result: 0, reported: 9
[replication_attempted] low: 28, high: 118, avg: 41.6, total: 374, Failed: 0.0%, no_result: 0, reported: 9
Oldest completion was 2017-05-09 21:29:09 (7 days ago) by 10.101.140.59:6000.
Most recent completion was 2017-05-17 21:00:25 (17 minutes ago) by 10.101.140.54:6000.
===============================================================================
ubuntu@myhost-cs-011:~$ uname -a
Linux myhost-cs-011 4.4.0-51-generic #72~14.04.1-Ubuntu SMP Thu Nov 24 19:22:30 UTC 2016 x86_64 x86_64 x86_64 GNU/Linux

ubuntu@myhost-cs-011:~$ cat /etc/os-release
NAME="Ubuntu"
VERSION="14.04.5 LTS, Trusty Tahr"
ID=ubuntu
ID_LIKE=debian
PRETTY_NAME="Ubuntu 14.04.5 LTS"
VERSION_ID="14.04"

I believe charm version is 17.02

I see there's a swift 2.7.1 available for trusty. Would this have a fix for this issue?

Drew Freiberger (afreiberger) wrote :

FYI, After updating the above server to swift 2.7.1, we are still seeing the exact same issues.

Drew Freiberger (afreiberger) wrote :

I believe this issue was the result of hanging non-interruptable storage hardware errors.

To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers