EXEC websocket python client via SSL debugging help needed

Aloha,

I’ve written a simple test client of the LXD REST protocol for the exec endpoint. It uses asyncio websockets library.

The problem I’m having is that occasionally the final steps of the protocol (closing the connections) appear to be done out of sync sometimes and takes longer to finish.

This problem only occurs when using the SSL connections.

This problem also occurs with PYLXD (which is how I got here in the first place).

Can anyone help with this pernicious problem? Specifically can anyone clarify the protocol over the control, stdout, stdin, and stderr websockets and in what order (and how) they should be closed? That is the grayest area since there is no documentation and following the original (go client/server) code is not straightforward (for me anyway).

Many Thanks,

Foozle

Here is “correct” (or at least timely) run’s debug output:

2021-05-16 12:22:36,060 asyncio:DEBUG Using selector: EpollSelector
2021-05-16 12:22:36,061 urllib3.connectionpool:DEBUG Starting new HTTPS connection (1): 10.20.5.1:8443
2021-05-16 12:22:36,084 urllib3.connectionpool:DEBUG https://10.20.5.1:8443 "POST /1.0/instances/pytest-lxd-foo3/exec HTTP/1.1" 202 1054
2021-05-16 12:22:36,087 __main__:DEBUG {'type': 'async', 'status': 'Operation created', 'status_code': 100, 'operation': '/1.0/operations/bbc71615-78e7-44d0-bff0-196607621416', 'error_code': 0, 'error': '', 'metadata': {'id': 'bbc71615-78e7-44d0-bff0-196607621416', 'class': 'websocket', 'description': 'Executing command', 'created_at': '2021-05-16T12:22:36.077430835-07:00', 'updated_at': '2021-05-16T12:22:36.077430835-07:00', 'status': 'Running', 'status_code': 103, 'resources': {'containers': ['/1.0/containers/pytest-lxd-foo3'], 'instances': ['/1.0/instances/pytest-lxd-foo3']}, 'metadata': {'command': ['/bin/hostname'], 'environment': {'HOME': '/root', 'LANG': 'C.UTF-8', 'PATH': '/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin', 'USER': 'root'}, 'fds': {'0': '640a3dd34f28757943dc29554d3d7b89fa2f23054892b71c31ce57545a7edad9', '1': '2196f61b6bb7b27644841ff3949a77ca36707ff782e9158d773fbb7f91b97e99', '2': '5aa63bfcb59381b703170f679391f966a8225f1b327cfb5f4639b84e796d4443', 'control': 'a30a480bf287ff3160adf20c349d55b45af575da61e06c5ede082057c7c0f810'}, 'interactive': False}, 'may_cancel': False, 'err': '', 'location': 'none'}}
2021-05-16 12:22:36,111 urllib3.connectionpool:DEBUG Starting new HTTPS connection (1): 10.20.5.1:8443
2021-05-16 12:22:36,119 urllib3.connectionpool:DEBUG https://10.20.5.1:8443 "GET /1.0/operations/bbc71615-78e7-44d0-bff0-196607621416 HTTP/1.1" 200 991
2021-05-16 12:22:36,120 __main__:DEBUG OP = <Response [200]> {'type': 'sync', 'status': 'Success', 'status_code': 200, 'operation': '', 'error_code': 0, 'error': '', 'metadata': {'id': 'bbc71615-78e7-44d0-bff0-196607621416', 'class': 'websocket', 'description': 'Executing command', 'created_at': '2021-05-16T12:22:36.077430835-07:00', 'updated_at': '2021-05-16T12:22:36.077430835-07:00', 'status': 'Running', 'status_code': 103, 'resources': {'containers': ['/1.0/containers/pytest-lxd-foo3'], 'instances': ['/1.0/instances/pytest-lxd-foo3']}, 'metadata': {'command': ['/bin/hostname'], 'environment': {'HOME': '/root', 'LANG': 'C.UTF-8', 'PATH': '/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin', 'USER': 'root'}, 'fds': {'0': '640a3dd34f28757943dc29554d3d7b89fa2f23054892b71c31ce57545a7edad9', '1': '2196f61b6bb7b27644841ff3949a77ca36707ff782e9158d773fbb7f91b97e99', '2': '5aa63bfcb59381b703170f679391f966a8225f1b327cfb5f4639b84e796d4443', 'control': 'a30a480bf287ff3160adf20c349d55b45af575da61e06c5ede082057c7c0f810'}, 'interactive': False}, 'may_cancel': False, 'err': '', 'location': 'none'}}
2021-05-16 12:22:36,120 websockets.protocol:DEBUG client - state = CONNECTING
2021-05-16 12:22:36,120 websockets.protocol:DEBUG client - state = CONNECTING
2021-05-16 12:22:36,120 websockets.protocol:DEBUG client - state = CONNECTING
2021-05-16 12:22:36,120 websockets.protocol:DEBUG client - state = CONNECTING
2021-05-16 12:22:36,138 websockets.protocol:DEBUG client - event = connection_made(<asyncio.sslproto._SSLProtocolTransport object at 0x7ff6e5c080a0>)
2021-05-16 12:22:36,139 websockets.server:DEBUG client > GET /1.0/operations/bbc71615-78e7-44d0-bff0-196607621416/websocket?secret=a30a480bf287ff3160adf20c349d55b45af575da61e06c5ede082057c7c0f810 HTTP/1.1
2021-05-16 12:22:36,139 websockets.server:DEBUG client > Headers([('Host', '10.20.5.1:8443'), ('Upgrade', 'websocket'), ('Connection', 'Upgrade'), ('Sec-WebSocket-Key', 'dyBm5vfZL0l/ZTB9JpnlPg=='), ('Sec-WebSocket-Version', '13'), ('Sec-WebSocket-Extensions', 'permessage-deflate; client_max_window_bits'), ('User-Agent', 'Python/3.8 websockets/9.0.2')])
2021-05-16 12:22:36,143 websockets.protocol:DEBUG client - event = data_received(<129 bytes>)
2021-05-16 12:22:36,143 websockets.server:DEBUG client < HTTP/1.1 101 Switching Protocols
2021-05-16 12:22:36,143 websockets.server:DEBUG client < Headers([('Upgrade', 'websocket'), ('Connection', 'Upgrade'), ('Sec-WebSocket-Accept', 'pMg7ux/k/yPh1TXzKdUF+bFQGb0=')])
2021-05-16 12:22:36,144 websockets.protocol:DEBUG client - state = OPEN
2021-05-16 12:22:36,147 websockets.protocol:DEBUG client - event = connection_made(<asyncio.sslproto._SSLProtocolTransport object at 0x7ff6e5c083a0>)
2021-05-16 12:22:36,150 websockets.protocol:DEBUG client - event = connection_made(<asyncio.sslproto._SSLProtocolTransport object at 0x7ff6e5c08220>)
2021-05-16 12:22:36,150 websockets.server:DEBUG client > GET /1.0/operations/bbc71615-78e7-44d0-bff0-196607621416/websocket?secret=2196f61b6bb7b27644841ff3949a77ca36707ff782e9158d773fbb7f91b97e99 HTTP/1.1
2021-05-16 12:22:36,150 websockets.server:DEBUG client > Headers([('Host', '10.20.5.1:8443'), ('Upgrade', 'websocket'), ('Connection', 'Upgrade'), ('Sec-WebSocket-Key', 'IOEzDZCNgVkwKSfkik8tzA=='), ('Sec-WebSocket-Version', '13'), ('Sec-WebSocket-Extensions', 'permessage-deflate; client_max_window_bits'), ('User-Agent', 'Python/3.8 websockets/9.0.2')])
2021-05-16 12:22:36,150 websockets.server:DEBUG client > GET /1.0/operations/bbc71615-78e7-44d0-bff0-196607621416/websocket?secret=640a3dd34f28757943dc29554d3d7b89fa2f23054892b71c31ce57545a7edad9 HTTP/1.1
2021-05-16 12:22:36,151 websockets.server:DEBUG client > Headers([('Host', '10.20.5.1:8443'), ('Upgrade', 'websocket'), ('Connection', 'Upgrade'), ('Sec-WebSocket-Key', 'GUbS6eunmdiBYGnYsJ9pgA=='), ('Sec-WebSocket-Version', '13'), ('Sec-WebSocket-Extensions', 'permessage-deflate; client_max_window_bits'), ('User-Agent', 'Python/3.8 websockets/9.0.2')])
2021-05-16 12:22:36,153 websockets.protocol:DEBUG client - event = connection_made(<asyncio.sslproto._SSLProtocolTransport object at 0x7ff6e5c08520>)
2021-05-16 12:22:36,154 websockets.server:DEBUG client > GET /1.0/operations/bbc71615-78e7-44d0-bff0-196607621416/websocket?secret=5aa63bfcb59381b703170f679391f966a8225f1b327cfb5f4639b84e796d4443 HTTP/1.1
2021-05-16 12:22:36,154 websockets.server:DEBUG client > Headers([('Host', '10.20.5.1:8443'), ('Upgrade', 'websocket'), ('Connection', 'Upgrade'), ('Sec-WebSocket-Key', 'heRQifEIl2nUT8eCH3Bm5w=='), ('Sec-WebSocket-Version', '13'), ('Sec-WebSocket-Extensions', 'permessage-deflate; client_max_window_bits'), ('User-Agent', 'Python/3.8 websockets/9.0.2')])
2021-05-16 12:22:36,154 websockets.protocol:DEBUG client - event = data_received(<129 bytes>)
2021-05-16 12:22:36,154 websockets.protocol:DEBUG client - event = data_received(<129 bytes>)
2021-05-16 12:22:36,154 websockets.server:DEBUG client < HTTP/1.1 101 Switching Protocols
2021-05-16 12:22:36,154 websockets.server:DEBUG client < Headers([('Upgrade', 'websocket'), ('Connection', 'Upgrade'), ('Sec-WebSocket-Accept', '7eA1Ud+gp8cidKg6lfYgc3Co8ks=')])
2021-05-16 12:22:36,154 websockets.protocol:DEBUG client - state = OPEN
2021-05-16 12:22:36,154 websockets.server:DEBUG client < HTTP/1.1 101 Switching Protocols
2021-05-16 12:22:36,154 websockets.server:DEBUG client < Headers([('Upgrade', 'websocket'), ('Connection', 'Upgrade'), ('Sec-WebSocket-Accept', 'CdFtt5zEpwsBN+7gzqbPjGDlX88=')])
2021-05-16 12:22:36,154 websockets.protocol:DEBUG client - state = OPEN
2021-05-16 12:22:36,155 websockets.protocol:DEBUG client > Frame(fin=True, opcode=<Opcode.TEXT: 1>, data=b'', rsv1=False, rsv2=False, rsv3=False)
2021-05-16 12:22:36,155 __main__:DEBUG stdin got None
2021-05-16 12:22:36,155 __main__:DEBUG stdin 640a3dd34f28757943dc29554d3d7b89fa2f23054892b71c31ce57545a7edad9 closing
2021-05-16 12:22:36,155 websockets.protocol:DEBUG client - event = data_received(<129 bytes>)
2021-05-16 12:22:36,155 websockets.protocol:DEBUG client - state = CLOSING
2021-05-16 12:22:36,155 websockets.protocol:DEBUG client > Frame(fin=True, opcode=<Opcode.CLOSE: 8>, data=b'\x03\xe8', rsv1=False, rsv2=False, rsv3=False)
2021-05-16 12:22:36,155 websockets.server:DEBUG client < HTTP/1.1 101 Switching Protocols
2021-05-16 12:22:36,155 websockets.server:DEBUG client < Headers([('Upgrade', 'websocket'), ('Connection', 'Upgrade'), ('Sec-WebSocket-Accept', 'iZx6zenElA7N66eQrrjfr5iX/qQ=')])
2021-05-16 12:22:36,155 websockets.protocol:DEBUG client - state = OPEN
2021-05-16 12:22:36,191 websockets.protocol:DEBUG client - event = data_received(<18 bytes>)
2021-05-16 12:22:36,191 websockets.protocol:DEBUG client < Frame(fin=True, opcode=<Opcode.BINARY: 2>, data=b'pytest-lxd-foo3\n', rsv1=False, rsv2=False, rsv3=False)
2021-05-16 12:22:36,192 websockets.protocol:DEBUG client - event = data_received(<2 bytes>)
2021-05-16 12:22:36,192 websockets.protocol:DEBUG client - event = data_received(<2 bytes>)
2021-05-16 12:22:36,192 __main__:DEBUG 2196f61b6bb7b27644841ff3949a77ca36707ff782e9158d773fbb7f91b97e99 received: "b'pytest-lxd-foo3\n'"
2021-05-16 12:22:36,192 websockets.protocol:DEBUG client < Frame(fin=True, opcode=<Opcode.TEXT: 1>, data=b'', rsv1=False, rsv2=False, rsv3=False)
2021-05-16 12:22:36,192 websockets.protocol:DEBUG client < Frame(fin=True, opcode=<Opcode.TEXT: 1>, data=b'', rsv1=False, rsv2=False, rsv3=False)
2021-05-16 12:22:36,192 websockets.protocol:DEBUG client - event = connection_lost(None)
2021-05-16 12:22:36,192 websockets.protocol:DEBUG client - state = CLOSED
2021-05-16 12:22:36,192 websockets.protocol:DEBUG client x code = 1006, reason = [no reason]
2021-05-16 12:22:36,193 websockets.protocol:DEBUG client ! failing CLOSED WebSocket connection with code 1006
2021-05-16 12:22:36,193 __main__:DEBUG 2196f61b6bb7b27644841ff3949a77ca36707ff782e9158d773fbb7f91b97e99 received: ""
2021-05-16 12:22:36,193 __main__:DEBUG 2196f61b6bb7b27644841ff3949a77ca36707ff782e9158d773fbb7f91b97e99 closing
2021-05-16 12:22:36,194 __main__:DEBUG 5aa63bfcb59381b703170f679391f966a8225f1b327cfb5f4639b84e796d4443 received: ""
2021-05-16 12:22:36,194 __main__:DEBUG 5aa63bfcb59381b703170f679391f966a8225f1b327cfb5f4639b84e796d4443 closing
2021-05-16 12:22:36,194 websockets.protocol:DEBUG client x closing TCP connection
2021-05-16 12:22:36,194 websockets.protocol:DEBUG client - state = CLOSING
2021-05-16 12:22:36,194 websockets.protocol:DEBUG client > Frame(fin=True, opcode=<Opcode.CLOSE: 8>, data=b'\x03\xe8', rsv1=False, rsv2=False, rsv3=False)
2021-05-16 12:22:36,195 websockets.protocol:DEBUG client - state = CLOSING
2021-05-16 12:22:36,195 websockets.protocol:DEBUG client > Frame(fin=True, opcode=<Opcode.CLOSE: 8>, data=b'\x03\xe8', rsv1=False, rsv2=False, rsv3=False)
2021-05-16 12:22:36,195 __main__:ERROR Got exception: code = 1006 (connection closed abnormally [internal]), no reason
2021-05-16 12:22:36,196 __main__:DEBUG a30a480bf287ff3160adf20c349d55b45af575da61e06c5ede082057c7c0f810 closing
2021-05-16 12:22:36,196 __main__:DEBUG a30a480bf287ff3160adf20c349d55b45af575da61e06c5ede082057c7c0f810 leaving ctmgr
2021-05-16 12:22:36,197 __main__:DEBUG a30a480bf287ff3160adf20c349d55b45af575da61e06c5ede082057c7c0f810 exiting
2021-05-16 12:22:36,625 urllib3.connectionpool:DEBUG Starting new HTTPS connection (1): 10.20.5.1:8443
2021-05-16 12:22:36,638 urllib3.connectionpool:DEBUG https://10.20.5.1:8443 "GET /1.0/operations/bbc71615-78e7-44d0-bff0-196607621416 HTTP/1.1" 200 524
2021-05-16 12:22:36,638 __main__:DEBUG OP = <Response [200]> {'type': 'sync', 'status': 'Success', 'status_code': 200, 'operation': '', 'error_code': 0, 'error': '', 'metadata': {'id': 'bbc71615-78e7-44d0-bff0-196607621416', 'class': 'websocket', 'description': 'Executing command', 'created_at': '2021-05-16T12:22:36.077430835-07:00', 'updated_at': '2021-05-16T12:22:36.191906752-07:00', 'status': 'Success', 'status_code': 200, 'resources': {'containers': ['/1.0/containers/pytest-lxd-foo3'], 'instances': ['/1.0/instances/pytest-lxd-foo3']}, 'metadata': {'return': 0}, 'may_cancel': False, 'err': '', 'location': 'none'}}
2021-05-16 12:22:36,639 __main__:DEBUG Exiting get_op()
2021-05-16 12:22:36,639 websockets.protocol:DEBUG client - event = eof_received()
2021-05-16 12:22:36,639 websockets.protocol:DEBUG client ! failing CLOSING WebSocket connection with code 1006
2021-05-16 12:22:36,639 websockets.protocol:DEBUG client - event = connection_lost([Errno 104] Connection reset by peer)
2021-05-16 12:22:36,639 websockets.protocol:DEBUG client - state = CLOSED
2021-05-16 12:22:36,639 websockets.protocol:DEBUG client x code = 1006, reason = [no reason]
2021-05-16 12:22:36,639 websockets.protocol:DEBUG client - event = connection_lost([Errno 104] Connection reset by peer)
2021-05-16 12:22:36,639 websockets.protocol:DEBUG client - state = CLOSED
2021-05-16 12:22:36,639 websockets.protocol:DEBUG client x code = 1006, reason = [no reason]
2021-05-16 12:22:36,639 websockets.protocol:DEBUG client - event = connection_lost(None)
2021-05-16 12:22:36,639 websockets.protocol:DEBUG client - state = CLOSED
2021-05-16 12:22:36,639 websockets.protocol:DEBUG client x code = 1006, reason = [no reason]
2021-05-16 12:22:36,639 websockets.protocol:DEBUG client ! failing CLOSED WebSocket connection with code 1006
2021-05-16 12:22:36,639 websockets.protocol:DEBUG client ! failing CLOSED WebSocket connection with code 1006
2021-05-16 12:22:36,640 websockets.protocol:DEBUG client x closing TCP connection
2021-05-16 12:22:36,640 websockets.protocol:DEBUG client x closing TCP connection
2021-05-16 12:22:36,640 __main__:DEBUG 5aa63bfcb59381b703170f679391f966a8225f1b327cfb5f4639b84e796d4443 leaving ctmgr
2021-05-16 12:22:36,640 __main__:DEBUG 2196f61b6bb7b27644841ff3949a77ca36707ff782e9158d773fbb7f91b97e99 leaving ctmgr
2021-05-16 12:22:36,640 websockets.protocol:DEBUG client x closing TCP connection
2021-05-16 12:22:36,640 __main__:DEBUG stdin 640a3dd34f28757943dc29554d3d7b89fa2f23054892b71c31ce57545a7edad9 leaving ctmgr
2021-05-16 12:22:36,640 __main__:DEBUG 5aa63bfcb59381b703170f679391f966a8225f1b327cfb5f4639b84e796d4443 exiting
2021-05-16 12:22:36,640 __main__:DEBUG 2196f61b6bb7b27644841ff3949a77ca36707ff782e9158d773fbb7f91b97e99 exiting
2021-05-16 12:22:36,640 __main__:DEBUG stdin 640a3dd34f28757943dc29554d3d7b89fa2f23054892b71c31ce57545a7edad9 exiting
{'stdout': [b'pytest-lxd-foo3\n'], 'stderr': []}

