Following the fix for bug 1453930, I ran some tests in a loop for a while to see if they would do anything interesting when their requests to Launchpad time out. Mostly things seem a lot better, but I noticed this oddity from a push over SSH that encountered a timeout and just left the connection open and apparently stuck from the user's point of view. (This is still much better than the previous situation, though, because the repository isn't left locked in a way that requires administrative intervention to fix.)
The following logs are interleaved from turnip-pack-frontend-ssh.log, turnip-pack-virt.log, and turnip-pack-backend.log.
2019-08-01 13:45:47+0000 [KeepAliveSettingSSHServerTransport,894,10.15.90.3] kex alg, key alg: 'ecdh-sha2-nistp256' 'ssh-rsa'
2019-08-01 13:45:47+0000 [KeepAliveSettingSSHServerTransport,894,10.15.90.3] outgoing: 'aes128-ctr' 'hmac-sha2-256' 'none'
2019-08-01 13:45:47+0000 [KeepAliveSettingSSHServerTransport,894,10.15.90.3] incoming: 'aes128-ctr' 'hmac-sha2-256' 'none'
2019-08-01 13:45:47+0000 [KeepAliveSettingSSHServerTransport,894,10.15.90.3] NEW KEYS
2019-08-01 13:45:47+0000 [KeepAliveSettingSSHServerTransport,894,10.15.90.3] starting service 'ssh-userauth'
2019-08-01 13:45:47+0000 [SSHService 'ssh-userauth' on KeepAliveSettingSSHServerTransport,894,10.15.90.3] 'cjwatson+git-testing' trying auth 'none'
2019-08-01 13:45:47+0000 [SSHService 'ssh-userauth' on KeepAliveSettingSSHServerTransport,894,10.15.90.3] 'cjwatson+git-testing' trying auth 'publickey'
2019-08-01 13:45:47+0000 [-] Starting factory <twisted.web.xmlrpc._QueryFactory instance at 0x7fc78fae43f8>
2019-08-01 13:45:48+0000 [-] Stopping factory <twisted.web.xmlrpc._QueryFactory instance at 0x7fc78fae43f8>
2019-08-01 13:45:48+0000 [SSHService 'ssh-userauth' on KeepAliveSettingSSHServerTransport,894,10.15.90.3] 'cjwatson+git-testing' trying auth 'publickey'
2019-08-01 13:45:48+0000 [SSHService 'ssh-userauth' on KeepAliveSettingSSHServerTransport,894,10.15.90.3] 'cjwatson+git-testing' authenticated with 'publickey'
2019-08-01 13:45:48+0000 [SSHService 'ssh-userauth' on KeepAliveSettingSSHServerTransport,894,10.15.90.3] starting service 'ssh-connection'
2019-08-01 13:45:48+0000 [SSHService 'ssh-connection' on KeepAliveSettingSSHServerTransport,894,10.15.90.3] got channel 'session' request
2019-08-01 13:45:48+0000 [SSHChannel session (0) on SSHService 'ssh-connection' on KeepAliveSettingSSHServerTransport,894,10.15.90.3] channel open
2019-08-01 13:45:48+0000 [SSHChannel session (0) on SSHService 'ssh-connection' on KeepAliveSettingSSHServerTransport,894,10.15.90.3] unhandled request for env
2019-08-01 13:45:48+0000 [SSHChannel session (0) on SSHService 'ssh-connection' on KeepAliveSettingSSHServerTransport,894,10.15.90.3] unhandled request for env
2019-08-01 13:45:48+0000 [SSHChannel session (0) on SSHService 'ssh-connection' on KeepAliveSettingSSHServerTransport,894,10.15.90.3] unhandled request for env
2019-08-01 13:45:48+0000 [SSHChannel session (0) on SSHService 'ssh-connection' on KeepAliveSettingSSHServerTransport,894,10.15.90.3] unhandled request for env
2019-08-01 13:45:48+0000 [SSHChannel session (0) on SSHService 'ssh-connection' on KeepAliveSettingSSHServerTransport,894,10.15.90.3] unhandled request for env
2019-08-01 13:45:48+0000 [SSHChannel session (0) on SSHService 'ssh-connection' on KeepAliveSettingSSHServerTransport,894,10.15.90.3] unhandled request for env
2019-08-01 13:45:48+0000 [SSHChannel session (0) on SSHService 'ssh-connection' on KeepAliveSettingSSHServerTransport,894,10.15.90.3] unhandled request for env
2019-08-01 13:45:48+0000 [SSHChannel session (0) on SSHService 'ssh-connection' on KeepAliveSettingSSHServerTransport,894,10.15.90.3] unhandled request for env
2019-08-01 13:45:48+0000 [SSHChannel session (0) on SSHService 'ssh-connection' on KeepAliveSettingSSHServerTransport,894,10.15.90.3] unhandled request for env
2019-08-01 13:45:48+0000 [SSHChannel session (0) on SSHService 'ssh-connection' on KeepAliveSettingSSHServerTransport,894,10.15.90.3] unhandled request for env
2019-08-01 13:45:48+0000 [SSHChannel session (0) on SSHService 'ssh-connection' on KeepAliveSettingSSHServerTransport,894,10.15.90.3] unhandled request for env
2019-08-01 13:45:48+0000 [SSHChannel session (0) on SSHService 'ssh-connection' on KeepAliveSettingSSHServerTransport,894,10.15.90.3] executing command "git-receive-pack '~cjwatson+git-testing/+git/launchpad-copy'"
2019-08-01 13:45:48+0000 [-] Starting factory <turnip.pack.ssh.SSHPackClientFactory instance at 0x7fc790727f38>
2019-08-01 13:45:49+0000 [SSHService 'ssh-connection' on KeepAliveSettingSSHServerTransport,894,10.15.90.3] adding 65685 to 65387 in channel 0
2019-08-01 13:45:49+0000 [SSHService 'ssh-connection' on KeepAliveSettingSSHServerTransport,894,10.15.90.3] adding 81920 to 49152 in channel 0
2019-08-01 13:45:49+0000 [SSHService 'ssh-connection' on KeepAliveSettingSSHServerTransport,894,10.15.90.3] adding 81920 to 49152 in channel 0
2019-08-01 13:45:49+0000 [SSHService 'ssh-connection' on KeepAliveSettingSSHServerTransport,894,10.15.90.3] adding 73728 to 57344 in channel 0
2019-08-01 13:45:49+0000 [SSHService 'ssh-connection' on KeepAliveSettingSSHServerTransport,894,10.15.90.3] adding 81920 to 49152 in channel 0
2019-08-01 13:45:48+0000 [-] [request-id=67324d7b-2624-4e41-a8b9-66c6ea242af6] [PackVirtServerProtocol] Request received: 'git-receive-pack ~cjwatson+git-testing/+git/launchpad-copy', params={'turnip-authenticated-user': 'cjwatson+git-testing', 'turnip-authenticated-uid': '6364739', 'turnip-request-id': '67324d7b-2624-4e41-a8b9-66c6ea242af6'}
2019-08-01 13:45:48+0000 [-] [request-id=67324d7b-2624-4e41-a8b9-66c6ea242af6] [PackVirtServerProtocol] Translating request.
2019-08-01 13:45:49+0000 [-] [request-id=67324d7b-2624-4e41-a8b9-66c6ea242af6] [PackVirtServerProtocol] Translation result: {'writable': True, 'path': '19058', 'trailing': '', 'private': False}
2019-08-01 13:45:49+0000 [-] [request-id=67324d7b-2624-4e41-a8b9-66c6ea242af6] [PackVirtServerProtocol] Connecting to backend: IPv4Address(TCP, '10.15.90.3', 19418).
2019-08-01 13:45:49+0000 [-] [request-id=67324d7b-2624-4e41-a8b9-66c6ea242af6] [PackVirtServerProtocol] Backend connection established: IPv4Address(TCP, '10.15.90.7', 57708) -> IPv4Address(TCP, '10.15.90.3', 19418)
2019-08-01 13:45:49+0000 [-] [request-id=67324d7b-2624-4e41-a8b9-66c6ea242af6] [PackVirtServerProtocol] Forwarding request to backend: 'git-receive-pack 19058', params={'turnip-authenticated-user': 'cjwatson+git-testing', 'turnip-authenticated-uid': '6364739', 'turnip-request-id': '67324d7b-2624-4e41-a8b9-66c6ea242af6'}
2019-08-01 13:45:49+0000 [-] [request-id=67324d7b-2624-4e41-a8b9-66c6ea242af ] [PackBackendProtocol] Request received: 'git-receive-pack 19058', params={'turnip-authenticated-user': 'cjwatson+git-testing', 'turnip-authenticated-uid': '6364739', 'turnip-request-id': '67324d7b-2624-4e41-a8b9-66c6ea242af6'}
2019-08-01 13:45:49+0000 [-] [request-id=67324d7b-2624-4e41-a8b9-66c6ea242af ] [PackBackendProtocol] Spawning ['git', 'receive-pack', '/srv/turnip/data/repos/19058']
2019-08-01 13:45:50+0000 [-] [request-id=67324d7b-2624-4e41-a8b9-66c6ea242af ] [HookRPCLogContext] checkRefPermissions request received: auth_params={u'request-id': '67324d7b-2624-4e41-a8b9-66c6ea242af6', u'user': 'cjwatson+git-testing', u'uid': 6364739}, ref_path=19058
2019-08-01 13:45:50+0000 [-] Starting factory <twisted.web.xmlrpc._QueryFactory instance at 0x7fb4cabdd0e0>
2019-08-01 13:46:05+0000 [-] [request-id=67324d7b-2624-4e41-a8b9-66c6ea242af ] [HookRPCLogContext] checkRefPermissions virtinfo timed out: auth_params={u'request-id': '67324d7b-2624-4e41-a8b9-66c6ea242af6', u'user': 'cjwatson+git-testing', u'uid': 6364739}, ref_path=19058
2019-08-01 13:46:05+0000 [-] Unhandled error in Deferred:
2019-08-01 13:46:05+0000 [-] Unhandled Error
Traceback (most recent call last):
File "/srv/turnip/turnip-pack-backend/payloads/53363600d82c721f8c81701bbd674a4ede3955e0/env/local/lib/python2.7/site-packages/twisted/internet/defer.py", line 500, in errback
self._startRunCallbacks(fail)
File "/srv/turnip/turnip-pack-backend/payloads/53363600d82c721f8c81701bbd674a4ede3955e0/env/local/lib/python2.7/site-packages/twisted/internet/defer.py", line 567, in _startRunCallbacks
self._runCallbacks()
File "/srv/turnip/turnip-pack-backend/payloads/53363600d82c721f8c81701bbd674a4ede3955e0/env/local/lib/python2.7/site-packages/twisted/internet/defer.py", line 653, in _runCallbacks
current.result = callback(current.result, *args, **kw)
File "/srv/turnip/turnip-pack-backend/payloads/53363600d82c721f8c81701bbd674a4ede3955e0/env/local/lib/python2.7/site-packages/twisted/internet/defer.py", line 1442, in gotResult
_inlineCallbacks(r, g, deferred)
--- <exception caught here> ---
File "/srv/turnip/turnip-pack-backend/payloads/53363600d82c721f8c81701bbd674a4ede3955e0/env/local/lib/python2.7/site-packages/twisted/internet/defer.py", line 1384, in _inlineCallbacks
result = result.throwExceptionIntoGenerator(g)
File "/srv/turnip/turnip-pack-backend/payloads/53363600d82c721f8c81701bbd674a4ede3955e0/env/local/lib/python2.7/site-packages/twisted/python/failure.py", line 422, in throwExceptionIntoGenerator
return g.throw(self.type, self.value, self.tb)
File "/srv/turnip/turnip-pack-backend/payloads/53363600d82c721f8c81701bbd674a4ede3955e0/turnip/pack/hookrpc.py", line 82, in valueReceived
res = yield self.methods[op](self, val)
File "/srv/turnip/turnip-pack-backend/payloads/53363600d82c721f8c81701bbd674a4ede3955e0/env/local/lib/python2.7/site-packages/twisted/internet/defer.py", line 1384, in _inlineCallbacks
result = result.throwExceptionIntoGenerator(g)
File "/srv/turnip/turnip-pack-backend/payloads/53363600d82c721f8c81701bbd674a4ede3955e0/env/local/lib/python2.7/site-packages/twisted/python/failure.py", line 422, in throwExceptionIntoGenerator
return g.throw(self.type, self.value, self.tb)
File "/srv/turnip/turnip-pack-backend/payloads/53363600d82c721f8c81701bbd674a4ede3955e0/turnip/pack/hookrpc.py", line 164, in checkRefPermissions
self.virtinfo_timeout, self.reactor)
File "/srv/turnip/turnip-pack-backend/payloads/53363600d82c721f8c81701bbd674a4ede3955e0/env/local/lib/python2.7/site-packages/twisted/internet/defer.py", line 653, in _runCallbacks
current.result = callback(current.result, *args, **kw)
File "/srv/turnip/turnip-pack-backend/payloads/53363600d82c721f8c81701bbd674a4ede3955e0/env/local/lib/python2.7/site-packages/twisted/internet/defer.py", line 394, in convertCancelled
return toCall(value, timeout)
File "/srv/turnip/turnip-pack-backend/payloads/53363600d82c721f8c81701bbd674a4ede3955e0/env/local/lib/python2.7/site-packages/twisted/internet/defer.py", line 860, in _cancelledToTimedOutError
raise TimeoutError(timeout, "Deferred")
twisted.internet.defer.TimeoutError: (15, 'Deferred')
2019-08-01 13:46:05+0000 [-] Stopping factory <twisted.web.xmlrpc._QueryFactory instance at 0x7fb4cabdd0e0>
2019-08-01 17:06:03+0000 [KeepAliveSettingSSHServerTransport,894,10.15.90.3] Got remote error, code 11
reason: disconnected by user
2019-08-01 17:06:03+0000 [SSHChannel session (0) on SSHService 'ssh-connection' on KeepAliveSettingSSHServerTransport,894,10.15.90.3] exitCode: 0
2019-08-01 17:06:03+0000 [-] Stopping factory <turnip.pack.ssh.SSHPackClientFactory instance at 0x7fc790727f38>
2019-08-01 17:06:03+0000 [KeepAliveSettingSSHServerTransport,894,10.15.90.3] connection lost
2019-08-01 17:06:16+0000 [-] [request-id=67324d7b-2624-4e41-a8b9-66c6ea242af6] [PackVirtServerProtocol] Backend connection closed.
2019-08-01 17:06:16+0000 [-] [request-id=67324d7b-2624-4e41-a8b9-66c6ea242af6] [PackVirtServerProtocol] Connection lost.
2019-08-01 17:06:31+0000 [-] [request-id=67324d7b-2624-4e41-a8b9-66c6ea242af ] [PackBackendProtocol] Connection lost.
(The 3h20m gap is when I wasn't watching the test; when I noticed, I hit Ctrl-c on the SSH client, and then you see the disconnection.)
We're probably just missing an exception handler somewhere here.
Oh, but it does leave a stale process lying around:
5377 13:45:48 S \_ git receive-pack /srv/turnip/
5403 13:45:49 S | \_ /srv/turnip/