Refactor logging system to use custom logger across the codebase

This commit is contained in:
Ori Kotek
2023-10-16 14:56:00 +03:00
parent 41166dc271
commit c324d88be3
32 changed files with 340 additions and 311 deletions

View File

@ -1,9 +1,7 @@
import copy
import hashlib
import json
import logging
import os
import sys
import time
import jwt
@ -18,9 +16,10 @@ from starlette_context.middleware import RawContextMiddleware
from pr_agent.agent.pr_agent import PRAgent
from pr_agent.config_loader import get_settings, global_settings
from pr_agent.log import LoggingFormat, get_logger, setup_logger
from pr_agent.secret_providers import get_secret_provider
logging.basicConfig(stream=sys.stdout, level=logging.INFO)
setup_logger(fmt=LoggingFormat.JSON)
router = APIRouter()
secret_provider = get_secret_provider()
@ -49,7 +48,7 @@ async def get_bearer_token(shared_secret: str, client_key: str):
bearer_token = response.json()["access_token"]
return bearer_token
except Exception as e:
logging.error(f"Failed to get bearer token: {e}")
get_logger().error(f"Failed to get bearer token: {e}")
raise e
@router.get("/")
@ -60,7 +59,7 @@ async def handle_manifest(request: Request, response: Response):
manifest = manifest.replace("app_key", get_settings().bitbucket.app_key)
manifest = manifest.replace("base_url", get_settings().bitbucket.base_url)
except:
logging.error("Failed to replace api_key in Bitbucket manifest, trying to continue")
get_logger().error("Failed to replace api_key in Bitbucket manifest, trying to continue")
manifest_obj = json.loads(manifest)
return JSONResponse(manifest_obj)
@ -92,7 +91,7 @@ async def handle_github_webhooks(background_tasks: BackgroundTasks, request: Req
comment_body = data["data"]["comment"]["content"]["raw"]
await agent.handle_request(pr_url, comment_body)
except Exception as e:
logging.error(f"Failed to handle webhook: {e}")
get_logger().error(f"Failed to handle webhook: {e}")
background_tasks.add_task(inner)
return "OK"
@ -115,7 +114,7 @@ async def handle_installed_webhooks(request: Request, response: Response):
}
secret_provider.store_secret(username, json.dumps(secrets))
except Exception as e:
logging.error(f"Failed to register user: {e}")
get_logger().error(f"Failed to register user: {e}")
return JSONResponse({"error": "Unable to register user"}, status_code=500)
@router.post("/uninstalled")

View File

@ -1,6 +1,4 @@
import copy
import logging
import sys
from enum import Enum
from json import JSONDecodeError
@ -12,9 +10,10 @@ from starlette_context import context
from starlette_context.middleware import RawContextMiddleware
from pr_agent.agent.pr_agent import PRAgent
from pr_agent.config_loader import global_settings, get_settings
from pr_agent.config_loader import get_settings, global_settings
from pr_agent.log import get_logger, setup_logger
logging.basicConfig(stream=sys.stdout, level=logging.DEBUG)
setup_logger()
router = APIRouter()
@ -35,7 +34,7 @@ class Item(BaseModel):
@router.post("/api/v1/gerrit/{action}")
async def handle_gerrit_request(action: Action, item: Item):
logging.debug("Received a Gerrit request")
get_logger().debug("Received a Gerrit request")
context["settings"] = copy.deepcopy(global_settings)
if action == Action.ask:
@ -54,7 +53,7 @@ async def get_body(request):
try:
body = await request.json()
except JSONDecodeError as e:
logging.error("Error parsing request body", e)
get_logger().error("Error parsing request body", e)
return {}
return body

View File

