ISPyB TIMEOUT pop-up is too frequent

[alanbchristie]

Currently the TIMEOUT popup is too frequent. We need to keep an eye on this and if it continues like this (with the private key tunnel approach) we need to reduce the rate it's displayed.

• Is there an underlying timeout we're not using?
• Is the timeout too short?
• Are we "polling" too often?

See #1316 for related material

[alanbchristie]

Exposing more debug during the connections we can see the log that occurs at an approximate period of 30 seconds (sensitive material removed): -

2024-04-03T14:04:40+0000 viewer.services.ispyb():160 INFO # + ispyb
2024-04-03T14:04:40+0000 api.security.get_remote_conn():79 INFO # Creating remote connector with credentials: [...]
2024-04-03T14:04:40+0000 api.remote_ispyb_connector.__init__():56 INFO # Creating remote connector: [...]
2024-04-03T14:04:40+0000 api.remote_ispyb_connector.remote_connect():94 INFO # Creating SSHTunnelForwarder (with SSH Key) host=ssh.diamond.ac.uk user=fragalysis-stack
2024-04-03T14:04:40+0000 sshtunnel.SSHTunnelForwarder._read_ssh_config():1032 WARNING # Could not read SSH configuration file: ~/.ssh/config
2024-04-03T14:04:40+0000 sshtunnel.SSHTunnelForwarder.get_agent_keys():1060 INFO # 0 keys loaded from agent
2024-04-03T14:04:40+0000 sshtunnel.SSHTunnelForwarder.get_keys():1117 INFO # 0 key(s) loaded
2024-04-03T14:04:41+0000 sshtunnel.SSHTunnelForwarder.read_private_key_file():1309 DEBUG # Private key file (/code/fragalysis-stack-ssh-key, <class 'paramiko.rsakey.RSAKey'>) successfully loaded
2024-04-03T14:04:41+0000 sshtunnel.SSHTunnelForwarder.__init__():978 INFO # Connecting to gateway: ssh.diamond.ac.uk:22 as user 'fragalysis-stack'
2024-04-03T14:04:41+0000 sshtunnel.SSHTunnelForwarder.__init__():983 DEBUG # Concurrent connections allowed: True
2024-04-03T14:04:41+0000 api.remote_ispyb_connector.remote_connect():117 INFO # Created SSHTunnelForwarder
2024-04-03T14:04:41+0000 api.remote_ispyb_connector.remote_connect():123 INFO # Starting SSH server...
2024-04-03T14:04:41+0000 sshtunnel.SSHTunnelForwarder._connect_to_gateway():1400 DEBUG # Trying to log in with key: [...]
2024-04-03T14:04:41+0000 sshtunnel.SSHTunnelForwarder._get_transport():1204 DEBUG # Transport socket info: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, 0), timeout=10.0
2024-04-03T14:04:41+0000 sshtunnel.SSHTunnelForwarder._serve_forever_wrapper():1433 INFO # Opening tunnel: 0.0.0.0:35869 <> ispybdbproxy.diamond.ac.uk:4306
2024-04-03T14:04:41+0000 api.remote_ispyb_connector.remote_connect():125 INFO # Started SSH server
2024-04-03T14:04:41+0000 api.remote_ispyb_connector.remote_connect():127 INFO # Connecting to ISPyB (db_user=ispyb_api_fragalysis db_name=ispyb)...
2024-04-03T14:04:41+0000 api.remote_ispyb_connector.remote_connect():137 INFO # Connected
2024-04-03T14:04:41+0000 api.remote_ispyb_connector.__init__():58 INFO # Started remote ssh_host=ssh.diamond.ac.uk ssh_user=fragalysis-stack local_bind_port=35869
2024-04-03T14:04:41+0000 api.security.get_remote_conn():89 INFO # Got remote connector: <api.remote_ispyb_connector.SSHConnector object at 0x7fe38b61eb90>
2024-04-03T14:04:41+0000 sshtunnel.SSHTunnelForwarder.stop():1374 INFO # Closing all open connections...
2024-04-03T14:04:41+0000 sshtunnel.SSHTunnelForwarder.stop():1378 DEBUG # Listening tunnels: 0.0.0.0:35869
2024-04-03T14:04:41+0000 sshtunnel.SSHTunnelForwarder._stop_transport():1458 INFO # Shutting down tunnel: 0.0.0.0:35869 <> ispybdbproxy.diamond.ac.uk:4306 (up)
2024-04-03T14:04:41+0000 sshtunnel.SSHTunnelForwarder._serve_forever_wrapper():1439 INFO # Tunnel: 0.0.0.0:35869 <> ispybdbproxy.diamond.ac.uk:4306 released
2024-04-03T14:04:41+0000 sshtunnel.SSHTunnelForwarder._stop_transport():1474 INFO # Closing ssh transport
2024-04-03T14:04:41+0000 sshtunnel.SSHTunnelForwarder._stop_transport():1477 DEBUG # Transport is closed

Connections are generally quick to establish, with the whole transaction complete within a second or so.

[alanbchristie]

TIMEOUT

When there is a genuine connection problem with ISPyB (e.g. a timeout) we do see this handled, which will yield a TIMEOUT popup: -

