From 88c3b1a78e8507deeae7f53ba7a0d9e2d9b501be Mon Sep 17 00:00:00 2001 From: nickpetrovic <4001122+nickpetrovic@users.noreply.github.com> Date: Sat, 22 Feb 2025 15:39:25 -0500 Subject: [PATCH] Add logging observability (#1999) --- compose.full.swarm.yaml | 33 +++++++ compose.full.yaml | 33 +++++++ docker/fluent-bit/fluent-bit.conf | 26 ++++++ docker/fluent-bit/parsers.conf | 3 + py/core/main/app_entry.py | 19 ++-- py/core/utils/logging_config.py | 150 ++++++++++++++++-------------- py/pyproject.toml | 1 + py/uv.lock | 13 ++- 8 files changed, 196 insertions(+), 82 deletions(-) create mode 100644 docker/fluent-bit/fluent-bit.conf create mode 100644 docker/fluent-bit/parsers.conf diff --git a/compose.full.swarm.yaml b/compose.full.swarm.yaml index b13bfa663..d2591cc5c 100644 --- a/compose.full.swarm.yaml +++ b/compose.full.swarm.yaml @@ -246,6 +246,7 @@ services: # R2R - R2R_LOG_LEVEL=${R2R_LOG_LEVEL:-INFO} + - R2R_LOG_CONSOLE_FORMATTER=${R2R_LOG_CONSOLE_FORMATTER:-json} - R2R_CONFIG_NAME=${R2R_CONFIG_NAME:-} - R2R_CONFIG_PATH=${R2R_CONFIG_PATH:-} - R2R_PROJECT_NAME=${R2R_PROJECT_NAME:-r2r_default} @@ -376,6 +377,12 @@ services: rollback_config: parallelism: 1 delay: 30s + logging: + driver: fluentd + options: + fluentd-address: host.docker.internal:24224 + fluentd-sub-second-precision: "true" + tag: backend r2r-dashboard: image: ${R2R_DASHBOARD_IMAGE:-emrgntcmplxty/r2r-dashboard:latest} @@ -388,3 +395,29 @@ services: replicas: 1 restart_policy: condition: on-failure + + fluent-bit: + image: fluent/fluent-bit:latest + volumes: + - ./docker/fluent-bit:/fluent-bit/etc:ro + ports: + - "24224:24224" + depends_on: + - victoria-logs + + grafana: + image: grafana/grafana:latest + ports: + - "3001:3000" + env_file: + - .env + volumes: + - ./.data/grafana:/var/lib/grafana + + victoria-logs: + image: victoriametrics/victoria-logs:v1.10.1-victorialogs + ports: + - "9428:9428" + volumes: + - ./.data/victoria-logs:/data + command: -storageDataPath=/data -retentionPeriod=60d diff --git a/compose.full.yaml b/compose.full.yaml index 315b2a5e3..f309c2cbc 100644 --- a/compose.full.yaml +++ b/compose.full.yaml @@ -262,6 +262,7 @@ services: # R2R - R2R_LOG_LEVEL=${R2R_LOG_LEVEL:-INFO} + - R2R_LOG_CONSOLE_FORMATTER=${R2R_LOG_CONSOLE_FORMATTER:-json} - R2R_CONFIG_NAME=${R2R_CONFIG_NAME:-} - R2R_CONFIG_PATH=${R2R_CONFIG_PATH:-} - R2R_PROJECT_NAME=${R2R_PROJECT_NAME:-r2r_default} @@ -384,6 +385,12 @@ services: condition: service_healthy graph_clustering: condition: service_healthy + logging: + driver: fluentd + options: + fluentd-address: host.docker.internal:24224 + fluentd-sub-second-precision: "true" + tag: backend r2r-dashboard: image: ${R2R_DASHBOARD_IMAGE:-emrgntcmplxty/r2r-dashboard:latest} @@ -392,3 +399,29 @@ services: - NEXT_PUBLIC_HATCHET_DASHBOARD_URL=${HATCHET_DASHBOARD_URL:-http://localhost:${R2R_HATCHET_DASHBOARD_PORT:-7274}} ports: - "${R2R_DASHBOARD_PORT:-7273}:3000" + + fluent-bit: + image: fluent/fluent-bit:latest + volumes: + - ./docker/fluent-bit:/fluent-bit/etc:ro + ports: + - "24224:24224" + depends_on: + - victoria-logs + + grafana: + image: grafana/grafana:latest + ports: + - "3001:3000" + env_file: + - .env + volumes: + - ./.data/grafana:/var/lib/grafana + + victoria-logs: + image: victoriametrics/victoria-logs:v1.10.1-victorialogs + ports: + - "9428:9428" + volumes: + - ./.data/victoria-logs:/data + command: -storageDataPath=/data -retentionPeriod=60d diff --git a/docker/fluent-bit/fluent-bit.conf b/docker/fluent-bit/fluent-bit.conf new file mode 100644 index 000000000..57afb00fd --- /dev/null +++ b/docker/fluent-bit/fluent-bit.conf @@ -0,0 +1,26 @@ +[SERVICE] + Flush 1 + Daemon Off + Log_Level info + Parsers_File parsers.conf + +[INPUT] + Tag backend + Name forward + Listen 0.0.0.0 + Port 24224 + +[FILTER] + Match backend + Name parser + Key_Name log + Parser json + +[OUTPUT] + Match backend + Name http + host host.docker.internal + port 9428 + uri /insert/jsonline?_stream_fields=log&_msg_field=msg,message&_time_field=date + format json_lines + json_date_format iso8601 diff --git a/docker/fluent-bit/parsers.conf b/docker/fluent-bit/parsers.conf new file mode 100644 index 000000000..b61491c96 --- /dev/null +++ b/docker/fluent-bit/parsers.conf @@ -0,0 +1,3 @@ +[PARSER] + Name json + Format json diff --git a/py/core/main/app_entry.py b/py/core/main/app_entry.py index 83cefc8bd..51689b257 100644 --- a/py/core/main/app_entry.py +++ b/py/core/main/app_entry.py @@ -1,4 +1,5 @@ import os +import logging from contextlib import asynccontextmanager from typing import Optional @@ -12,7 +13,7 @@ from .assembly import R2RBuilder, R2RConfig -logger, log_file = configure_logging() +log_file = configure_logging() # Global scheduler scheduler = AsyncIOScheduler() @@ -72,23 +73,23 @@ async def create_r2r_app( host = os.getenv("R2R_HOST", os.getenv("HOST", "0.0.0.0")) port = int(os.getenv("R2R_PORT", "7272")) -logger.info( +logging.info( f"Environment R2R_CONFIG_NAME: {'None' if config_name is None else config_name}" ) -logger.info( +logging.info( f"Environment R2R_CONFIG_PATH: {'None' if config_path is None else config_path}" ) -logger.info(f"Environment R2R_PROJECT_NAME: {os.getenv('R2R_PROJECT_NAME')}") +logging.info(f"Environment R2R_PROJECT_NAME: {os.getenv('R2R_PROJECT_NAME')}") -logger.info(f"Environment R2R_POSTGRES_HOST: {os.getenv('R2R_POSTGRES_HOST')}") -logger.info( +logging.info(f"Environment R2R_POSTGRES_HOST: {os.getenv('R2R_POSTGRES_HOST')}") +logging.info( f"Environment R2R_POSTGRES_DBNAME: {os.getenv('R2R_POSTGRES_DBNAME')}" ) -logger.info(f"Environment R2R_POSTGRES_PORT: {os.getenv('R2R_POSTGRES_PORT')}") -logger.info( +logging.info(f"Environment R2R_POSTGRES_PORT: {os.getenv('R2R_POSTGRES_PORT')}") +logging.info( f"Environment R2R_POSTGRES_PASSWORD: {os.getenv('R2R_POSTGRES_PASSWORD')}" ) -logger.info( +logging.info( f"Environment R2R_PROJECT_NAME: {os.getenv('R2R_PR2R_PROJECT_NAME')}" ) diff --git a/py/core/utils/logging_config.py b/py/core/utils/logging_config.py index 2337d2885..c2a76d14d 100644 --- a/py/core/utils/logging_config.py +++ b/py/core/utils/logging_config.py @@ -70,82 +70,88 @@ def filter(self, record: logging.LogRecord) -> bool: return True -def configure_logging(): - # Read the desired log level from the environment (default to DEBUG) - log_level = os.environ.get("R2R_LOG_LEVEL", "INFO").upper() - - # Create a logs directory if it does not already exist - log_dir = Path.cwd() / "logs" - log_dir.mkdir(exist_ok=True) - - log_config = { - "version": 1, - "disable_existing_loggers": False, - "filters": { - "http_status_filter": { - "()": HTTPStatusFilter, - } +log_level = os.environ.get("R2R_LOG_LEVEL", "INFO").upper() +log_console_formatter = os.environ.get("R2R_LOG_CONSOLE_FORMATTER", "colored").lower() # colored or json + +log_dir = Path.cwd() / "logs" +log_dir.mkdir(exist_ok=True) +log_file = log_dir / "app.log" + +log_config = { + "version": 1, + "disable_existing_loggers": False, + "filters": { + "http_status_filter": { + "()": HTTPStatusFilter, + } + }, + "formatters": { + "default": { + "format": "%(asctime)s - %(name)s - %(levelname)s - %(message)s", + "datefmt": "%Y-%m-%d %H:%M:%S", }, - "formatters": { - "default": { - "format": "%(asctime)s - %(name)s - %(levelname)s - %(message)s", - "datefmt": "%Y-%m-%d %H:%M:%S", - }, - "colored": { - "()": "colorlog.ColoredFormatter", - "format": "%(asctime)s - %(log_color)s%(levelname)s%(reset)s - %(message)s", - "datefmt": "%Y-%m-%d %H:%M:%S", - "log_colors": { - "DEBUG": "white", - "INFO": "green", - "WARNING": "yellow", - "ERROR": "red", - "CRITICAL": "bold_red", - }, + "colored": { + "()": "colorlog.ColoredFormatter", + "format": "%(asctime)s - %(log_color)s%(levelname)s%(reset)s - %(message)s", + "datefmt": "%Y-%m-%d %H:%M:%S", + "log_colors": { + "DEBUG": "white", + "INFO": "green", + "WARNING": "yellow", + "ERROR": "red", + "CRITICAL": "bold_red", }, }, - "handlers": { - "file": { - "class": "logging.handlers.RotatingFileHandler", - "formatter": "colored", - "filename": str(log_dir / "app.log"), - "maxBytes": 10485760, # 10MB - "backupCount": 5, - "filters": ["http_status_filter"], - "level": log_level, # Set handler level based on the environment variable - }, - "console": { - "class": "logging.StreamHandler", - "formatter": "colored", - "stream": sys.stdout, - "filters": ["http_status_filter"], - "level": log_level, # Set handler level based on the environment variable - }, + "json": { + "()": "pythonjsonlogger.json.JsonFormatter", + "format": "%(name)s %(levelname)s %(message)s", # these become keys in the JSON log + "rename_fields": {"asctime": "time", "levelname": "level", "name": "logger"}, }, - "loggers": { - "": { # Root logger - "handlers": ["console", "file"], - "level": log_level, # Set logger level based on the environment variable - }, - "uvicorn": { - "handlers": ["console", "file"], - "level": log_level, - "propagate": False, - }, - "uvicorn.error": { - "handlers": ["console", "file"], - "level": log_level, - "propagate": False, - }, - "uvicorn.access": { - "handlers": ["console", "file"], - "level": log_level, - "propagate": False, - }, + }, + "handlers": { + "file": { + "class": "logging.handlers.RotatingFileHandler", + "formatter": "colored", + "filename": log_file, + "maxBytes": 10485760, # 10MB + "backupCount": 5, + "filters": ["http_status_filter"], + "level": log_level, # Set handler level based on the environment variable }, - } + "console": { + "class": "logging.StreamHandler", + "formatter": log_console_formatter, + "stream": sys.stdout, + "filters": ["http_status_filter"], + "level": log_level, # Set handler level based on the environment variable + }, + }, + "loggers": { + "": { # Root logger + "handlers": ["console", "file"], + "level": log_level, # Set logger level based on the environment variable + }, + "uvicorn": { + "handlers": ["console", "file"], + "level": log_level, + "propagate": False, + }, + "uvicorn.error": { + "handlers": ["console", "file"], + "level": log_level, + "propagate": False, + }, + "uvicorn.access": { + "handlers": ["console", "file"], + "level": log_level, + "propagate": False, + }, + }, +} +def configure_logging() -> Path: logging.config.dictConfig(log_config) - logger = logging.getLogger() - logger.info(f"Logging is configured at {log_level} level.") - return logger, Path(log_config["handlers"]["file"]["filename"]) + + logging.info(f"Logging is configured at {log_level} level.") + + return log_file diff --git a/py/pyproject.toml b/py/pyproject.toml index bc087faab..10917bebc 100644 --- a/py/pyproject.toml +++ b/py/pyproject.toml @@ -27,6 +27,7 @@ dependencies = [ "types-aiofiles >=24.1.0.20240626,<25.0.0", "typing-extensions >=4.12.2,<5.0.0", "pydantic>=2.10.6", + "python-json-logger>=3.2.1", ] [project.optional-dependencies] diff --git a/py/uv.lock b/py/uv.lock index 0148b7059..63750b443 100644 --- a/py/uv.lock +++ b/py/uv.lock @@ -2830,6 +2830,15 @@ wheels = [ { url = "https://files.pythonhosted.org/packages/29/31/9b360138f4e4035ee9dac4fe1132b6437bd05751aaf1db2a2d83dc45db5f/python_http_client-3.3.7-py3-none-any.whl", hash = "sha256:ad371d2bbedc6ea15c26179c6222a78bc9308d272435ddf1d5c84f068f249a36", size = 8352 }, ] +[[package]] +name = "python-json-logger" +version = "3.2.1" +source = { registry = "https://pypi.org/simple" } +sdist = { url = "https://files.pythonhosted.org/packages/e3/c4/358cd13daa1d912ef795010897a483ab2f0b41c9ea1b35235a8b2f7d15a7/python_json_logger-3.2.1.tar.gz", hash = "sha256:8eb0554ea17cb75b05d2848bc14fb02fbdbd9d6972120781b974380bfa162008", size = 16287 } +wheels = [ + { url = "https://files.pythonhosted.org/packages/4b/72/2f30cf26664fcfa0bd8ec5ee62ec90c03bd485e4a294d92aabc76c5203a5/python_json_logger-3.2.1-py3-none-any.whl", hash = "sha256:cdc17047eb5374bd311e748b42f99d71223f3b0e186f4206cc5d52aefe85b090", size = 14924 }, +] + [[package]] name = "python-multipart" version = "0.0.18" @@ -2891,7 +2900,7 @@ wheels = [ [[package]] name = "r2r" -version = "3.4.1" +version = "3.4.2" source = { editable = "." } dependencies = [ { name = "aiofiles" }, @@ -2903,6 +2912,7 @@ dependencies = [ { name = "psycopg-binary" }, { name = "pydantic" }, { name = "python-dotenv" }, + { name = "python-json-logger" }, { name = "requests" }, { name = "toml" }, { name = "types-aiofiles" }, @@ -3035,6 +3045,7 @@ requires-dist = [ { name = "pypdf2", marker = "extra == 'core'", specifier = ">=3.0.1,<4.0.0" }, { name = "python-docx", marker = "extra == 'core'", specifier = ">=1.1.0,<2.0.0" }, { name = "python-dotenv", specifier = ">=1.0.1,<2.0.0" }, + { name = "python-json-logger", specifier = ">=3.2.1" }, { name = "python-multipart", marker = "extra == 'core'", specifier = ">=0.0.9,<0.0.19" }, { name = "python-pptx", marker = "extra == 'core'", specifier = ">=1.0.1,<2.0.0" }, { name = "pyyaml", marker = "extra == 'core'", specifier = ">=6.0.1,<7.0.0" },