@ -1,6 +1,4 @@
import copy
import logging
import sys
import os
import time
from typing import Any, Dict
@ -16,9 +14,11 @@ from pr_agent.algo.utils import update_settings_from_args
from pr_agent.config_loader import get_settings, global_settings
from pr_agent.git_providers import get_git_provider
from pr_agent.git_providers.utils import apply_repo_settings
from pr_agent.log import LoggingFormat, get_logger, setup_logger
from pr_agent.servers.utils import verify_signature
logging.basicConfig(stream=sys.stdout, level=logging.INFO)
setup_logger(fmt=LoggingFormat.JSON)
router = APIRouter()
@ -29,11 +29,11 @@ async def handle_github_webhooks(request: Request, response: Response):
Verifies the request signature, parses the request body, and passes it to the handle_request function for further
processing.
"""
logging.debug("Received a GitHub webhook")
get_logger().debug("Received a GitHub webhook")
body = await get_body(request)
logging.debug(f'Request body:\n{body}')
get_logger().debug(f'Request body:\n{body}')
installation_id = body.get("installation", {}).get("id")
context["installation_id"] = installation_id
context["settings"] = copy.deepcopy(global_settings)
@ -45,13 +45,13 @@ async def handle_github_webhooks(request: Request, response: Response):
@router.post("/api/v1/marketplace_webhooks")
async def handle_marketplace_webhooks(request: Request, response: Response):
body = await get_body(request)
logging.info(f'Request body:\n{body}')
get_logger().info(f'Request body:\n{body}')
async def get_body(request):
try:
body = await request.json()
except Exception as e:
logging.error("Error parsing request body", e)
get_logger().error("Error parsing request body", e)
raise HTTPException(status_code=400, detail="Error parsing request body") from e
webhook_secret = getattr(get_settings().github, 'webhook_secret', None)
if webhook_secret:
@ -77,8 +77,8 @@ async def handle_request(body: Dict[str, Any], event: str):
return {}
agent = PRAgent()
bot_user = get_settings().github_app.bot_user
logging.info(f"action: '{action}'")
logging.info(f"event: '{event}'")
sender = body.get("sender", {}).get("login")
log_context = {"action": action, "event": event, "sender": sender}
if get_settings().github_app.duplicate_requests_cache and _is_duplicate_request(body):
return {}
@ -88,22 +88,23 @@ async def handle_request(body: Dict[str, Any], event: str):
if "comment" not in body:
return {}
comment_body = body.get("comment", {}).get("body")
sender = body.get("sender", {}).get("login")
if sender and bot_user in sender:
logging.info(f"Ignoring comment from {bot_user} user")
get_logger().info(f"Ignoring comment from {bot_user} user")
return {}
logging.info(f"Processing comment from {sender} user")
get_logger().info(f"Processing comment from {sender} user")
if "issue" in body and "pull_request" in body["issue"] and "url" in body["issue"]["pull_request"]:
api_url = body["issue"]["pull_request"]["url"]
elif "comment" in body and "pull_request_url" in body["comment"]:
api_url = body["comment"]["pull_request_url"]
else:
return {}
logging.info(body)
logging.info(f"Handling comment because of event={event} and action={action}")
log_context["api_url"] = api_url
get_logger().info(body)
get_logger().info(f"Handling comment because of event={event} and action={action}")
comment_id = body.get("comment", {}).get("id")
provider = get_git_provider()(pr_url=api_url)
await agent.handle_request(api_url, comment_body, notify=lambda: provider.add_eyes_reaction(comment_id))
with get_logger().contextualize(**log_context):
await agent.handle_request(api_url, comment_body, notify=lambda: provider.add_eyes_reaction(comment_id))
# handle pull_request event:
# automatically review opened/reopened/ready_for_review PRs as long as they're not in draft,
@ -115,6 +116,7 @@ async def handle_request(body: Dict[str, Any], event: str):
api_url = pull_request.get("url")
if not api_url:
return {}
log_context["api_url"] = api_url
if pull_request.get("draft", True) or pull_request.get("state") != "open" or pull_request.get("user", {}).get("login", "") == bot_user:
return {}
if action in get_settings().github_app.handle_pr_actions:
@ -124,7 +126,7 @@ async def handle_request(body: Dict[str, Any], event: str):
if pull_request.get("created_at") == pull_request.get("updated_at"):
# avoid double reviews when opening a PR for the first time
return {}
logging.info(f"Performing review because of event={event} and action={action}")
get_logger().info(f"Performing review because of event={event} and action={action}")
apply_repo_settings(api_url)
for command in get_settings().github_app.pr_commands:
split_command = command.split(" ")
@ -132,11 +134,12 @@ async def handle_request(body: Dict[str, Any], event: str):
args = split_command[1:]
other_args = update_settings_from_args(args)
new_command = ' '.join([command] + other_args)
logging.info(body)
logging.info(f"Performing command: {new_command}")
await agent.handle_request(api_url, new_command)
get_logger().info(body)
get_logger().info(f"Performing command: {new_command}")
with get_logger().contextualize(**log_context):
await agent.handle_request(api_url, new_command)
logging.info("event or action does not require handling")
get_logger().info("event or action does not require handling")
return {}
@ -146,7 +149,7 @@ def _is_duplicate_request(body: Dict[str, Any]) -> bool:
This function checks if the request is duplicate and if so - ignores it.
"""
request_hash = hash(str(body))
logging.info(f"request_hash: {request_hash}")
get_logger().info(f"request_hash: {request_hash}")
request_time = time.monotonic()
ttl = get_settings().github_app.duplicate_requests_cache_ttl # in seconds
to_delete = [key for key, key_time in _duplicate_requests_cache.items() if request_time - key_time > ttl]
@ -155,7 +158,7 @@ def _is_duplicate_request(body: Dict[str, Any]) -> bool:
is_duplicate = request_hash in _duplicate_requests_cache
_duplicate_requests_cache[request_hash] = request_time
if is_duplicate:
logging.info(f"Ignoring duplicate request {request_hash}")
get_logger().info(f"Ignoring duplicate request {request_hash}")
return is_duplicate

