search

canonical / charmed-openstack-upgrader

Automatic upgrade tool for Charmed Openstack
https://canonical-charmed-openstack-upgrader.readthedocs-hosted.com/en/stable/
Apache License 2.0
4 stars 12 forks source link

COU sometimes hangs on "Connecting to 'admin/openstack' model..." #458

Open samuelallan72 opened 4 days ago

samuelallan72 commented 4 days ago 
$ cou upgrade -vvv
Full execution log: '/home/ubuntu/.local/share/cou/log/cou-20240627064120.log'
Connecting to 'admin/openstack' model...

With debug verbosity, we can see this kind of repeating output from open websocket connections:

2024-06-27 06:49:00 [websockets.client] [DEBUG] % sending keepalive ping
2024-06-27 06:49:00 [websockets.client] [DEBUG] > PING 3e 44 99 fa [binary, 4 bytes]
2024-06-27 06:49:00 [websockets.client] [DEBUG] < PONG 3e 44 99 fa [binary, 4 bytes]
2024-06-27 06:49:00 [websockets.client] [DEBUG] % received keepalive pong
2024-06-27 06:49:01 [juju.client.connection] [DEBUG] Pinger <Task pending name='Task_Pinger' coro=<Connection._pinger() running at /snap/charmed-openstack-upgrader/290/lib/python3.10/site-packages/juju/client/connection.py:609> wait_for=<Future pending cb=[Task.task_wakeup()]>>: pinging
2024-06-27 06:49:01 [juju.client.connection] [DEBUG] connection id: 140185049120144 ---> {
  "type": "Pinger",
  "request": "Ping",
  "version": 1,
  "params": {},
  "request-id": 65
}
2024-06-27 06:49:01 [websockets.client] [DEBUG] > TEXT '{\n  "type": "Pinger",\n  "request": "Ping",\n ...\n  "request-id": 65\n}' [95 bytes]
2024-06-27 06:49:01 [websockets.client] [DEBUG] < TEXT '{"request-id":65,"response":{}}\n' [32 bytes]
2024-06-27 06:49:01 [juju.client.connection] [DEBUG] connection id : 140185049120144 <--- {'request-id': 65, 'response': {}}
2024-06-27 06:49:01 [websockets.client] [DEBUG] % sending keepalive ping
2024-06-27 06:49:01 [websockets.client] [DEBUG] > PING 61 31 73 a4 [binary, 4 bytes]
2024-06-27 06:49:01 [websockets.client] [DEBUG] < PONG 61 31 73 a4 [binary, 4 bytes]
2024-06-27 06:49:01 [websockets.client] [DEBUG] % received keepalive pong
2024-06-27 06:49:01 [juju.client.connection] [DEBUG] Pinger <Task pending name='Task_Pinger' coro=<Connection._pinger() running at /snap/charmed-openstack-upgrader/290/lib/python3.10/site-packages/juju/client/connection.py:609> wait_for=<Future pending cb=[Task.task_wakeup()]>>: pinging
2024-06-27 06:49:01 [juju.client.connection] [DEBUG] connection id: 140185047876944 ---> {
  "type": "Pinger",
  "request": "Ping",
  "version": 1,
  "params": {},
  "request-id": 49
}
2024-06-27 06:49:01 [websockets.client] [DEBUG] > TEXT '{\n  "type": "Pinger",\n  "request": "Ping",\n ...\n  "request-id": 49\n}' [95 bytes]
2024-06-27 06:49:01 [websockets.client] [DEBUG] < TEXT '{"request-id":49,"response":{}}\n' [32 bytes]
2024-06-27 06:49:01 [juju.client.connection] [DEBUG] connection id : 140185047876944 <--- {'request-id': 49, 'response': {}}
2024-06-27 06:49:11 [juju.client.connection] [DEBUG] Pinger <Task pending name='Task_Pinger' coro=<Connection._pinger() running at /snap/charmed-openstack-upgrader/290/lib/python3.10/site-packages/juju/client/connection.py:609> wait_for=<Future pending cb=[Task.task_wakeup()]>>: pinging
2024-06-27 06:49:11 [juju.client.connection] [DEBUG] connection id: 140185049120144 ---> {
  "type": "Pinger",
  "request": "Ping",
  "version": 1,
  "params": {},
  "request-id": 66
}
2024-06-27 06:49:11 [websockets.client] [DEBUG] > TEXT '{\n  "type": "Pinger",\n  "request": "Ping",\n ...\n  "request-id": 66\n}' [95 bytes]
2024-06-27 06:49:11 [websockets.client] [DEBUG] < TEXT '{"request-id":66,"response":{}}\n' [32 bytes]
2024-06-27 06:49:11 [juju.client.connection] [DEBUG] connection id : 140185049120144 <--- {'request-id': 66, 'response': {}}
2024-06-27 06:49:11 [juju.client.connection] [DEBUG] Pinger <Task pending name='Task_Pinger' coro=<Connection._pinger() running at /snap/charmed-openstack-upgrader/290/lib/python3.10/site-packages/juju/client/connection.py:609> wait_for=<Future pending cb=[Task.task_wakeup()]>>: pinging
2024-06-27 06:49:11 [juju.client.connection] [DEBUG] connection id: 140185047876944 ---> {
  "type": "Pinger",
  "request": "Ping",
  "version": 1,
  "params": {},
  "request-id": 50
}
2024-06-27 06:49:11 [websockets.client] [DEBUG] > TEXT '{\n  "type": "Pinger",\n  "request": "Ping",\n ...\n  "request-id": 50\n}' [95 bytes]
2024-06-27 06:49:11 [websockets.client] [DEBUG] < TEXT '{"request-id":50,"response":{}}\n' [32 bytes]
2024-06-27 06:49:11 [juju.client.connection] [DEBUG] connection id : 140185047876944 <--- {'request-id': 50, 'response': {}}
2024-06-27 06:49:20 [websockets.client] [DEBUG] % sending keepalive ping
2024-06-27 06:49:20 [websockets.client] [DEBUG] > PING 'Yy\x16.' [text, 4 bytes]
2024-06-27 06:49:20 [websockets.client] [DEBUG] < PONG 'Yy\x16.' [text, 4 bytes]
2024-06-27 06:49:20 [websockets.client] [DEBUG] % received keepalive pong
2024-06-27 06:49:21 [websockets.client] [DEBUG] % sending keepalive ping
2024-06-27 06:49:21 [websockets.client] [DEBUG] > PING e0 84 08 58 [binary, 4 bytes]
2024-06-27 06:49:21 [juju.client.connection] [DEBUG] Pinger <Task pending name='Task_Pinger' coro=<Connection._pinger() running at /snap/charmed-openstack-upgrader/290/lib/python3.10/site-packages/juju/client/connection.py:609> wait_for=<Future pending cb=[Task.task_wakeup()]>>: pinging
2024-06-27 06:49:21 [juju.client.connection] [DEBUG] connection id: 140185049120144 ---> {
  "type": "Pinger",
  "request": "Ping",
  "version": 1,
  "params": {},
  "request-id": 67
}
2024-06-27 06:49:21 [websockets.client] [DEBUG] > TEXT '{\n  "type": "Pinger",\n  "request": "Ping",\n ...\n  "request-id": 67\n}' [95 bytes]
2024-06-27 06:49:21 [websockets.client] [DEBUG] < PONG e0 84 08 58 [binary, 4 bytes]
2024-06-27 06:49:21 [websockets.client] [DEBUG] % received keepalive pong
2024-06-27 06:49:21 [websockets.client] [DEBUG] < TEXT '{"request-id":67,"response":{}}\n' [32 bytes]
2024-06-27 06:49:21 [juju.client.connection] [DEBUG] connection id : 140185049120144 <--- {'request-id': 67, 'response': {}}
2024-06-27 06:49:21 [juju.client.connection] [DEBUG] Pinger <Task pending name='Task_Pinger' coro=<Connection._pinger() running at /snap/charmed-openstack-upgrader/290/lib/python3.10/site-packages/juju/client/connection.py:609> wait_for=<Future pending cb=[Task.task_wakeup()]>>: pinging
2024-06-27 06:49:21 [juju.client.connection] [DEBUG] connection id: 140185047876944 ---> {
  "type": "Pinger",
  "request": "Ping",
  "version": 1,
  "params": {},
  "request-id": 51
}
2024-06-27 06:49:21 [websockets.client] [DEBUG] > TEXT '{\n  "type": "Pinger",\n  "request": "Ping",\n ...\n  "request-id": 51\n}' [95 bytes]
2024-06-27 06:49:21 [websockets.client] [DEBUG] < TEXT '{"request-id":51,"response":{}}\n' [32 bytes]
2024-06-27 06:49:21 [juju.client.connection] [DEBUG] connection id : 140185047876944 <--- {'request-id': 51, 'response': {}}
samuelallan72 commented 4 days ago

It appears that it might eventually complete, but for me it might hang for > 20 minutes.