2024-04-03T14:13:11+0000 api.remote_ispyb_connector.remote_connect():127 INFO # Connecting to ISPyB (db_user=ispyb_api_fragalysis db_name=ispyb)...
2024-04-03T14:13:20+0000 viewer.services.wrapper_service_query():139 ERROR # Service query 'ispyb' timed out
Traceback (most recent call last):
  File "/code/viewer/services.py", line 131, in wrapper_service_query
    result = await future
             ^^^^^^^^^^^^
asyncio.exceptions.CancelledError

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/code/viewer/services.py", line 126, in wrapper_service_query
    async with asyncio.timeout(DELAY):
  File "/usr/local/lib/python3.11/asyncio/timeouts.py", line 115, in __aexit__
    raise TimeoutError from exc_val
TimeoutError

This happens when the underlying method (responsible for checking the service) does not respond within the required period (10 Seconds)

[alanbchristie]

Why did we introduce a new TIMEOUT state as well as DEGRADED? They're effectively synonymous. The service is either DEGRADED or it isn't.

[alanbchristie]

The real concern is why we constant see DEGRADED to OK, further debug is required.

[alanbchristie]

DEGRADED

When there is a failure of the remote service its state switches to DEGRADED. In the case of ISPyB this is where it is unable to obtain a valid connection (or SSH tunnel): -

2024-04-03T14:45:30+0000 sshtunnel.SSHTunnelForwarder._serve_forever_wrapper():1433 INFO # Opening tunnel: 0.0.0.0:38703 <> ispybdbproxy.diamond.ac.uk:4306
2024-04-03T14:45:30+0000 api.remote_ispyb_connector.remote_connect():125 INFO # Started SSH server
2024-04-03T14:45:30+0000 api.remote_ispyb_connector.remote_connect():127 INFO # Connecting to ISPyB (db_user=ispyb_api_fragalysis db_name=ispyb)...
2024-04-03T14:45:30+0000 api.security.get_remote_conn():89 INFO # Got remote connector: None

This happens when the underlying method (responsible for checking the service) considers the service to unavailable.

[alanbchristie]

The majority of DEGRADED instances today were caused by the pymysql.connect() method returning (almost instantly) without having made a connection. Only very few were caused by the connection timing out (i.e. a TIMEOUT).

[alanbchristie]

Options for consideration: -

1. Remove the popups. The service is indicated by the "lamp" after all.
2. Extended timeouts (or reducing the period the services is queried). This may not help (certainly true in today's debug session).
3. Redesign. This would allow the ability to implement a low-pass-filter mechanism - e.g. a "consecutive failure/success" thresholds akin to Kubernetes probes.

[alanbchristie]

It is also clear there are "intermittent" exceptions occurring during more regularly during the day. They appear to be more regular during working hours, which indicates a load on the network or DB?

The pymysql.err.OperationalError exception manifests itself in the log with a modified "monitoring" version of the stack: -

2024-04-04T08:45:59+0000 api.security.get_remote_conn():87 ERROR # Got the following exception creating SSHConnector...
Traceback (most recent call last):
  File "/code/api/security.py", line 82, in get_remote_conn
    conn = SSHConnector(**credentials)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/code/api/remote_ispyb_connector.py", line 61, in __init__
    self.remote_connect(**creds)
  File "/code/api/remote_ispyb_connector.py", line 132, in remote_connect
    self.conn = pymysql.connect(
                ^^^^^^^^^^^^^^^^
  File "/.venv/lib/python3.11/site-packages/pymysql/connections.py", line 358, in __init__
    self.connect()
  File "/.venv/lib/python3.11/site-packages/pymysql/connections.py", line 679, in connect
    self.set_character_set(self.charset, self.collation)
  File "/.venv/lib/python3.11/site-packages/pymysql/connections.py", line 621, in set_character_set
    self._read_packet()
  File "/.venv/lib/python3.11/site-packages/pymysql/connections.py", line 739, in _read_packet
    packet_header = self._read_bytes(4)
                    ^^^^^^^^^^^^^^^^^^^
  File "/.venv/lib/python3.11/site-packages/pymysql/connections.py", line 795, in _read_bytes
    raise err.OperationalError(
pymysql.err.OperationalError: (2013, 'Lost connection to MySQL server during query')
2024-04-04T08:45:59+0000 api.security.get_remote_conn():88 INFO # Got remote connector: None

[mwinokan]

@alanbchristie says there are issues connecting to the MySQL server (out of our control), mid-query connection losses. Alan is setting timeouts.

The pop-up is reporting actual connection issues, Alan is improving the underlying logic to re-try as quickly as possible. Usually MySQL queries are resolved after a few attempts. These connection issues are most prevalent during the normal work-day. This suggests there are issues out of our control going on behind the scenes.

@Waztom to talk to James Hall, Carl Levik and to highlight this issue.

Alan suggests that there could be another layer in the bottom-end that is aware of the instability of the MySQL/ISpyB connection and doesn't throw a pup-up every time.

@matej-vavrek Simplest solution: get rid of the pop-ups, and just provide some hover-over info to report how long ago the outage happened.

New ticket to investigate the MySQL connection issues @alanbchristie to create

[alanbchristie]

Opinion at the meeting was to remove the pop-ups as the DEGRADED services already show up in the lights. Also, fixes underway in #1407 should significantly reduce the number of intermittent DEGRADED states we see.

[mwinokan]

@alanbchristie backend work is in staging but he should monitor the logs to see if things are behaving correctly. #1407 also fixed

@matej-vavrek to tackle the frontend work here

[mwinokan]

@matej-vavrek has completed the F/E work on his stack. Please push to staging