View File

@ -1,6 +1,4 @@
import asyncio
import logging
import sys
from datetime import datetime, timezone
import aiohttp
@ -8,9 +6,10 @@ import aiohttp
from pr_agent.agent.pr_agent import PRAgent
from pr_agent.config_loader import get_settings
from pr_agent.git_providers import get_git_provider
from pr_agent.log import LoggingFormat, get_logger, setup_logger
from pr_agent.servers.help import bot_help_text
logging.basicConfig(stream=sys.stdout, level=logging.DEBUG)
setup_logger(fmt=LoggingFormat.JSON)
NOTIFICATION_URL = "https://api.github.com/notifications"
@ -94,7 +93,7 @@ async def polling_loop():
comment_body = comment['body'] if 'body' in comment else ''
commenter_github_user = comment['user']['login'] \
if 'user' in comment else ''
logging.info(f"Commenter: {commenter_github_user}\nComment: {comment_body}")
get_logger().info(f"Commenter: {commenter_github_user}\nComment: {comment_body}")
user_tag = "@" + user_id
if user_tag not in comment_body:
continue
@ -112,7 +111,7 @@ async def polling_loop():
print(f"Failed to fetch notifications. Status code: {response.status}")
except Exception as e:
logging.error(f"Exception during processing of a notification: {e}")
get_logger().error(f"Exception during processing of a notification: {e}")
if __name__ == '__main__':

View File

@ -1,7 +1,5 @@
import copy
import json
import logging
import sys
import uvicorn
from fastapi import APIRouter, FastAPI, Request, status
@ -14,9 +12,10 @@ from starlette_context.middleware import RawContextMiddleware
from pr_agent.agent.pr_agent import PRAgent
from pr_agent.config_loader import get_settings, global_settings
from pr_agent.log import get_logger, setup_logger
from pr_agent.secret_providers import get_secret_provider
logging.basicConfig(stream=sys.stdout, level=logging.INFO)
setup_logger()
router = APIRouter()
secret_provider = get_secret_provider() if get_settings().get("CONFIG.SECRET_PROVIDER") else None
@ -33,7 +32,7 @@ async def gitlab_webhook(background_tasks: BackgroundTasks, request: Request):
context["settings"] = copy.deepcopy(global_settings)
context["settings"].gitlab.personal_access_token = gitlab_token
except Exception as e:
logging.error(f"Failed to validate secret {request_token}: {e}")
get_logger().error(f"Failed to validate secret {request_token}: {e}")
return JSONResponse(status_code=status.HTTP_401_UNAUTHORIZED, content=jsonable_encoder({"message": "unauthorized"}))
elif get_settings().get("GITLAB.SHARED_SECRET"):
secret = get_settings().get("GITLAB.SHARED_SECRET")
@ -45,9 +44,9 @@ async def gitlab_webhook(background_tasks: BackgroundTasks, request: Request):
if not gitlab_token:
return JSONResponse(status_code=status.HTTP_401_UNAUTHORIZED, content=jsonable_encoder({"message": "unauthorized"}))
data = await request.json()
logging.info(json.dumps(data))
get_logger().info(json.dumps(data))
if data.get('object_kind') == 'merge_request' and data['object_attributes'].get('action') in ['open', 'reopen']:
logging.info(f"A merge request has been opened: {data['object_attributes'].get('title')}")
get_logger().info(f"A merge request has been opened: {data['object_attributes'].get('title')}")
url = data['object_attributes'].get('url')
background_tasks.add_task(PRAgent().handle_request, url, "/review")
elif data.get('object_kind') == 'note' and data['event_type'] == 'note':

View File

@ -1,12 +1,10 @@
import logging
from fastapi import FastAPI
from mangum import Mangum
from pr_agent.log import setup_logger
from pr_agent.servers.github_app import router
logger = logging.getLogger()
logger.setLevel(logging.DEBUG)
setup_logger()
app = FastAPI()
app.include_router(router)