From f63f586ee816d7c461b55810a38c7e133ab50570 Mon Sep 17 00:00:00 2001 From: sanderegg <35365065+sanderegg@users.noreply.github.com> Date: Mon, 7 Jul 2025 11:46:14 +0200 Subject: [PATCH 1/7] proper configuration of engineio/socketio logger --- .../src/simcore_service_webserver/socketio/server.py | 8 +++----- 1 file changed, 3 insertions(+), 5 deletions(-) diff --git a/services/web/server/src/simcore_service_webserver/socketio/server.py b/services/web/server/src/simcore_service_webserver/socketio/server.py index 617af26072fe..b52245cc902c 100644 --- a/services/web/server/src/simcore_service_webserver/socketio/server.py +++ b/services/web/server/src/simcore_service_webserver/socketio/server.py @@ -19,17 +19,15 @@ async def _socketio_server_cleanup_ctx(app: web.Application) -> AsyncIterator[None]: - use_logger: bool | logging.Logger = _logger - # SEE https://github.com/miguelgrinberg/python-socketio/blob/v4.6.1/docs/server.rst#aiohttp server_manager = AsyncAioPikaManager( url=get_rabbitmq_settings(app).dsn, - logger=use_logger, + logger=True, ) sio_server = AsyncServer( async_mode="aiohttp", - logger=use_logger, - engineio_logger=False, + logger=True, + engineio_logger=True, client_manager=server_manager, json=JsonNamespace, ) From 7efc962698ee06fe4b8cb89620ba5264b84c58fb Mon Sep 17 00:00:00 2001 From: sanderegg <35365065+sanderegg@users.noreply.github.com> Date: Mon, 7 Jul 2025 13:44:38 +0200 Subject: [PATCH 2/7] proper configuration --- services/web/server/src/simcore_service_webserver/log.py | 4 +++- .../src/simcore_service_webserver/socketio/messages.py | 2 +- .../server/src/simcore_service_webserver/socketio/server.py | 5 +---- 3 files changed, 5 insertions(+), 6 deletions(-) diff --git a/services/web/server/src/simcore_service_webserver/log.py b/services/web/server/src/simcore_service_webserver/log.py index f1cbbada0570..2ed45c8e2884 100644 --- a/services/web/server/src/simcore_service_webserver/log.py +++ b/services/web/server/src/simcore_service_webserver/log.py @@ -14,13 +14,15 @@ "aio_pika", "aiormq", "engineio", + "engineio.server", "inotify.adapters", "gunicorn.access", "openapi_spec_validator", "servicelib.aiohttp.monitoring", + "socketio", + "socketio.server", "sqlalchemy.engine", "sqlalchemy", - "socketio", ) diff --git a/services/web/server/src/simcore_service_webserver/socketio/messages.py b/services/web/server/src/simcore_service_webserver/socketio/messages.py index 60056a2aa910..2b20fc4b5785 100644 --- a/services/web/server/src/simcore_service_webserver/socketio/messages.py +++ b/services/web/server/src/simcore_service_webserver/socketio/messages.py @@ -54,7 +54,7 @@ async def _safe_emit( room=room, ignore_queue=ignore_queue, ) - _logger.info("emitted socketio event '%s' to room '%s'", event, room) + _logger.debug("emitted socketio event '%s' to room '%s'", event, room) async def send_message_to_user( diff --git a/services/web/server/src/simcore_service_webserver/socketio/server.py b/services/web/server/src/simcore_service_webserver/socketio/server.py index b52245cc902c..4245b9502f74 100644 --- a/services/web/server/src/simcore_service_webserver/socketio/server.py +++ b/services/web/server/src/simcore_service_webserver/socketio/server.py @@ -20,10 +20,7 @@ async def _socketio_server_cleanup_ctx(app: web.Application) -> AsyncIterator[None]: # SEE https://github.com/miguelgrinberg/python-socketio/blob/v4.6.1/docs/server.rst#aiohttp - server_manager = AsyncAioPikaManager( - url=get_rabbitmq_settings(app).dsn, - logger=True, - ) + server_manager = AsyncAioPikaManager(url=get_rabbitmq_settings(app).dsn) sio_server = AsyncServer( async_mode="aiohttp", logger=True, From 0b07fba16df0dbd416b62f9659647444d240b807 Mon Sep 17 00:00:00 2001 From: sanderegg <35365065+sanderegg@users.noreply.github.com> Date: Mon, 7 Jul 2025 13:54:35 +0200 Subject: [PATCH 3/7] better logs --- .../socketio/_handlers.py | 15 ++++++++------- 1 file changed, 8 insertions(+), 7 deletions(-) diff --git a/services/web/server/src/simcore_service_webserver/socketio/_handlers.py b/services/web/server/src/simcore_service_webserver/socketio/_handlers.py index 181a24199c16..b45a0f3df4b2 100644 --- a/services/web/server/src/simcore_service_webserver/socketio/_handlers.py +++ b/services/web/server/src/simcore_service_webserver/socketio/_handlers.py @@ -74,11 +74,6 @@ async def _handler(request: web.Request) -> tuple[UserID, ProductName, str]: # REDIS wrapper with managed_resource(user_id, client_session_id, app) as resource_registry: - _logger.info( - "socketio connection from user %s", - user_id, - extra=get_log_record_extra(user_id=user_id), - ) await resource_registry.set_socket_id(socket_id) return user_id, product.name, client_session_id @@ -129,10 +124,16 @@ async def connect( user_id, product_name, client_session_id = await auth_user_handler( environ["aiohttp.request"] ) + _logger.info( + "%s successfully connected with %s", + f"{user_id=}", + f"{client_session_id=}", + extra=get_log_record_extra(user_id=user_id), + ) await _set_user_in_group_rooms(app, user_id, socket_id) - _logger.info("Sending set_heartbeat_emit_interval with %s", _EMIT_INTERVAL_S) + _logger.debug("Sending set_heartbeat_emit_interval with %s", _EMIT_INTERVAL_S) await emit( app, "SIGNAL_USER_CONNECTED", user_id, app, product_name, client_session_id @@ -170,7 +171,7 @@ async def disconnect(socket_id: SocketID, app: web.Application) -> None: with log_context( _logger, logging.INFO, - "disconnection of %s for %s", + "disconnection of %s with %s", f"{user_id=}", f"{client_session_id=}", ): From b0a5f28f3d3e3ed31dc203f94ab6f3bb7c0a7ada Mon Sep 17 00:00:00 2001 From: sanderegg <35365065+sanderegg@users.noreply.github.com> Date: Mon, 7 Jul 2025 14:01:23 +0200 Subject: [PATCH 4/7] add some more noisy stuff --- .../src/simcore_service_director_v2/core/application.py | 5 ++--- .../src/simcore_service_director/core/application.py | 6 +++++- 2 files changed, 7 insertions(+), 4 deletions(-) diff --git a/services/director-v2/src/simcore_service_director_v2/core/application.py b/services/director-v2/src/simcore_service_director_v2/core/application.py index 5031c74a6185..9dfc9ec69742 100644 --- a/services/director-v2/src/simcore_service_director_v2/core/application.py +++ b/services/director-v2/src/simcore_service_director_v2/core/application.py @@ -99,6 +99,7 @@ def _set_exception_handlers(app: FastAPI): "aio_pika", "aiormq", "httpcore", + "httpx", ) @@ -201,9 +202,7 @@ def init_app(settings: AppSettings | None = None) -> FastAPI: socketio.setup(app) notifier.setup(app) - if ( - settings.DIRECTOR_V2_COMPUTATIONAL_BACKEND.COMPUTATIONAL_BACKEND_DASK_CLIENT_ENABLED - ): + if settings.DIRECTOR_V2_COMPUTATIONAL_BACKEND.COMPUTATIONAL_BACKEND_DASK_CLIENT_ENABLED: dask_clients_pool.setup(app, settings.DIRECTOR_V2_COMPUTATIONAL_BACKEND) if computational_backend_enabled: diff --git a/services/director/src/simcore_service_director/core/application.py b/services/director/src/simcore_service_director/core/application.py index 0baa557506f6..4d38daa958e1 100644 --- a/services/director/src/simcore_service_director/core/application.py +++ b/services/director/src/simcore_service_director/core/application.py @@ -22,7 +22,11 @@ from .settings import ApplicationSettings _LOG_LEVEL_STEP = logging.CRITICAL - logging.ERROR -_NOISY_LOGGERS: Final[tuple[str]] = ("werkzeug",) +_NOISY_LOGGERS: Final[tuple[str, ...]] = ( + "httpcore", + "httpx", + "werkzeug", +) _logger = logging.getLogger(__name__) From 23f501dd889aef9e16761e46d9e4b7e5122cca28 Mon Sep 17 00:00:00 2001 From: sanderegg <35365065+sanderegg@users.noreply.github.com> Date: Mon, 7 Jul 2025 15:11:44 +0200 Subject: [PATCH 5/7] degrade log level --- .../payments/src/simcore_service_payments/api/rest/_health.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/services/payments/src/simcore_service_payments/api/rest/_health.py b/services/payments/src/simcore_service_payments/api/rest/_health.py index 948317cf883e..030d56afbdd6 100644 --- a/services/payments/src/simcore_service_payments/api/rest/_health.py +++ b/services/payments/src/simcore_service_payments/api/rest/_health.py @@ -23,9 +23,9 @@ class HealthCheckError(RuntimeError): async def healthcheck( rabbitmq_client: Annotated[ RabbitMQClient, Depends(get_rabbitmq_client_from_request) - ] + ], ) -> str: - _logger.info("Checking rabbit health check %s", rabbitmq_client.healthy) + _logger.debug("Checking rabbit health check %s", rabbitmq_client.healthy) if not rabbitmq_client.healthy: raise HealthCheckError(RABBITMQ_CLIENT_UNHEALTHY_MSG) From edbf4b136a17c358863eecf6c82b405772320c92 Mon Sep 17 00:00:00 2001 From: sanderegg <35365065+sanderegg@users.noreply.github.com> Date: Mon, 7 Jul 2025 15:11:57 +0200 Subject: [PATCH 6/7] ensure gunicorn logs are visible --- services/web/server/src/simcore_service_webserver/log.py | 7 ++----- 1 file changed, 2 insertions(+), 5 deletions(-) diff --git a/services/web/server/src/simcore_service_webserver/log.py b/services/web/server/src/simcore_service_webserver/log.py index 2ed45c8e2884..b8d3ba328b3d 100644 --- a/services/web/server/src/simcore_service_webserver/log.py +++ b/services/web/server/src/simcore_service_webserver/log.py @@ -1,6 +1,4 @@ -""" Configuration and utilities for service logging - -""" +"""Configuration and utilities for service logging""" import logging @@ -16,7 +14,6 @@ "engineio", "engineio.server", "inotify.adapters", - "gunicorn.access", "openapi_spec_validator", "servicelib.aiohttp.monitoring", "socketio", @@ -32,7 +29,7 @@ def setup_logging( slow_duration: float | None = None, log_format_local_dev_enabled: bool, logger_filter_mapping: dict, - tracing_settings: TracingSettings | None + tracing_settings: TracingSettings | None, ): # service log level logging.basicConfig(level=level) From 787df247490af3c0ecafb693de49b94a9888c884 Mon Sep 17 00:00:00 2001 From: sanderegg <35365065+sanderegg@users.noreply.github.com> Date: Mon, 7 Jul 2025 15:12:08 +0200 Subject: [PATCH 7/7] remove standard logs for health from logs --- .env-devel | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/.env-devel b/.env-devel index 1842a982b854..1825a8d7628f 100644 --- a/.env-devel +++ b/.env-devel @@ -161,7 +161,7 @@ INVITATIONS_USERNAME=admin INVITATIONS_TRACING=null LOG_FORMAT_LOCAL_DEV_ENABLED=1 -LOG_FILTER_MAPPING='{}' +LOG_FILTER_MAPPING='{"gunicorn.access":[" /v0/ ", " /v0/health "], "uvicorn.access":[" / "]}' NOTIFICATIONS_LOGLEVEL=INFO NOTIFICATIONS_TRACING=null