awight@tin:/srv/deployment/ores/deploy$ scap deploy -v -f -l "ores1001*" "(non-production) Update ORES on new cluster"
11:23:51 INFO     - <Command u'/usr/bin/git describe --always'>: starting process
11:23:51 INFO     - <Command u'/usr/bin/git describe --always', pid 4191>: process started
11:23:51 INFO     - <Command u'/usr/bin/git describe --always', pid 4191>: process completed
11:23:51 INFO     - <Command u'/usr/bin/git describe --always', pid 4191>: process completed
11:23:51 INFO     - <Command u'/usr/bin/git describe --always', pid 4191>: process completed
11:23:51 <Command u'/usr/bin/git show -s --format=%ct b67bba77acb7c0ffc678201c9f3f54f198da6650'>: starting process
11:23:51 <Command u'/usr/bin/git show -s --format=%%ct b67bba77acb7c0ffc678201c9f3f54f198da6650'>.<Process 4196 ['/usr/bin/git', 'show', '-s', '--format=%ct', 'b67bba77acb7c0ffc678201c9f3f54f198da6650']>: started process
11:23:51 <Command u'/usr/bin/git show -s --format=%ct b67bba77acb7c0ffc678201c9f3f54f198da6650', pid 4196>: process started
11:23:51 <Command u'/usr/bin/git show -s --format=%%ct b67bba77acb7c0ffc678201c9f3f54f198da6650'>.<Process 4196 ['/usr/bin/git', 'show', '-s', '--format=%ct', 'b67bba77acb7c0ffc678201c9f3f54f198da6650']>: acquiring wait lock to wait for completion
11:23:51 <Command u'/usr/bin/git show -s --format=%%ct b67bba77acb7c0ffc678201c9f3f54f198da6650'>.<Process 4196 ['/usr/bin/git', 'show', '-s', '--format=%ct', 'b67bba77acb7c0ffc678201c9f3f54f198da6650']>: got wait lock
11:23:51 <Command u'/usr/bin/git show -s --format=%%ct b67bba77acb7c0ffc678201c9f3f54f198da6650'>.<Process 4196 ['/usr/bin/git', 'show', '-s', '--format=%ct', 'b67bba77acb7c0ffc678201c9f3f54f198da6650']>: exit code not set, waiting on pid
11:23:51 <Command u'/usr/bin/git show -s --format=%%ct b67bba77acb7c0ffc678201c9f3f54f198da6650'>.<Process 4196 ['/usr/bin/git', 'show', '-s', '--format=%ct', 'b67bba77acb7c0ffc678201c9f3f54f198da6650']>: <scap.sh.StreamReader object at 0x7f0b81f00850> ready to be read from
11:23:51 <Command u'/usr/bin/git show -s --format=%%%%ct b67bba77acb7c0ffc678201c9f3f54f198da6650'>.<Process 4196 ['/usr/bin/git', 'show', '-s', '--format=%%ct', 'b67bba77acb7c0ffc678201c9f3f54f198da6650']>.stdout: got chunk size 11: '1513181123\n'
11:23:51 acquiring buffering lock to process chunk (buffering: 1)
11:23:51 got buffering lock to process chunk (buffering: 1)
11:23:51 released buffering lock for processing chunk (buffering: 1)
11:23:51 <Command u'/usr/bin/git show -s --format=%%%%ct b67bba77acb7c0ffc678201c9f3f54f198da6650'>.<Process 4196 ['/usr/bin/git', 'show', '-s', '--format=%%ct', 'b67bba77acb7c0ffc678201c9f3f54f198da6650']>.stdout: putting chunk onto pipe: '1513181123\n'
11:23:51 <Command u'/usr/bin/git show -s --format=%%ct b67bba77acb7c0ffc678201c9f3f54f198da6650'>.<Process 4196 ['/usr/bin/git', 'show', '-s', '--format=%ct', 'b67bba77acb7c0ffc678201c9f3f54f198da6650']>: <scap.sh.StreamReader object at 0x7f0b81f00fd0> ready to be read from
11:23:51 got no chunk, done reading
11:23:51 <Command u'/usr/bin/git show -s --format=%%ct b67bba77acb7c0ffc678201c9f3f54f198da6650'>.<Process 4196 ['/usr/bin/git', 'show', '-s', '--format=%ct', 'b67bba77acb7c0ffc678201c9f3f54f198da6650']>: <scap.sh.StreamReader object at 0x7f0b81f00850> ready to be read from
11:23:51 <Command u'/usr/bin/git show -s --format=%%%%ct b67bba77acb7c0ffc678201c9f3f54f198da6650'>.<Process 4196 ['/usr/bin/git', 'show', '-s', '--format=%%ct', 'b67bba77acb7c0ffc678201c9f3f54f198da6650']>.stdout: got no chunk, done reading
11:23:51 acquiring buffering lock for flushing buffer
11:23:51 got buffering lock for flushing buffer
11:23:51 released buffering lock for flushing buffer
11:23:51 <Command u'/usr/bin/git show -s --format=%%%%ct b67bba77acb7c0ffc678201c9f3f54f198da6650'>.<Process 4196 ['/usr/bin/git', 'show', '-s', '--format=%%ct', 'b67bba77acb7c0ffc678201c9f3f54f198da6650']>.stdout: got chunk size 0 to flush: ''
11:23:51 acquiring buffering lock for flushing buffer
11:23:51 got buffering lock for flushing buffer
11:23:51 released buffering lock for flushing buffer
11:23:51 got chunk size 0 to flush: ''
11:23:51 <Command u'/usr/bin/git show -s --format=%ct b67bba77acb7c0ffc678201c9f3f54f198da6650', pid 4196>: process completed
11:23:51 <Command u'/usr/bin/git show -s --format=%ct b67bba77acb7c0ffc678201c9f3f54f198da6650', pid 4196>: process completed
11:23:51 <Command u'/usr/bin/git show -s --format=%ct b67bba77acb7c0ffc678201c9f3f54f198da6650', pid 4196>: process completed
11:23:51 <Command u'/usr/bin/git ls-remote --get-url'>: starting process
11:23:51 <Command u'/usr/bin/git ls-remote --get-url'>.<Process 4200 ['/usr/bin/git', 'ls-remote', '--get-url']>: started process
11:23:51 <Command u'/usr/bin/git ls-remote --get-url', pid 4200>: process started
11:23:51 <Command u'/usr/bin/git ls-remote --get-url'>.<Process 4200 ['/usr/bin/git', 'ls-remote', '--get-url']>: acquiring wait lock to wait for completion
11:23:51 <Command u'/usr/bin/git ls-remote --get-url'>.<Process 4200 ['/usr/bin/git', 'ls-remote', '--get-url']>: got wait lock
11:23:51 <Command u'/usr/bin/git ls-remote --get-url'>.<Process 4200 ['/usr/bin/git', 'ls-remote', '--get-url']>: exit code not set, waiting on pid
11:23:51 <Command u'/usr/bin/git ls-remote --get-url'>.<Process 4200 ['/usr/bin/git', 'ls-remote', '--get-url']>: <scap.sh.StreamReader object at 0x7f0b81ef6d90> ready to be read from
11:23:51 <Command u'/usr/bin/git ls-remote --get-url'>.<Process 4200 ['/usr/bin/git', 'ls-remote', '--get-url']>.stdout: got chunk size 68: 'https://gerrit.wikimedia.org/r'
11:23:51 acquiring buffering lock to process chunk (buffering: 1)
11:23:51 got buffering lock to process chunk (buffering: 1)
11:23:51 released buffering lock for processing chunk (buffering: 1)
11:23:51 <Command u'/usr/bin/git ls-remote --get-url'>.<Process 4200 ['/usr/bin/git', 'ls-remote', '--get-url']>.stdout: putting chunk onto pipe: 'https://gerrit.wikimedia.org/r'
11:23:51 <Command u'/usr/bin/git ls-remote --get-url'>.<Process 4200 ['/usr/bin/git', 'ls-remote', '--get-url']>: <scap.sh.StreamReader object at 0x7f0b81f17590> ready to be read from
11:23:51 got no chunk, done reading
11:23:51 <Command u'/usr/bin/git ls-remote --get-url'>.<Process 4200 ['/usr/bin/git', 'ls-remote', '--get-url']>: <scap.sh.StreamReader object at 0x7f0b81ef6d90> ready to be read from
11:23:51 <Command u'/usr/bin/git ls-remote --get-url'>.<Process 4200 ['/usr/bin/git', 'ls-remote', '--get-url']>.stdout: got no chunk, done reading
11:23:51 acquiring buffering lock for flushing buffer
11:23:51 got buffering lock for flushing buffer
11:23:51 released buffering lock for flushing buffer
11:23:51 <Command u'/usr/bin/git ls-remote --get-url'>.<Process 4200 ['/usr/bin/git', 'ls-remote', '--get-url']>.stdout: got chunk size 0 to flush: ''
11:23:51 acquiring buffering lock for flushing buffer
11:23:51 got buffering lock for flushing buffer
11:23:51 released buffering lock for flushing buffer
11:23:51 got chunk size 0 to flush: ''
11:23:51 <Command u'/usr/bin/git ls-remote --get-url', pid 4200>: process completed
11:23:51 <Command u'/usr/bin/git ls-remote --get-url', pid 4200>: process completed
11:23:51 <Command u'/usr/bin/git ls-remote --get-url', pid 4200>: process completed
11:23:51 Started deploy [ores/deploy@b67bba7]
11:23:51 <Command u'/usr/bin/git tag --list scap/sync/2017-12-14/*'>: starting process
11:23:51 <Command u'/usr/bin/git tag --list scap/sync/2017-12-14/*'>.<Process 4204 ['/usr/bin/git', 'tag', '--list', 'scap/sync/2017-12-14/*']>: started process
11:23:51 <Command u'/usr/bin/git tag --list scap/sync/2017-12-14/*', pid 4204>: process started
11:23:51 <Command u'/usr/bin/git tag --list scap/sync/2017-12-14/*'>.<Process 4204 ['/usr/bin/git', 'tag', '--list', 'scap/sync/2017-12-14/*']>: acquiring wait lock to wait for completion
11:23:51 <Command u'/usr/bin/git tag --list scap/sync/2017-12-14/*'>.<Process 4204 ['/usr/bin/git', 'tag', '--list', 'scap/sync/2017-12-14/*']>: got wait lock
11:23:51 <Command u'/usr/bin/git tag --list scap/sync/2017-12-14/*'>.<Process 4204 ['/usr/bin/git', 'tag', '--list', 'scap/sync/2017-12-14/*']>: exit code not set, waiting on pid
11:23:51 <Command u'/usr/bin/git tag --list scap/sync/2017-12-14/*'>.<Process 4204 ['/usr/bin/git', 'tag', '--list', 'scap/sync/2017-12-14/*']>: <scap.sh.StreamReader object at 0x7f0b8125f090> ready to be read from
11:23:51 <Command u'/usr/bin/git tag --list scap/sync/2017-12-14/*'>.<Process 4204 ['/usr/bin/git', 'tag', '--list', 'scap/sync/2017-12-14/*']>.stdout: got chunk size 104: 'scap/sync/2017-12-14/0001\nscap'
11:23:51 acquiring buffering lock to process chunk (buffering: 1)
11:23:51 got buffering lock to process chunk (buffering: 1)
11:23:51 released buffering lock for processing chunk (buffering: 1)
11:23:51 <Command u'/usr/bin/git tag --list scap/sync/2017-12-14/*'>.<Process 4204 ['/usr/bin/git', 'tag', '--list', 'scap/sync/2017-12-14/*']>.stdout: putting chunk onto pipe: 'scap/sync/2017-12-14/0001\n'
11:23:51 <Command u'/usr/bin/git tag --list scap/sync/2017-12-14/*'>.<Process 4204 ['/usr/bin/git', 'tag', '--list', 'scap/sync/2017-12-14/*']>.stdout: putting chunk onto pipe: 'scap/sync/2017-12-14/0002\n'
11:23:51 <Command u'/usr/bin/git tag --list scap/sync/2017-12-14/*'>.<Process 4204 ['/usr/bin/git', 'tag', '--list', 'scap/sync/2017-12-14/*']>.stdout: putting chunk onto pipe: 'scap/sync/2017-12-14/0003\n'
11:23:51 <Command u'/usr/bin/git tag --list scap/sync/2017-12-14/*'>.<Process 4204 ['/usr/bin/git', 'tag', '--list', 'scap/sync/2017-12-14/*']>.stdout: putting chunk onto pipe: 'scap/sync/2017-12-14/0004\n'
11:23:51 <Command u'/usr/bin/git tag --list scap/sync/2017-12-14/*'>.<Process 4204 ['/usr/bin/git', 'tag', '--list', 'scap/sync/2017-12-14/*']>: <scap.sh.StreamReader object at 0x7f0b8125f090> ready to be read from
11:23:51 <Command u'/usr/bin/git tag --list scap/sync/2017-12-14/*'>.<Process 4204 ['/usr/bin/git', 'tag', '--list', 'scap/sync/2017-12-14/*']>.stdout: got no chunk, done reading
11:23:51 <Command u'/usr/bin/git tag --list scap/sync/2017-12-14/*'>.<Process 4204 ['/usr/bin/git', 'tag', '--list', 'scap/sync/2017-12-14/*']>: <scap.sh.StreamReader object at 0x7f0b8125f1d0> ready to be read from
11:23:51 got no chunk, done reading
11:23:51 acquiring buffering lock for flushing buffer
11:23:51 got buffering lock for flushing buffer
11:23:51 released buffering lock for flushing buffer
11:23:51 <Command u'/usr/bin/git tag --list scap/sync/2017-12-14/*'>.<Process 4204 ['/usr/bin/git', 'tag', '--list', 'scap/sync/2017-12-14/*']>.stdout: got chunk size 0 to flush: ''
11:23:51 acquiring buffering lock for flushing buffer
11:23:51 got buffering lock for flushing buffer
11:23:51 released buffering lock for flushing buffer
11:23:51 got chunk size 0 to flush: ''
11:23:51 <Command u'/usr/bin/git tag --list scap/sync/2017-12-14/*', pid 4204>: process completed
11:23:51 <Command u'/usr/bin/git tag --list scap/sync/2017-12-14/*', pid 4204>: process completed
11:23:51 <Command u'/usr/bin/git tag --list scap/sync/2017-12-14/*', pid 4204>: process completed
11:23:51 <Command u'/usr/bin/git rev-parse --verify HEAD'>: starting process
11:23:51 <Command u'/usr/bin/git rev-parse --verify HEAD'>.<Process 4208 ['/usr/bin/git', 'rev-parse', '--verify', 'HEAD']>: started process
11:23:51 <Command u'/usr/bin/git rev-parse --verify HEAD', pid 4208>: process started
11:23:51 <Command u'/usr/bin/git rev-parse --verify HEAD'>.<Process 4208 ['/usr/bin/git', 'rev-parse', '--verify', 'HEAD']>: acquiring wait lock to wait for completion
11:23:51 <Command u'/usr/bin/git rev-parse --verify HEAD'>.<Process 4208 ['/usr/bin/git', 'rev-parse', '--verify', 'HEAD']>: got wait lock
11:23:51 <Command u'/usr/bin/git rev-parse --verify HEAD'>.<Process 4208 ['/usr/bin/git', 'rev-parse', '--verify', 'HEAD']>: exit code not set, waiting on pid
11:23:51 <Command u'/usr/bin/git rev-parse --verify HEAD'>.<Process 4208 ['/usr/bin/git', 'rev-parse', '--verify', 'HEAD']>: <scap.sh.StreamReader object at 0x7f0b81f17850> ready to be read from
11:23:51 <Command u'/usr/bin/git rev-parse --verify HEAD'>.<Process 4208 ['/usr/bin/git', 'rev-parse', '--verify', 'HEAD']>.stdout: got chunk size 41: 'b67bba77acb7c0ffc678201c9f3f54'
11:23:51 acquiring buffering lock to process chunk (buffering: 1)
11:23:51 got buffering lock to process chunk (buffering: 1)
11:23:51 released buffering lock for processing chunk (buffering: 1)
11:23:51 <Command u'/usr/bin/git rev-parse --verify HEAD'>.<Process 4208 ['/usr/bin/git', 'rev-parse', '--verify', 'HEAD']>.stdout: putting chunk onto pipe: 'b67bba77acb7c0ffc678201c9f3f54'
11:23:51 <Command u'/usr/bin/git rev-parse --verify HEAD'>.<Process 4208 ['/usr/bin/git', 'rev-parse', '--verify', 'HEAD']>: <scap.sh.StreamReader object at 0x7f0b81f17850> ready to be read from
11:23:51 <Command u'/usr/bin/git rev-parse --verify HEAD'>.<Process 4208 ['/usr/bin/git', 'rev-parse', '--verify', 'HEAD']>.stdout: got no chunk, done reading
11:23:51 <Command u'/usr/bin/git rev-parse --verify HEAD'>.<Process 4208 ['/usr/bin/git', 'rev-parse', '--verify', 'HEAD']>: <scap.sh.StreamReader object at 0x7f0b81f17750> ready to be read from
11:23:51 got no chunk, done reading
11:23:51 acquiring buffering lock for flushing buffer
11:23:51 got buffering lock for flushing buffer
11:23:51 released buffering lock for flushing buffer
11:23:51 <Command u'/usr/bin/git rev-parse --verify HEAD'>.<Process 4208 ['/usr/bin/git', 'rev-parse', '--verify', 'HEAD']>.stdout: got chunk size 0 to flush: ''
11:23:51 acquiring buffering lock for flushing buffer
11:23:51 got buffering lock for flushing buffer
11:23:51 released buffering lock for flushing buffer
11:23:51 got chunk size 0 to flush: ''
11:23:51 <Command u'/usr/bin/git rev-parse --verify HEAD', pid 4208>: process completed
11:23:51 <Command u'/usr/bin/git rev-parse --verify HEAD', pid 4208>: process completed
11:23:51 <Command u'/usr/bin/git rev-parse --verify HEAD', pid 4208>: process completed
11:23:51 Deploying Rev: b67bba77acb7c0ffc678201c9f3f54f198da6650
11:23:51 Update DEPLOY_HEAD
11:23:51 Creating /srv/deployment/ores/deploy/.git/DEPLOY_HEAD
11:23:51 <Command u'/usr/bin/git for-each-ref --sort=taggerdate --format=%(refname) refs/tags'>: starting process
11:23:51 <Command u'/usr/bin/git for-each-ref --sort=taggerdate --format=%%(refname) refs/tags'>.<Process 4214 ['/usr/bin/git', 'for-each-ref', '--sort=taggerdate', '--format=%(refname)', 'refs/tags']>: started process
11:23:51 <Command u'/usr/bin/git for-each-ref --sort=taggerdate --format=%(refname) refs/tags', pid 4214>: process started
11:23:51 <Command u'/usr/bin/git for-each-ref --sort=taggerdate --format=%%(refname) refs/tags'>.<Process 4214 ['/usr/bin/git', 'for-each-ref', '--sort=taggerdate', '--format=%(refname)', 'refs/tags']>: acquiring wait lock to wait for completion
11:23:51 <Command u'/usr/bin/git for-each-ref --sort=taggerdate --format=%%(refname) refs/tags'>.<Process 4214 ['/usr/bin/git', 'for-each-ref', '--sort=taggerdate', '--format=%(refname)', 'refs/tags']>: got wait lock
11:23:51 <Command u'/usr/bin/git for-each-ref --sort=taggerdate --format=%%(refname) refs/tags'>.<Process 4214 ['/usr/bin/git', 'for-each-ref', '--sort=taggerdate', '--format=%(refname)', 'refs/tags']>: exit code not set, waiting on pid
11:23:51 <Command u'/usr/bin/git for-each-ref --sort=taggerdate --format=%%(refname) refs/tags'>.<Process 4214 ['/usr/bin/git', 'for-each-ref', '--sort=taggerdate', '--format=%(refname)', 'refs/tags']>: <scap.sh.StreamReader object at 0x7f0b8125f8d0> ready to be read from
11:23:51 <Command u'/usr/bin/git for-each-ref --sort=taggerdate --format=%%%%(refname) refs/tags'>.<Process 4214 ['/usr/bin/git', 'for-each-ref', '--sort=taggerdate', '--format=%%(refname)', 'refs/tags']>.stdout: got chunk size 756: 'refs/tags/scap/sync/2017-12-05'
11:23:51 acquiring buffering lock to process chunk (buffering: 1)
11:23:51 got buffering lock to process chunk (buffering: 1)
11:23:51 released buffering lock for processing chunk (buffering: 1)
11:23:51 <Command u'/usr/bin/git for-each-ref --sort=taggerdate --format=%%%%(refname) refs/tags'>.<Process 4214 ['/usr/bin/git', 'for-each-ref', '--sort=taggerdate', '--format=%%(refname)', 'refs/tags']>.stdout: putting chunk onto pipe: 'refs/tags/scap/sync/2017-12-05'
11:23:51 <Command u'/usr/bin/git for-each-ref --sort=taggerdate --format=%%%%(refname) refs/tags'>.<Process 4214 ['/usr/bin/git', 'for-each-ref', '--sort=taggerdate', '--format=%%(refname)', 'refs/tags']>.stdout: putting chunk onto pipe: 'refs/tags/scap/sync/2017-12-09'
11:23:51 <Command u'/usr/bin/git for-each-ref --sort=taggerdate --format=%%%%(refname) refs/tags'>.<Process 4214 ['/usr/bin/git', 'for-each-ref', '--sort=taggerdate', '--format=%%(refname)', 'refs/tags']>.stdout: putting chunk onto pipe: 'refs/tags/scap/sync/2017-12-09'
11:23:51 <Command u'/usr/bin/git for-each-ref --sort=taggerdate --format=%%%%(refname) refs/tags'>.<Process 4214 ['/usr/bin/git', 'for-each-ref', '--sort=taggerdate', '--format=%%(refname)', 'refs/tags']>.stdout: putting chunk onto pipe: 'refs/tags/scap/sync/2017-12-09'
11:23:51 <Command u'/usr/bin/git for-each-ref --sort=taggerdate --format=%%%%(refname) refs/tags'>.<Process 4214 ['/usr/bin/git', 'for-each-ref', '--sort=taggerdate', '--format=%%(refname)', 'refs/tags']>.stdout: putting chunk onto pipe: 'refs/tags/scap/sync/2017-12-09'
11:23:51 <Command u'/usr/bin/git for-each-ref --sort=taggerdate --format=%%%%(refname) refs/tags'>.<Process 4214 ['/usr/bin/git', 'for-each-ref', '--sort=taggerdate', '--format=%%(refname)', 'refs/tags']>.stdout: putting chunk onto pipe: 'refs/tags/scap/sync/2017-12-11'
11:23:51 <Command u'/usr/bin/git for-each-ref --sort=taggerdate --format=%%%%(refname) refs/tags'>.<Process 4214 ['/usr/bin/git', 'for-each-ref', '--sort=taggerdate', '--format=%%(refname)', 'refs/tags']>.stdout: putting chunk onto pipe: 'refs/tags/scap/sync/2017-12-12'
11:23:51 <Command u'/usr/bin/git for-each-ref --sort=taggerdate --format=%%%%(refname) refs/tags'>.<Process 4214 ['/usr/bin/git', 'for-each-ref', '--sort=taggerdate', '--format=%%(refname)', 'refs/tags']>.stdout: putting chunk onto pipe: 'refs/tags/scap/sync/2017-12-12'
11:23:51 <Command u'/usr/bin/git for-each-ref --sort=taggerdate --format=%%%%(refname) refs/tags'>.<Process 4214 ['/usr/bin/git', 'for-each-ref', '--sort=taggerdate', '--format=%%(refname)', 'refs/tags']>.stdout: putting chunk onto pipe: 'refs/tags/scap/sync/2017-12-12'
11:23:51 <Command u'/usr/bin/git for-each-ref --sort=taggerdate --format=%%%%(refname) refs/tags'>.<Process 4214 ['/usr/bin/git', 'for-each-ref', '--sort=taggerdate', '--format=%%(refname)', 'refs/tags']>.stdout: putting chunk onto pipe: 'refs/tags/scap/sync/2017-12-12'
11:23:51 <Command u'/usr/bin/git for-each-ref --sort=taggerdate --format=%%%%(refname) refs/tags'>.<Process 4214 ['/usr/bin/git', 'for-each-ref', '--sort=taggerdate', '--format=%%(refname)', 'refs/tags']>.stdout: putting chunk onto pipe: 'refs/tags/scap/sync/2017-12-12'
11:23:51 <Command u'/usr/bin/git for-each-ref --sort=taggerdate --format=%%%%(refname) refs/tags'>.<Process 4214 ['/usr/bin/git', 'for-each-ref', '--sort=taggerdate', '--format=%%(refname)', 'refs/tags']>.stdout: putting chunk onto pipe: 'refs/tags/scap/sync/2017-12-12'
11:23:51 <Command u'/usr/bin/git for-each-ref --sort=taggerdate --format=%%%%(refname) refs/tags'>.<Process 4214 ['/usr/bin/git', 'for-each-ref', '--sort=taggerdate', '--format=%%(refname)', 'refs/tags']>.stdout: putting chunk onto pipe: 'refs/tags/scap/sync/2017-12-13'
11:23:51 <Command u'/usr/bin/git for-each-ref --sort=taggerdate --format=%%%%(refname) refs/tags'>.<Process 4214 ['/usr/bin/git', 'for-each-ref', '--sort=taggerdate', '--format=%%(refname)', 'refs/tags']>.stdout: putting chunk onto pipe: 'refs/tags/scap/sync/2017-12-13'
11:23:51 <Command u'/usr/bin/git for-each-ref --sort=taggerdate --format=%%%%(refname) refs/tags'>.<Process 4214 ['/usr/bin/git', 'for-each-ref', '--sort=taggerdate', '--format=%%(refname)', 'refs/tags']>.stdout: putting chunk onto pipe: 'refs/tags/scap/sync/2017-12-13'
11:23:51 <Command u'/usr/bin/git for-each-ref --sort=taggerdate --format=%%%%(refname) refs/tags'>.<Process 4214 ['/usr/bin/git', 'for-each-ref', '--sort=taggerdate', '--format=%%(refname)', 'refs/tags']>.stdout: putting chunk onto pipe: 'refs/tags/scap/sync/2017-12-13'
11:23:51 <Command u'/usr/bin/git for-each-ref --sort=taggerdate --format=%%%%(refname) refs/tags'>.<Process 4214 ['/usr/bin/git', 'for-each-ref', '--sort=taggerdate', '--format=%%(refname)', 'refs/tags']>.stdout: putting chunk onto pipe: 'refs/tags/scap/sync/2017-12-14'
11:23:51 <Command u'/usr/bin/git for-each-ref --sort=taggerdate --format=%%%%(refname) refs/tags'>.<Process 4214 ['/usr/bin/git', 'for-each-ref', '--sort=taggerdate', '--format=%%(refname)', 'refs/tags']>.stdout: putting chunk onto pipe: 'refs/tags/scap/sync/2017-12-14'
11:23:51 <Command u'/usr/bin/git for-each-ref --sort=taggerdate --format=%%%%(refname) refs/tags'>.<Process 4214 ['/usr/bin/git', 'for-each-ref', '--sort=taggerdate', '--format=%%(refname)', 'refs/tags']>.stdout: putting chunk onto pipe: 'refs/tags/scap/sync/2017-12-14'
11:23:51 <Command u'/usr/bin/git for-each-ref --sort=taggerdate --format=%%%%(refname) refs/tags'>.<Process 4214 ['/usr/bin/git', 'for-each-ref', '--sort=taggerdate', '--format=%%(refname)', 'refs/tags']>.stdout: putting chunk onto pipe: 'refs/tags/scap/sync/2017-12-14'
11:23:51 <Command u'/usr/bin/git for-each-ref --sort=taggerdate --format=%%%%(refname) refs/tags'>.<Process 4214 ['/usr/bin/git', 'for-each-ref', '--sort=taggerdate', '--format=%%(refname)', 'refs/tags']>.stdout: putting chunk onto pipe: 'refs/tags/scap/sync/2017-12-14'
11:23:51 <Command u'/usr/bin/git for-each-ref --sort=taggerdate --format=%%(refname) refs/tags'>.<Process 4214 ['/usr/bin/git', 'for-each-ref', '--sort=taggerdate', '--format=%(refname)', 'refs/tags']>: <scap.sh.StreamReader object at 0x7f0b8125f8d0> ready to be read from
11:23:51 <Command u'/usr/bin/git for-each-ref --sort=taggerdate --format=%%%%(refname) refs/tags'>.<Process 4214 ['/usr/bin/git', 'for-each-ref', '--sort=taggerdate', '--format=%%(refname)', 'refs/tags']>.stdout: got no chunk, done reading
11:23:51 <Command u'/usr/bin/git for-each-ref --sort=taggerdate --format=%%(refname) refs/tags'>.<Process 4214 ['/usr/bin/git', 'for-each-ref', '--sort=taggerdate', '--format=%(refname)', 'refs/tags']>: <scap.sh.StreamReader object at 0x7f0b8125f950> ready to be read from
11:23:51 got no chunk, done reading
11:23:51 acquiring buffering lock for flushing buffer
11:23:51 got buffering lock for flushing buffer
11:23:51 released buffering lock for flushing buffer
11:23:51 <Command u'/usr/bin/git for-each-ref --sort=taggerdate --format=%%%%(refname) refs/tags'>.<Process 4214 ['/usr/bin/git', 'for-each-ref', '--sort=taggerdate', '--format=%%(refname)', 'refs/tags']>.stdout: got chunk size 0 to flush: ''
11:23:51 acquiring buffering lock for flushing buffer
11:23:51 got buffering lock for flushing buffer
11:23:51 released buffering lock for flushing buffer
11:23:51 got chunk size 0 to flush: ''
11:23:51 <Command u'/usr/bin/git for-each-ref --sort=taggerdate --format=%(refname) refs/tags', pid 4214>: process completed
11:23:51 <Command u'/usr/bin/git for-each-ref --sort=taggerdate --format=%(refname) refs/tags', pid 4214>: process completed
11:23:51 <Command u'/usr/bin/git for-each-ref --sort=taggerdate --format=%(refname) refs/tags', pid 4214>: process completed
11:23:51 <Command u'/usr/bin/git tag -d scap/sync/2017-12-05/0001'>: starting process
11:23:51 <Command u'/usr/bin/git tag -d scap/sync/2017-12-05/0001'>.<Process 4218 ['/usr/bin/git', 'tag', '-d', 'scap/sync/2017-12-05/0001']>: started process
11:23:51 <Command u'/usr/bin/git tag -d scap/sync/2017-12-05/0001', pid 4218>: process started
11:23:51 <Command u'/usr/bin/git tag -d scap/sync/2017-12-05/0001'>.<Process 4218 ['/usr/bin/git', 'tag', '-d', 'scap/sync/2017-12-05/0001']>: acquiring wait lock to wait for completion
11:23:51 <Command u'/usr/bin/git tag -d scap/sync/2017-12-05/0001'>.<Process 4218 ['/usr/bin/git', 'tag', '-d', 'scap/sync/2017-12-05/0001']>: got wait lock
11:23:51 <Command u'/usr/bin/git tag -d scap/sync/2017-12-05/0001'>.<Process 4218 ['/usr/bin/git', 'tag', '-d', 'scap/sync/2017-12-05/0001']>: exit code not set, waiting on pid
11:23:51 <Command u'/usr/bin/git tag -d scap/sync/2017-12-05/0001'>.<Process 4218 ['/usr/bin/git', 'tag', '-d', 'scap/sync/2017-12-05/0001']>: <scap.sh.StreamReader object at 0x7f0b81f00a50> ready to be read from
11:23:51 <Command u'/usr/bin/git tag -d scap/sync/2017-12-05/0001'>.<Process 4218 ['/usr/bin/git', 'tag', '-d', 'scap/sync/2017-12-05/0001']>.stdout: got chunk size 54: "Deleted tag 'scap/sync/2017-12"
11:23:51 acquiring buffering lock to process chunk (buffering: 1)
11:23:51 got buffering lock to process chunk (buffering: 1)
11:23:51 released buffering lock for processing chunk (buffering: 1)
11:23:51 <Command u'/usr/bin/git tag -d scap/sync/2017-12-05/0001'>.<Process 4218 ['/usr/bin/git', 'tag', '-d', 'scap/sync/2017-12-05/0001']>.stdout: putting chunk onto pipe: "Deleted tag 'scap/sync/2017-12"
11:23:51 <Command u'/usr/bin/git tag -d scap/sync/2017-12-05/0001'>.<Process 4218 ['/usr/bin/git', 'tag', '-d', 'scap/sync/2017-12-05/0001']>: <scap.sh.StreamReader object at 0x7f0b81f00a50> ready to be read from
11:23:51 <Command u'/usr/bin/git tag -d scap/sync/2017-12-05/0001'>.<Process 4218 ['/usr/bin/git', 'tag', '-d', 'scap/sync/2017-12-05/0001']>.stdout: got no chunk, done reading
11:23:51 <Command u'/usr/bin/git tag -d scap/sync/2017-12-05/0001'>.<Process 4218 ['/usr/bin/git', 'tag', '-d', 'scap/sync/2017-12-05/0001']>: <scap.sh.StreamReader object at 0x7f0b81f00590> ready to be read from
11:23:51 got no chunk, done reading
11:23:51 acquiring buffering lock for flushing buffer
11:23:51 got buffering lock for flushing buffer
11:23:51 released buffering lock for flushing buffer
11:23:51 <Command u'/usr/bin/git tag -d scap/sync/2017-12-05/0001'>.<Process 4218 ['/usr/bin/git', 'tag', '-d', 'scap/sync/2017-12-05/0001']>.stdout: got chunk size 0 to flush: ''
11:23:51 acquiring buffering lock for flushing buffer
11:23:51 got buffering lock for flushing buffer
11:23:51 released buffering lock for flushing buffer
11:23:51 got chunk size 0 to flush: ''
11:23:51 <Command u'/usr/bin/git tag -d scap/sync/2017-12-05/0001', pid 4218>: process completed
11:23:51 Update server info
11:23:51 <Command u'/usr/bin/git update-server-info'>: starting process
11:23:51 <Command u'/usr/bin/git update-server-info'>.<Process 4222 ['/usr/bin/git', 'update-server-info']>: started process
11:23:51 <Command u'/usr/bin/git update-server-info', pid 4222>: process started
11:23:51 <Command u'/usr/bin/git update-server-info'>.<Process 4222 ['/usr/bin/git', 'update-server-info']>: acquiring wait lock to wait for completion
11:23:51 <Command u'/usr/bin/git update-server-info'>.<Process 4222 ['/usr/bin/git', 'update-server-info']>: got wait lock
11:23:51 <Command u'/usr/bin/git update-server-info'>.<Process 4222 ['/usr/bin/git', 'update-server-info']>: exit code not set, waiting on pid
11:23:51 <Command u'/usr/bin/git update-server-info'>.<Process 4222 ['/usr/bin/git', 'update-server-info']>: <scap.sh.StreamReader object at 0x7f0b8126e910> ready to be read from
11:23:51 <Command u'/usr/bin/git update-server-info'>.<Process 4222 ['/usr/bin/git', 'update-server-info']>.stdout: got no chunk, done reading
11:23:51 <Command u'/usr/bin/git update-server-info'>.<Process 4222 ['/usr/bin/git', 'update-server-info']>: <scap.sh.StreamReader object at 0x7f0b8126ea50> ready to be read from
11:23:51 got no chunk, done reading
11:23:51 acquiring buffering lock for flushing buffer
11:23:51 got buffering lock for flushing buffer
11:23:51 released buffering lock for flushing buffer
11:23:51 <Command u'/usr/bin/git update-server-info'>.<Process 4222 ['/usr/bin/git', 'update-server-info']>.stdout: got chunk size 0 to flush: ''
11:23:51 acquiring buffering lock for flushing buffer
11:23:51 got buffering lock for flushing buffer
11:23:51 released buffering lock for flushing buffer
11:23:51 got chunk size 0 to flush: ''
11:23:51 <Command u'/usr/bin/git update-server-info', pid 4222>: process completed
11:23:51 <Command u'/usr/bin/git submodule foreach --recursive git update-server-info'>: starting process
11:23:51 <Command u'/usr/bin/git submodule foreach --recursive git update-server-info'>.<Process 4226 ['/usr/bin/git', 'submodule', 'foreach', '--recursive', 'git update-server-info']>: started process
11:23:51 <Command u'/usr/bin/git submodule foreach --recursive git update-server-info', pid 4226>: process started
11:23:51 <Command u'/usr/bin/git submodule foreach --recursive git update-server-info'>.<Process 4226 ['/usr/bin/git', 'submodule', 'foreach', '--recursive', 'git update-server-info']>: acquiring wait lock to wait for completion
11:23:51 <Command u'/usr/bin/git submodule foreach --recursive git update-server-info'>.<Process 4226 ['/usr/bin/git', 'submodule', 'foreach', '--recursive', 'git update-server-info']>: got wait lock
11:23:51 <Command u'/usr/bin/git submodule foreach --recursive git update-server-info'>.<Process 4226 ['/usr/bin/git', 'submodule', 'foreach', '--recursive', 'git update-server-info']>: exit code not set, waiting on pid
11:23:51 <Command u'/usr/bin/git submodule foreach --recursive git update-server-info'>.<Process 4226 ['/usr/bin/git', 'submodule', 'foreach', '--recursive', 'git update-server-info']>: <scap.sh.StreamReader object at 0x7f0b8125fc10> ready to be read from
11:23:51 <Command u'/usr/bin/git submodule foreach --recursive git update-server-info'>.<Process 4226 ['/usr/bin/git', 'submodule', 'foreach', '--recursive', 'git update-server-info']>.stdout: got chunk size 35: "Entering 'submodules/draftqual"
11:23:51 acquiring buffering lock to process chunk (buffering: 1)
11:23:51 got buffering lock to process chunk (buffering: 1)
11:23:51 released buffering lock for processing chunk (buffering: 1)
11:23:51 <Command u'/usr/bin/git submodule foreach --recursive git update-server-info'>.<Process 4226 ['/usr/bin/git', 'submodule', 'foreach', '--recursive', 'git update-server-info']>.stdout: putting chunk onto pipe: "Entering 'submodules/draftqual"
11:23:51 <Command u'/usr/bin/git submodule foreach --recursive git update-server-info'>.<Process 4226 ['/usr/bin/git', 'submodule', 'foreach', '--recursive', 'git update-server-info']>: <scap.sh.StreamReader object at 0x7f0b8125fc10> ready to be read from
11:23:51 <Command u'/usr/bin/git submodule foreach --recursive git update-server-info'>.<Process 4226 ['/usr/bin/git', 'submodule', 'foreach', '--recursive', 'git update-server-info']>.stdout: got chunk size 34: "Entering 'submodules/editquali"
11:23:51 acquiring buffering lock to process chunk (buffering: 1)
11:23:51 got buffering lock to process chunk (buffering: 1)
11:23:51 released buffering lock for processing chunk (buffering: 1)
11:23:51 <Command u'/usr/bin/git submodule foreach --recursive git update-server-info'>.<Process 4226 ['/usr/bin/git', 'submodule', 'foreach', '--recursive', 'git update-server-info']>.stdout: putting chunk onto pipe: "Entering 'submodules/editquali"
11:23:51 <Command u'/usr/bin/git submodule foreach --recursive git update-server-info'>.<Process 4226 ['/usr/bin/git', 'submodule', 'foreach', '--recursive', 'git update-server-info']>: <scap.sh.StreamReader object at 0x7f0b8125fc10> ready to be read from
11:23:51 <Command u'/usr/bin/git submodule foreach --recursive git update-server-info'>.<Process 4226 ['/usr/bin/git', 'submodule', 'foreach', '--recursive', 'git update-server-info']>.stdout: got chunk size 27: "Entering 'submodules/ores'\n"
11:23:51 acquiring buffering lock to process chunk (buffering: 1)
11:23:51 got buffering lock to process chunk (buffering: 1)
11:23:51 released buffering lock for processing chunk (buffering: 1)
11:23:51 <Command u'/usr/bin/git submodule foreach --recursive git update-server-info'>.<Process 4226 ['/usr/bin/git', 'submodule', 'foreach', '--recursive', 'git update-server-info']>.stdout: putting chunk onto pipe: "Entering 'submodules/ores'\n"
11:23:51 <Command u'/usr/bin/git submodule foreach --recursive git update-server-info'>.<Process 4226 ['/usr/bin/git', 'submodule', 'foreach', '--recursive', 'git update-server-info']>: <scap.sh.StreamReader object at 0x7f0b8125fc10> ready to be read from
11:23:51 <Command u'/usr/bin/git submodule foreach --recursive git update-server-info'>.<Process 4226 ['/usr/bin/git', 'submodule', 'foreach', '--recursive', 'git update-server-info']>.stdout: got chunk size 29: "Entering 'submodules/wheels'\n"
11:23:51 acquiring buffering lock to process chunk (buffering: 1)
11:23:51 got buffering lock to process chunk (buffering: 1)
11:23:51 released buffering lock for processing chunk (buffering: 1)
11:23:51 <Command u'/usr/bin/git submodule foreach --recursive git update-server-info'>.<Process 4226 ['/usr/bin/git', 'submodule', 'foreach', '--recursive', 'git update-server-info']>.stdout: putting chunk onto pipe: "Entering 'submodules/wheels'\n"
11:23:51 <Command u'/usr/bin/git submodule foreach --recursive git update-server-info'>.<Process 4226 ['/usr/bin/git', 'submodule', 'foreach', '--recursive', 'git update-server-info']>: <scap.sh.StreamReader object at 0x7f0b8125fc10> ready to be read from
11:23:51 <Command u'/usr/bin/git submodule foreach --recursive git update-server-info'>.<Process 4226 ['/usr/bin/git', 'submodule', 'foreach', '--recursive', 'git update-server-info']>.stdout: got chunk size 32: "Entering 'submodules/wikiclass"
11:23:51 acquiring buffering lock to process chunk (buffering: 1)
11:23:51 got buffering lock to process chunk (buffering: 1)
11:23:51 released buffering lock for processing chunk (buffering: 1)
11:23:51 <Command u'/usr/bin/git submodule foreach --recursive git update-server-info'>.<Process 4226 ['/usr/bin/git', 'submodule', 'foreach', '--recursive', 'git update-server-info']>.stdout: putting chunk onto pipe: "Entering 'submodules/wikiclass"
11:23:51 <Command u'/usr/bin/git submodule foreach --recursive git update-server-info'>.<Process 4226 ['/usr/bin/git', 'submodule', 'foreach', '--recursive', 'git update-server-info']>: <scap.sh.StreamReader object at 0x7f0b8125fc10> ready to be read from
11:23:51 <Command u'/usr/bin/git submodule foreach --recursive git update-server-info'>.<Process 4226 ['/usr/bin/git', 'submodule', 'foreach', '--recursive', 'git update-server-info']>.stdout: got no chunk, done reading
11:23:51 <Command u'/usr/bin/git submodule foreach --recursive git update-server-info'>.<Process 4226 ['/usr/bin/git', 'submodule', 'foreach', '--recursive', 'git update-server-info']>: <scap.sh.StreamReader object at 0x7f0b8125ff90> ready to be read from
11:23:51 got no chunk, done reading
11:23:51 acquiring buffering lock for flushing buffer
11:23:51 got buffering lock for flushing buffer
11:23:51 released buffering lock for flushing buffer
11:23:51 <Command u'/usr/bin/git submodule foreach --recursive git update-server-info'>.<Process 4226 ['/usr/bin/git', 'submodule', 'foreach', '--recursive', 'git update-server-info']>.stdout: got chunk size 0 to flush: ''
11:23:51 acquiring buffering lock for flushing buffer
11:23:51 got buffering lock for flushing buffer
11:23:51 released buffering lock for flushing buffer
11:23:51 got chunk size 0 to flush: ''
11:23:51 <Command u'/usr/bin/git submodule foreach --recursive git update-server-info', pid 4226>: process completed
11:23:51 Started deploy [ores/deploy@b67bba7]: (non-production) Update ORES on new cluster
11:23:51 
== CLUSTER ==
:* ores1001.eqiad.wmnet
11:23:51 Running remote deploy cmd ['/usr/bin/scap', 'deploy-local', '-v', '--repo', 'ores/deploy', '--force', '-g', 'cluster', 'fetch', '--refresh-config']
11:23:51 Using key: /etc/keyholder.d/deploy_service.pub
11:23:53 ['/usr/bin/scap', 'deploy-local', '-v', '--repo', 'ores/deploy', '--force', '-g', 'cluster', 'fetch', '--refresh-config'] on ores1001.eqiad.wmnet returned [70]: OpenSSH_6.7p1 Debian-5+deb8u3, OpenSSL 1.0.2m  2 Nov 2017
debug1: Reading configuration data /dev/null
debug1: Connecting to ores1001.eqiad.wmnet [10.64.0.51] port 22.
debug1: Connection established.
debug1: identity file /etc/keyholder.d/deploy_service.pub type 1
debug1: key_load_public: No such file or directory
debug1: identity file /etc/keyholder.d/deploy_service.pub-cert type -1
debug1: Enabling compatibility mode for protocol 2.0
debug1: Local version string SSH-2.0-OpenSSH_6.7p1 Debian-5+deb8u3
debug1: Remote protocol version 2.0, remote software version OpenSSH_6.7p1 Debian-5+deb8u3
debug1: match: OpenSSH_6.7p1 Debian-5+deb8u3 pat OpenSSH* compat 0x04000000
debug1: SSH2_MSG_KEXINIT sent
debug1: SSH2_MSG_KEXINIT received
debug1: kex: server->client aes128-ctr umac-128-etm@openssh.com none
debug1: kex: client->server aes128-ctr umac-128-etm@openssh.com none
debug1: sending SSH2_MSG_KEX_ECDH_INIT
debug1: expecting SSH2_MSG_KEX_ECDH_REPLY
debug1: Server host key: ECDSA 18:71:ca:a4:ae:29:83:c6:46:55:43:56:7a:74:42:7c
debug1: Host 'ores1001.eqiad.wmnet' is known and matches the ECDSA host key.
debug1: Found key in /etc/ssh/ssh_known_hosts:1086
debug1: SSH2_MSG_NEWKEYS sent
debug1: expecting SSH2_MSG_NEWKEYS
debug1: SSH2_MSG_NEWKEYS received
debug1: SSH2_MSG_SERVICE_REQUEST sent
debug1: SSH2_MSG_SERVICE_ACCEPT received
debug1: Authentications that can continue: publickey,keyboard-interactive
debug1: Next authentication method: publickey
debug1: Offering RSA public key: /etc/keyholder.d/deploy_service.pub
debug1: Server accepts key: pkalg ssh-rsa blen 279
debug1: Authentication succeeded (publickey).
Authenticated to ores1001.eqiad.wmnet ([10.64.0.51]:22).
debug1: channel 0: new [client-session]
debug1: Requesting no-more-sessions@openssh.com
debug1: Entering interactive session.
debug1: Sending command: /usr/bin/scap deploy-local -v --repo ores/deploy --force -g cluster fetch --refresh-config
http://tin.eqiad.wmnet/ores/deploy/.git
/srv/deployment/ores/deploy-cache/cache
debug1: client_input_channel_req: channel 0 rtype exit-status reply 0
debug1: client_input_channel_req: channel 0 rtype eow@openssh.com reply 0
debug1: channel 0: free: client-session, nchannels 1
debug1: fd 1 clearing O_NONBLOCK
Transferred: sent 3448, received 162856 bytes, in 2.0 seconds
Bytes per second: sent 1707.3, received 80639.4
debug1: Exit status 70

ores/deploy: fetch stage(s): 100% (ok: 0; fail: 1; left: 0)                     
11:23:53 1 targets had deploy errors
11:23:53 1 targets failed
11:23:53 1 of 1 cluster targets failed, exceeding limit