Slack Socket Mode fails replying to messages with "django.core.exceptions.SynchronousOnlyOperation: You cannot call this from an async context" #348

gioccher · 2024-12-14T00:33:09Z

Environment

Python version: 3.9.20
Nautobot version: 2.3.13
nautobot-chatops version: 3.1.1
Database version: MySQL 8?

Expected Behavior

chatops replies with the available commands

Observed Behavior

the following appears in the logs
django.core.exceptions.SynchronousOnlyOperation: You cannot call this from an async context - use a thread or sync_to_async.

2024-12-14 00:20:25,216 - slack_sdk.socket_mode.aiohttp - DEBUG - Received message (type: PONG, data: sdk-ping-pong:1734135625.1085894, extra: , session: s_8778481267962)
2024-12-14 00:20:27,437 - slack_sdk.socket_mode.aiohttp - DEBUG - Received message (type: PING, data: Ping from applink-10, extra: , session: s_8778481267962)
2024-12-14 00:20:30,220 - slack_sdk.socket_mode.aiohttp - DEBUG - Received message (type: PONG, data: sdk-ping-pong:1734135630.112617, extra: , session: s_8778481267962)
2024-12-14 00:20:34,562 - slack_sdk.socket_mode.aiohttp - DEBUG - Received message (type: TEXT, data: {"envelope_id":"c3653b94-b838-4a98-8926-f0ccd66f8d3e","payload":{"token":"XXX","team_id":"XXX","team_domain":"XXX","channel_id":"XXX","channel_name":"nautobot_chatops_test","user_id":"XXX","user_name":"XXX","command":"\/nautobot","text":"","api_app_id":"XXX","is_enterprise_install":"false","response_url":"https:\/\/hooks.slack.com\/commands\/XXX\/XXX\/XXX","trigger_id":"XXX.XXX.XXX"},"type":"slash_commands","accepts_response_payload":true}, extra: , session: s_8778481267962)
2024-12-14 00:20:34,562 - slack_sdk.socket_mode.aiohttp - DEBUG - A new message enqueued (current queue size: 1, session: s_8778481267962)
2024-12-14 00:20:34,562 - slack_sdk.socket_mode.aiohttp - DEBUG - Message processing started (type: slash_commands, envelope_id: c3653b94-b838-4a98-8926-f0ccd66f8d3e, session: s_8778481267962)
2024-12-14 00:20:34,562 - slack_sdk.socket_mode.aiohttp - DEBUG - Worker received a socket request.
2024-12-14 00:20:34,562 - slack_sdk.socket_mode.aiohttp - DEBUG - Received slash command.
2024-12-14 00:20:34,562 - slack_sdk.socket_mode.aiohttp - DEBUG - Sending a message: {"envelope_id": "c3653b94-b838-4a98-8926-f0ccd66f8d3e"} from session: s_8778481267962
2024-12-14 00:20:34,562 - slack_sdk.socket_mode.aiohttp - DEBUG - Processing slash command.
2024-12-14 00:20:34,569 - slack_sdk.socket_mode.aiohttp - ERROR - Failed to run a request listener: You cannot call this from an async context - use a thread or sync_to_async., session: s_8778481267962
Traceback (most recent call last):
  File "/opt/nautobot/.local/lib/python3.9/site-packages/slack_sdk/socket_mode/async_client.py", line 156, in run_message_listeners
    await listener(self, request)  # type: ignore
  File "/opt/nautobot/.local/lib/python3.9/site-packages/nautobot_chatops/sockets/slack.py", line 36, in process
    await process_slash_command(client, req)
  File "/opt/nautobot/.local/lib/python3.9/site-packages/nautobot_chatops/sockets/slack.py", line 74, in process_slash_command
    registry = get_commands_registry()
  File "/opt/nautobot/.local/lib/python3.9/site-packages/nautobot_chatops/workers/__init__.py", line 60, in get_commands_registry
    from nautobot_chatops.integrations.utils import (  # pylint: disable=import-outside-toplevel
  File "/opt/nautobot/.local/lib/python3.9/site-packages/nautobot_chatops/integrations/utils.py", line 30, in <module>
    ENABLED_INTEGRATIONS = set(_each_enabled_integration())
  File "/opt/nautobot/.local/lib/python3.9/site-packages/nautobot_chatops/integrations/utils.py", line 26, in _each_enabled_integration
    if get_app_settings_or_config("nautobot_chatops", f"enable_{name}"):
  File "/usr/local/lib/python3.9/site-packages/nautobot/apps/config.py", line 12, in get_app_settings_or_config
    return getattr(config, f"{app_name}__{variable_name}")
  File "/usr/local/lib/python3.9/site-packages/django/utils/functional.py", line 268, in inner
    return func(_wrapped, *args)
  File "/usr/local/lib/python3.9/site-packages/constance/base.py", line 19, in __getattr__
    result = self._backend.get(key)
  File "/usr/local/lib/python3.9/site-packages/constance/backends/database.py", line 80, in get
    value = self._model._default_manager.get(key=key).value
  File "/usr/local/lib/python3.9/site-packages/django/db/models/manager.py", line 87, in manager_method
    return getattr(self.get_queryset(), name)(*args, **kwargs)
  File "/usr/local/lib/python3.9/site-packages/django/db/models/query.py", line 633, in get
    num = len(clone)
  File "/usr/local/lib/python3.9/site-packages/django/db/models/query.py", line 380, in __len__
    self._fetch_all()
  File "/usr/local/lib/python3.9/site-packages/django/db/models/query.py", line 1881, in _fetch_all
    self._result_cache = list(self._iterable_class(self))
  File "/usr/local/lib/python3.9/site-packages/django/db/models/query.py", line 91, in __iter__
    results = compiler.execute_sql(
  File "/usr/local/lib/python3.9/site-packages/django/db/models/sql/compiler.py", line 1560, in execute_sql
    cursor = self.connection.cursor()
  File "/usr/local/lib/python3.9/site-packages/django/utils/asyncio.py", line 24, in inner
    raise SynchronousOnlyOperation(message)
django.core.exceptions.SynchronousOnlyOperation: You cannot call this from an async context - use a thread or sync_to_async.
2024-12-14 00:20:34,569 - slack_sdk.socket_mode.aiohttp - DEBUG - Message processing completed (type: slash_commands, envelope_id: c3653b94-b838-4a98-8926-f0ccd66f8d3e, session: s_8778481267962)
2024-12-14 00:20:35,219 - slack_sdk.socket_mode.aiohttp - DEBUG - Received message (type: PONG, data: sdk-ping-pong:1734135635.1144571, extra: , session: s_8778481267962)
2024-12-14 00:20:37,484 - slack_sdk.socket_mode.aiohttp - DEBUG - Received message (type: PING, data: Ping from applink-10, extra: , session: s_8778481267962)
2024-12-14 00:20:40,221 - slack_sdk.socket_mode.aiohttp - DEBUG - Received message (type: PONG, data: sdk-ping-pong:1734135640.1165822, extra: , session: s_8778481267962)
2024-12-14 00:20:45,224 - slack_sdk.socket_mode.aiohttp - DEBUG - Received message (type: PONG, data: sdk-ping-pong:1734135645.1191676, extra: , session: s_8778481267962)
2024-12-14 00:20:47,497 - slack_sdk.socket_mode.aiohttp - DEBUG - Received message (type: PING, data: Ping from applink-10, extra: , session: s_8778481267962)

Steps to Reproduce

start nautobot-server start_slack_socket
type /nautobot in slack

The text was updated successfully, but these errors were encountered:

smk4664 · 2024-12-14T01:35:00Z

I will look at this next week.

smk4664 · 2024-12-18T15:56:01Z

Thank you @gioccher, I was able to find and resolve the issue. I will be putting a PR in, followed by a patch release.

gioccher · 2024-12-19T21:09:38Z

Thank you @smk4664 ! I can confirm it solves the issue I reported - but I stumbled on something else that might be related: chatops in slack mode is not recovering from a closed database connection. The rest of nautobot was working fine, but chatops would log the following and not respond to the command:

2024-12-19 19:19:41,160 - slack_sdk.socket_mode.aiohttp - DEBUG - Received message (type: TEXT, data: {"envelope_id":"bafaf21e-a091-4240-9241-14b5ff5f03f8","payload":{"token":"XXX","team_id":"XXX","team_domain":"XXX","channel_id":"XXX","channel_name":"XXX","user_id":"XXX","user_name":"XXX","command":"\/whatever","text":"","api_app_id":"XXX","is_enterprise_install":"false","response_url":"XXX","trigger_id":"XXX"},"type":"slash_commands","accepts_response_payload":true}, extra: , session: s_8727666920834)
2024-12-19 19:19:41,161 - slack_sdk.socket_mode.aiohttp - DEBUG - A new message enqueued (current queue size: 1, session: s_8727666920834)
2024-12-19 19:19:41,161 - slack_sdk.socket_mode.aiohttp - DEBUG - Message processing started (type: slash_commands, envelope_id: bafaf21e-a091-4240-9241-14b5ff5f03f8, session: s_8727666920834)
2024-12-19 19:19:41,161 - slack_sdk.socket_mode.aiohttp - DEBUG - Worker received a socket request.
2024-12-19 19:19:41,161 - slack_sdk.socket_mode.aiohttp - DEBUG - Received slash command.
2024-12-19 19:19:41,161 - slack_sdk.socket_mode.aiohttp - DEBUG - Sending a message: {"envelope_id": "bafaf21e-a091-4240-9241-14b5ff5f03f8"} from session: s_8727666920834
2024-12-19 19:19:41,161 - slack_sdk.socket_mode.aiohttp - DEBUG - Processing slash command.
2024-12-19 19:19:41,162 - slack_sdk.socket_mode.aiohttp - ERROR - Failed to run a request listener: (2006, 'Server has gone away'), session: s_8727666920834
Traceback (most recent call last):
  File "/usr/local/lib/python3.9/site-packages/django/db/backends/utils.py", line 89, in _execute
    return self.cursor.execute(sql, params)
  File "/usr/local/lib/python3.9/site-packages/django/db/backends/mysql/base.py", line 75, in execute
    return self.cursor.execute(query, args)
  File "/usr/local/lib/python3.9/site-packages/MySQLdb/cursors.py", line 179, in execute
    res = self._query(mogrified_query)
  File "/usr/local/lib/python3.9/site-packages/MySQLdb/cursors.py", line 330, in _query
    db.query(q)
  File "/usr/local/lib/python3.9/site-packages/MySQLdb/connections.py", line 265, in query
    _mysql.connection.query(self, query)
MySQLdb.OperationalError: (2006, 'Server has gone away')

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

Traceback (most recent call last):
  File "/opt/nautobot/.local/lib/python3.9/site-packages/slack_sdk/socket_mode/async_client.py", line 156, in run_message_listeners
    await listener(self, request)  # type: ignore
  File "/opt/nautobot/.local/lib/python3.9/site-packages/nautobot_chatops/sockets/slack.py", line 37, in process
    await process_slash_command(client, req)
  File "/opt/nautobot/.local/lib/python3.9/site-packages/nautobot_chatops/sockets/slack.py", line 80, in process_slash_command
    return await socket_check_and_enqueue_command(registry, command, subcommand, params, context, SlackDispatcher)
  File "/usr/local/lib/python3.9/site-packages/asgiref/sync.py", line 468, in __call__
    ret = await asyncio.shield(exec_coro)
  File "/usr/local/lib/python3.9/concurrent/futures/thread.py", line 58, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/usr/local/lib/python3.9/site-packages/asgiref/sync.py", line 522, in thread_handler
    return func(*args, **kwargs)
  File "/opt/nautobot/.local/lib/python3.9/site-packages/nautobot_chatops/utils.py", line 119, in socket_check_and_enqueue_command
    return check_and_enqueue_command(*args, **kwargs)
  File "/opt/nautobot/.local/lib/python3.9/site-packages/nautobot_chatops/utils.py", line 157, in check_and_enqueue_command
    command_log = create_command_log(dispatcher, registry, command, subcommand, params)
  File "/opt/nautobot/.local/lib/python3.9/site-packages/nautobot_chatops/utils.py", line 112, in create_command_log
    nautobot_user=dispatcher.user,
  File "/opt/nautobot/.local/lib/python3.9/site-packages/nautobot_chatops/dispatchers/base.py", line 52, in user
    return ChatOpsAccountLink.objects.get(
  File "/usr/local/lib/python3.9/site-packages/django/db/models/manager.py", line 87, in manager_method
    return getattr(self.get_queryset(), name)(*args, **kwargs)
  File "/usr/local/lib/python3.9/site-packages/django/db/models/query.py", line 633, in get
    num = len(clone)
  File "/usr/local/lib/python3.9/site-packages/django/db/models/query.py", line 380, in __len__
    self._fetch_all()
  File "/usr/local/lib/python3.9/site-packages/django/db/models/query.py", line 1881, in _fetch_all
    self._result_cache = list(self._iterable_class(self))
  File "/usr/local/lib/python3.9/site-packages/django/db/models/query.py", line 91, in __iter__
    results = compiler.execute_sql(
  File "/usr/local/lib/python3.9/site-packages/django/db/models/sql/compiler.py", line 1562, in execute_sql
    cursor.execute(sql, params)
  File "/usr/local/lib/python3.9/site-packages/django/db/backends/utils.py", line 102, in execute
    return super().execute(sql, params)
  File "/usr/local/lib/python3.9/site-packages/django/db/backends/utils.py", line 67, in execute
    return self._execute_with_wrappers(
  File "/usr/local/lib/python3.9/site-packages/django/db/backends/utils.py", line 80, in _execute_with_wrappers
    return executor(sql, params, many, context)
  File "/usr/local/lib/python3.9/site-packages/django/db/backends/utils.py", line 89, in _execute
    return self.cursor.execute(sql, params)
  File "/usr/local/lib/python3.9/site-packages/django/db/utils.py", line 91, in __exit__
    raise dj_exc_value.with_traceback(traceback) from exc_value
  File "/usr/local/lib/python3.9/site-packages/django/db/backends/utils.py", line 89, in _execute
    return self.cursor.execute(sql, params)
  File "/usr/local/lib/python3.9/site-packages/django/db/backends/mysql/base.py", line 75, in execute
    return self.cursor.execute(query, args)
  File "/usr/local/lib/python3.9/site-packages/MySQLdb/cursors.py", line 179, in execute
    res = self._query(mogrified_query)
  File "/usr/local/lib/python3.9/site-packages/MySQLdb/cursors.py", line 330, in _query
    db.query(q)
  File "/usr/local/lib/python3.9/site-packages/MySQLdb/connections.py", line 265, in query
    _mysql.connection.query(self, query)
django.db.utils.OperationalError: (2006, 'Server has gone away')
2024-12-19 19:19:41,163 - slack_sdk.socket_mode.aiohttp - DEBUG - Message processing completed (type: slash_commands, envelope_id: bafaf21e-a091-4240-9241-14b5ff5f03f8, session: s_8727666920834)

I've done some light reading about this, and it might be enough to replace @sync_to_async with @database_sync_to_async in sockets/slack.py and nautobot_chatops/utils.py
https://channels.readthedocs.io/en/latest/topics/databases.html#database-sync-to-async
https://stackoverflow.com/a/68938365

smk4664 · 2024-12-19T21:15:24Z

@gioccher What is the CONN_MAX_AGE set to? I did some light reading of the Channels documentation, and using that might require installing Channels, which will likely not be compatible with Nautobot. I originally looked into Channels, but decided against it for the reason of being required to use their ASGI and their runserver.

smk4664 · 2024-12-19T21:19:09Z

Also, could we try CONN_HEALTH_CHECKS=True in the Database properties? https://stackoverflow.com/a/77009905

I wonder if that would help.

gioccher · 2024-12-19T21:23:30Z

I'm not setting CONN_MAX_AGE explicitly, I'm using the helm chart and it isn't one of the nautobot.db. values we can modify https://docs.nautobot.com/projects/helm-charts/en/stable/configuration/reference/#nautobot-values
But looking at https://docs.nautobot.com/projects/core/en/stable/user-guide/administration/configuration/settings/#database_routers it would appear that CONN_MAX_AGE default is 300.
I retried sending the slack command way after 5 minutes, and it would still fail.

I'll try to see how to add CONN_HEALTH_CHECKS to my deployment. Still wondering why it wouldn't be required for nautobot, but would be required for chatops.

smk4664 · 2024-12-19T21:40:29Z

I believe the issue is with the Slack Socket mode trying to maintain a persistent connection with the database. I will use your settings to try to replicate the issue on my end.

gioccher · 2024-12-19T21:48:41Z

Thanks, and I've added DATABASES["default"]["CONN_HEALTH_CHECKS"] = True to nautobot's config. I'll try to reproduce the "Server has gone away" condition... or wait a few days and see if it still works

smk4664 mentioned this issue Dec 18, 2024

Resolve synchronous function running in the Async Slack Socket Mode #350

Merged

smk4664 self-assigned this Dec 18, 2024

smk4664 added type: bug bug Something isn't working labels Dec 18, 2024

smk4664 closed this as completed in #350 Dec 18, 2024

smk4664 mentioned this issue Dec 19, 2024

Release v3.1.2 #352

Merged

This was referenced Dec 20, 2024

### Environment #354

Closed

Slack Socket mode does not auto-reconnect to MySQL #355

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Slack Socket Mode fails replying to messages with "django.core.exceptions.SynchronousOnlyOperation: You cannot call this from an async context" #348

Slack Socket Mode fails replying to messages with "django.core.exceptions.SynchronousOnlyOperation: You cannot call this from an async context" #348

gioccher commented Dec 14, 2024

smk4664 commented Dec 14, 2024

smk4664 commented Dec 18, 2024

gioccher commented Dec 19, 2024 •

edited

Loading

smk4664 commented Dec 19, 2024

smk4664 commented Dec 19, 2024

gioccher commented Dec 19, 2024

smk4664 commented Dec 19, 2024

gioccher commented Dec 19, 2024

Slack Socket Mode fails replying to messages with "django.core.exceptions.SynchronousOnlyOperation: You cannot call this from an async context" #348

Slack Socket Mode fails replying to messages with "django.core.exceptions.SynchronousOnlyOperation: You cannot call this from an async context" #348

Comments

gioccher commented Dec 14, 2024

Environment

Expected Behavior

Observed Behavior

Steps to Reproduce

smk4664 commented Dec 14, 2024

smk4664 commented Dec 18, 2024

gioccher commented Dec 19, 2024 • edited Loading

smk4664 commented Dec 19, 2024

smk4664 commented Dec 19, 2024

gioccher commented Dec 19, 2024

smk4664 commented Dec 19, 2024

gioccher commented Dec 19, 2024

gioccher commented Dec 19, 2024 •

edited

Loading