Followed by a delayed finish that took over 20 seconds.

2021-05-16 12:21:32,320 asyncio:DEBUG Using selector: EpollSelector
2021-05-16 12:21:32,322 urllib3.connectionpool:DEBUG Starting new HTTPS connection (1): 10.20.5.1:8443
2021-05-16 12:21:32,353 urllib3.connectionpool:DEBUG https://10.20.5.1:8443 "POST /1.0/instances/pytest-lxd-foo3/exec HTTP/1.1" 202 1054
2021-05-16 12:21:32,354 __main__:DEBUG {'type': 'async', 'status': 'Operation created', 'status_code': 100, 'operation': '/1.0/operations/2534dc0b-4fb5-44fd-8c33-79a376923c6b', 'error_code': 0, 'error': '', 'metadata': {'id': '2534dc0b-4fb5-44fd-8c33-79a376923c6b', 'class': 'websocket', 'description': 'Executing command', 'created_at': '2021-05-16T12:21:32.349211217-07:00', 'updated_at': '2021-05-16T12:21:32.349211217-07:00', 'status': 'Running', 'status_code': 103, 'resources': {'containers': ['/1.0/containers/pytest-lxd-foo3'], 'instances': ['/1.0/instances/pytest-lxd-foo3']}, 'metadata': {'command': ['/bin/hostname'], 'environment': {'HOME': '/root', 'LANG': 'C.UTF-8', 'PATH': '/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin', 'USER': 'root'}, 'fds': {'0': 'cfad270c85abb0bd923266e08923c1d8c1764b2f5d1748d0f482b339036ebaf3', '1': '3e5261927f1a4a06f6e299b2ec93ba51766ddc7c07fc244248a9a746edfa6bff', '2': '41617770b1b3958fe37f0565dcd1abb9b707d4018057b03ed708e56a323eae76', 'control': '6786115e4de0b3b05dc957ff96b8cac7439b973edeaf8ae8f8d7a4a8424422dd'}, 'interactive': False}, 'may_cancel': False, 'err': '', 'location': 'none'}}
2021-05-16 12:21:32,369 urllib3.connectionpool:DEBUG Starting new HTTPS connection (1): 10.20.5.1:8443
2021-05-16 12:21:32,382 urllib3.connectionpool:DEBUG https://10.20.5.1:8443 "GET /1.0/operations/2534dc0b-4fb5-44fd-8c33-79a376923c6b HTTP/1.1" 200 991
2021-05-16 12:21:32,384 __main__:DEBUG OP = <Response [200]> {'type': 'sync', 'status': 'Success', 'status_code': 200, 'operation': '', 'error_code': 0, 'error': '', 'metadata': {'id': '2534dc0b-4fb5-44fd-8c33-79a376923c6b', 'class': 'websocket', 'description': 'Executing command', 'created_at': '2021-05-16T12:21:32.349211217-07:00', 'updated_at': '2021-05-16T12:21:32.349211217-07:00', 'status': 'Running', 'status_code': 103, 'resources': {'containers': ['/1.0/containers/pytest-lxd-foo3'], 'instances': ['/1.0/instances/pytest-lxd-foo3']}, 'metadata': {'command': ['/bin/hostname'], 'environment': {'HOME': '/root', 'LANG': 'C.UTF-8', 'PATH': '/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin', 'USER': 'root'}, 'fds': {'0': 'cfad270c85abb0bd923266e08923c1d8c1764b2f5d1748d0f482b339036ebaf3', '1': '3e5261927f1a4a06f6e299b2ec93ba51766ddc7c07fc244248a9a746edfa6bff', '2': '41617770b1b3958fe37f0565dcd1abb9b707d4018057b03ed708e56a323eae76', 'control': '6786115e4de0b3b05dc957ff96b8cac7439b973edeaf8ae8f8d7a4a8424422dd'}, 'interactive': False}, 'may_cancel': False, 'err': '', 'location': 'none'}}
2021-05-16 12:21:32,385 websockets.protocol:DEBUG client - state = CONNECTING
2021-05-16 12:21:32,386 websockets.protocol:DEBUG client - state = CONNECTING
2021-05-16 12:21:32,387 websockets.protocol:DEBUG client - state = CONNECTING
2021-05-16 12:21:32,387 websockets.protocol:DEBUG client - state = CONNECTING
2021-05-16 12:21:32,406 websockets.protocol:DEBUG client - event = connection_made(<asyncio.sslproto._SSLProtocolTransport object at 0x7f69cf00e0a0>)
2021-05-16 12:21:32,406 websockets.server:DEBUG client > GET /1.0/operations/2534dc0b-4fb5-44fd-8c33-79a376923c6b/websocket?secret=6786115e4de0b3b05dc957ff96b8cac7439b973edeaf8ae8f8d7a4a8424422dd HTTP/1.1
2021-05-16 12:21:32,406 websockets.server:DEBUG client > Headers([('Host', '10.20.5.1:8443'), ('Upgrade', 'websocket'), ('Connection', 'Upgrade'), ('Sec-WebSocket-Key', 'fOojtpL1tbhnL0jYpAlTiQ=='), ('Sec-WebSocket-Version', '13'), ('Sec-WebSocket-Extensions', 'permessage-deflate; client_max_window_bits'), ('User-Agent', 'Python/3.8 websockets/9.0.2')])
2021-05-16 12:21:32,411 websockets.protocol:DEBUG client - event = connection_made(<asyncio.sslproto._SSLProtocolTransport object at 0x7f69cf00e520>)
2021-05-16 12:21:32,411 websockets.server:DEBUG client > GET /1.0/operations/2534dc0b-4fb5-44fd-8c33-79a376923c6b/websocket?secret=41617770b1b3958fe37f0565dcd1abb9b707d4018057b03ed708e56a323eae76 HTTP/1.1
2021-05-16 12:21:32,411 websockets.server:DEBUG client > Headers([('Host', '10.20.5.1:8443'), ('Upgrade', 'websocket'), ('Connection', 'Upgrade'), ('Sec-WebSocket-Key', 'tCUDk9TZM49123g5SW891A=='), ('Sec-WebSocket-Version', '13'), ('Sec-WebSocket-Extensions', 'permessage-deflate; client_max_window_bits'), ('User-Agent', 'Python/3.8 websockets/9.0.2')])
2021-05-16 12:21:32,415 websockets.protocol:DEBUG client - event = connection_made(<asyncio.sslproto._SSLProtocolTransport object at 0x7f69cf00e3a0>)
2021-05-16 12:21:32,418 websockets.protocol:DEBUG client - event = connection_made(<asyncio.sslproto._SSLProtocolTransport object at 0x7f69cf00e220>)
2021-05-16 12:21:32,418 websockets.protocol:DEBUG client - event = data_received(<129 bytes>)
2021-05-16 12:21:32,419 websockets.server:DEBUG client > GET /1.0/operations/2534dc0b-4fb5-44fd-8c33-79a376923c6b/websocket?secret=3e5261927f1a4a06f6e299b2ec93ba51766ddc7c07fc244248a9a746edfa6bff HTTP/1.1
2021-05-16 12:21:32,419 websockets.server:DEBUG client > Headers([('Host', '10.20.5.1:8443'), ('Upgrade', 'websocket'), ('Connection', 'Upgrade'), ('Sec-WebSocket-Key', 'V+TGODS2b0tHiVBJKv4pXg=='), ('Sec-WebSocket-Version', '13'), ('Sec-WebSocket-Extensions', 'permessage-deflate; client_max_window_bits'), ('User-Agent', 'Python/3.8 websockets/9.0.2')])
2021-05-16 12:21:32,419 websockets.server:DEBUG client > GET /1.0/operations/2534dc0b-4fb5-44fd-8c33-79a376923c6b/websocket?secret=cfad270c85abb0bd923266e08923c1d8c1764b2f5d1748d0f482b339036ebaf3 HTTP/1.1
2021-05-16 12:21:32,419 websockets.server:DEBUG client > Headers([('Host', '10.20.5.1:8443'), ('Upgrade', 'websocket'), ('Connection', 'Upgrade'), ('Sec-WebSocket-Key', '43PogyZNipR0BVyZAm7S0A=='), ('Sec-WebSocket-Version', '13'), ('Sec-WebSocket-Extensions', 'permessage-deflate; client_max_window_bits'), ('User-Agent', 'Python/3.8 websockets/9.0.2')])
2021-05-16 12:21:32,419 websockets.server:DEBUG client < HTTP/1.1 101 Switching Protocols
2021-05-16 12:21:32,419 websockets.server:DEBUG client < Headers([('Upgrade', 'websocket'), ('Connection', 'Upgrade'), ('Sec-WebSocket-Accept', 'ev+i0d1F9xX3IBLF8vet08X1BLs=')])
2021-05-16 12:21:32,419 websockets.protocol:DEBUG client - state = OPEN
2021-05-16 12:21:32,420 websockets.protocol:DEBUG client - event = data_received(<129 bytes>)
2021-05-16 12:21:32,420 websockets.server:DEBUG client < HTTP/1.1 101 Switching Protocols
2021-05-16 12:21:32,420 websockets.server:DEBUG client < Headers([('Upgrade', 'websocket'), ('Connection', 'Upgrade'), ('Sec-WebSocket-Accept', 'p/S4JSI3LUVR63dGOzpw06wFFPo=')])
2021-05-16 12:21:32,420 websockets.protocol:DEBUG client - state = OPEN
2021-05-16 12:21:32,420 websockets.protocol:DEBUG client - event = data_received(<129 bytes>)
2021-05-16 12:21:32,420 websockets.server:DEBUG client < HTTP/1.1 101 Switching Protocols
2021-05-16 12:21:32,420 websockets.server:DEBUG client < Headers([('Upgrade', 'websocket'), ('Connection', 'Upgrade'), ('Sec-WebSocket-Accept', 'AyubbrLto+im6KTdO4sN9KOQWOU=')])
2021-05-16 12:21:32,420 websockets.protocol:DEBUG client - state = OPEN
2021-05-16 12:21:32,421 websockets.protocol:DEBUG client - event = data_received(<129 bytes>)
2021-05-16 12:21:32,421 websockets.server:DEBUG client < HTTP/1.1 101 Switching Protocols
2021-05-16 12:21:32,421 websockets.server:DEBUG client < Headers([('Upgrade', 'websocket'), ('Connection', 'Upgrade'), ('Sec-WebSocket-Accept', 'IWNpQo5acuTPTo6ahGD2QFtFq8M=')])
2021-05-16 12:21:32,421 websockets.protocol:DEBUG client - state = OPEN
2021-05-16 12:21:32,421 websockets.protocol:DEBUG client > Frame(fin=True, opcode=<Opcode.TEXT: 1>, data=b'', rsv1=False, rsv2=False, rsv3=False)
2021-05-16 12:21:32,421 __main__:DEBUG stdin got None
2021-05-16 12:21:32,421 __main__:DEBUG stdin cfad270c85abb0bd923266e08923c1d8c1764b2f5d1748d0f482b339036ebaf3 closing
2021-05-16 12:21:32,421 websockets.protocol:DEBUG client - state = CLOSING
2021-05-16 12:21:32,421 websockets.protocol:DEBUG client > Frame(fin=True, opcode=<Opcode.CLOSE: 8>, data=b'\x03\xe8', rsv1=False, rsv2=False, rsv3=False)
2021-05-16 12:21:32,451 websockets.protocol:DEBUG client - event = data_received(<18 bytes>)
2021-05-16 12:21:32,452 websockets.protocol:DEBUG client < Frame(fin=True, opcode=<Opcode.BINARY: 2>, data=b'pytest-lxd-foo3\n', rsv1=False, rsv2=False, rsv3=False)
2021-05-16 12:21:32,452 __main__:DEBUG 3e5261927f1a4a06f6e299b2ec93ba51766ddc7c07fc244248a9a746edfa6bff received: "b'pytest-lxd-foo3\n'"
2021-05-16 12:21:32,452 websockets.protocol:DEBUG client - event = connection_lost(None)
2021-05-16 12:21:32,452 websockets.protocol:DEBUG client - state = CLOSED
2021-05-16 12:21:32,452 websockets.protocol:DEBUG client x code = 1006, reason = [no reason]
2021-05-16 12:21:32,452 websockets.protocol:DEBUG client - event = data_received(<2 bytes>)
2021-05-16 12:21:32,453 websockets.protocol:DEBUG client ! failing CLOSED WebSocket connection with code 1006
2021-05-16 12:21:32,453 websockets.protocol:DEBUG client < Frame(fin=True, opcode=<Opcode.TEXT: 1>, data=b'', rsv1=False, rsv2=False, rsv3=False)
2021-05-16 12:21:32,454 websockets.protocol:DEBUG client - event = data_received(<2 bytes>)
2021-05-16 12:21:32,454 websockets.protocol:DEBUG client x closing TCP connection
2021-05-16 12:21:32,454 websockets.protocol:DEBUG client < Frame(fin=True, opcode=<Opcode.TEXT: 1>, data=b'', rsv1=False, rsv2=False, rsv3=False)
2021-05-16 12:21:32,455 __main__:ERROR Got exception: code = 1006 (connection closed abnormally [internal]), no reason
2021-05-16 12:21:32,455 __main__:DEBUG 6786115e4de0b3b05dc957ff96b8cac7439b973edeaf8ae8f8d7a4a8424422dd closing
2021-05-16 12:21:32,455 __main__:DEBUG 41617770b1b3958fe37f0565dcd1abb9b707d4018057b03ed708e56a323eae76 received: ""
2021-05-16 12:21:32,456 __main__:DEBUG 41617770b1b3958fe37f0565dcd1abb9b707d4018057b03ed708e56a323eae76 closing
2021-05-16 12:21:32,456 websockets.protocol:DEBUG client - state = CLOSING
2021-05-16 12:21:32,456 websockets.protocol:DEBUG client > Frame(fin=True, opcode=<Opcode.CLOSE: 8>, data=b'\x03\xe8', rsv1=False, rsv2=False, rsv3=False)
2021-05-16 12:21:32,457 __main__:DEBUG 3e5261927f1a4a06f6e299b2ec93ba51766ddc7c07fc244248a9a746edfa6bff received: ""
2021-05-16 12:21:32,457 __main__:DEBUG 3e5261927f1a4a06f6e299b2ec93ba51766ddc7c07fc244248a9a746edfa6bff closing
2021-05-16 12:21:32,458 websockets.protocol:DEBUG client - state = CLOSING
2021-05-16 12:21:32,458 websockets.protocol:DEBUG client > Frame(fin=True, opcode=<Opcode.CLOSE: 8>, data=b'\x03\xe8', rsv1=False, rsv2=False, rsv3=False)
2021-05-16 12:21:32,459 __main__:DEBUG 6786115e4de0b3b05dc957ff96b8cac7439b973edeaf8ae8f8d7a4a8424422dd leaving ctmgr
2021-05-16 12:21:32,459 __main__:DEBUG 6786115e4de0b3b05dc957ff96b8cac7439b973edeaf8ae8f8d7a4a8424422dd exiting
2021-05-16 12:21:32,888 urllib3.connectionpool:DEBUG Starting new HTTPS connection (1): 10.20.5.1:8443
2021-05-16 12:21:32,901 urllib3.connectionpool:DEBUG https://10.20.5.1:8443 "GET /1.0/operations/2534dc0b-4fb5-44fd-8c33-79a376923c6b HTTP/1.1" 200 524
2021-05-16 12:21:32,902 __main__:DEBUG OP = <Response [200]> {'type': 'sync', 'status': 'Success', 'status_code': 200, 'operation': '', 'error_code': 0, 'error': '', 'metadata': {'id': '2534dc0b-4fb5-44fd-8c33-79a376923c6b', 'class': 'websocket', 'description': 'Executing command', 'created_at': '2021-05-16T12:21:32.349211217-07:00', 'updated_at': '2021-05-16T12:21:32.453612861-07:00', 'status': 'Success', 'status_code': 200, 'resources': {'containers': ['/1.0/containers/pytest-lxd-foo3'], 'instances': ['/1.0/instances/pytest-lxd-foo3']}, 'metadata': {'return': 0}, 'may_cancel': False, 'err': '', 'location': 'none'}}
2021-05-16 12:21:32,902 __main__:DEBUG Exiting get_op()
2021-05-16 12:21:52,433 websockets.protocol:DEBUG client ! timed out waiting for TCP close
2021-05-16 12:21:52,433 websockets.protocol:DEBUG client x closing TCP connection
2021-05-16 12:21:52,462 websockets.protocol:DEBUG client ! timed out waiting for TCP close
2021-05-16 12:21:52,462 websockets.protocol:DEBUG client x closing TCP connection
2021-05-16 12:21:52,462 websockets.protocol:DEBUG client ! timed out waiting for TCP close
2021-05-16 12:21:52,462 websockets.protocol:DEBUG client x closing TCP connection
2021-05-16 12:21:58,806 websockets.protocol:DEBUG client - event = connection_lost([Errno 104] Connection reset by peer)
2021-05-16 12:21:58,806 websockets.protocol:DEBUG client - state = CLOSED
2021-05-16 12:21:58,806 websockets.protocol:DEBUG client x code = 1006, reason = [no reason]
2021-05-16 12:21:58,806 websockets.protocol:DEBUG client - event = connection_lost([Errno 104] Connection reset by peer)
2021-05-16 12:21:58,806 websockets.protocol:DEBUG client - state = CLOSED
2021-05-16 12:21:58,806 websockets.protocol:DEBUG client x code = 1006, reason = [no reason]
2021-05-16 12:21:58,806 websockets.protocol:DEBUG client - event = connection_lost([Errno 104] Connection reset by peer)
2021-05-16 12:21:58,806 websockets.protocol:DEBUG client - state = CLOSED
2021-05-16 12:21:58,806 websockets.protocol:DEBUG client x code = 1006, reason = [no reason]
2021-05-16 12:21:58,806 __main__:DEBUG stdin cfad270c85abb0bd923266e08923c1d8c1764b2f5d1748d0f482b339036ebaf3 leaving ctmgr
2021-05-16 12:21:58,806 __main__:DEBUG 41617770b1b3958fe37f0565dcd1abb9b707d4018057b03ed708e56a323eae76 leaving ctmgr
2021-05-16 12:21:58,806 __main__:DEBUG 3e5261927f1a4a06f6e299b2ec93ba51766ddc7c07fc244248a9a746edfa6bff leaving ctmgr
2021-05-16 12:21:58,806 __main__:DEBUG stdin cfad270c85abb0bd923266e08923c1d8c1764b2f5d1748d0f482b339036ebaf3 exiting
2021-05-16 12:21:58,807 __main__:DEBUG 41617770b1b3958fe37f0565dcd1abb9b707d4018057b03ed708e56a323eae76 exiting
2021-05-16 12:21:58,807 __main__:DEBUG 3e5261927f1a4a06f6e299b2ec93ba51766ddc7c07fc244248a9a746edfa6bff exiting
{'stdout': [b'pytest-lxd-foo3\n'], 'stderr': []}

It appears that lxd/client/lxd_instances.go:ExecInstance() does not wait for the typical WS close frame, this makes me assume that the server isn’t sending one either.

That may well be the problem as the python websockets library will wait for the close frame, this doesn’t explain why the delayed exit doesn’t always happen.

Setting close_timeout=0 in the websockets.connect() call solved this problem. Hooray. Someone should try to fix this in PyLXD :slight_smile: