[resotocore][chore] Improve logging (#1836)

resotocore/resotocore/__main__.py

@@ -62,6 +62,7 @@
 from resotocore.task.task_handler import TaskHandlerService
 from resotocore.user.user_management import UserManagementService
 from resotocore.util import shutdown_process, utc
+from resotocore.web.accesslog import ResotoAccessLogger
 from resotocore.web.api import Api
 from resotocore.web.certificate_handler import CertificateHandlerWithCA, CertificateHandlerNoCA
 from resotocore.worker_task_queue import WorkerTaskQueue
@@ -332,6 +333,7 @@ async def on_start_stop(_: Application) -> AsyncIterator[None]:
         http_port=config.api.http_port,
         default_port=8900,
         ssl_context=deps.cert_handler.host_context,
+        access_log_class=ResotoAccessLogger,
     )
 
 

resotocore/resotocore/db/graphdb.py

@@ -244,6 +244,7 @@ async def get_node(self, model: Model, node_id: NodeId) -> Optional[Json]:
         return self.document_to_instance_fn(model)(node) if node is not None else None
 
     async def create_node(self, model: Model, node_id: NodeId, data: Json, under_node_id: NodeId) -> Json:
+        log.info(f"Create node: node_id={node_id}, under_node_id={under_node_id}, data={data}")
         graph = GraphBuilder(model, uuid_str())
         graph.add_node(node_id, data)
         graph.add_edge(under_node_id, node_id, EdgeTypes.default)
@@ -260,6 +261,7 @@ async def create_node(self, model: Model, node_id: NodeId, data: Json, under_nod
             return trafo(result["new"])
 
     async def update_deferred_edges(self, edges: List[Tuple[NodeId, NodeId, str]], ts: datetime) -> Tuple[int, int]:
+        log.info(f"Update {len(edges)} deferred edges.")
         default_edges: List[Json] = []
         delete_edges: List[Json] = []
 
@@ -315,6 +317,7 @@ async def update_node_with(
         replace: bool,
         section: Optional[str],
     ) -> Json:
+        log.info(f"Update node with node_id={node_id}, section={section}, replace={replace}, update={patch_or_replace}")
         node = await self.by_id_with(db, node_id)
         if node is None:
             raise AttributeError(f"No document found with this id: {node_id}")
@@ -430,13 +433,16 @@ async def delete_nodes_section_with(
     async def update_nodes_section_with(
         self, db: AsyncArangoDBBase, model: Model, section: str, patch: Json, node_ids: List[NodeId]
     ) -> AsyncGenerator[Json, None]:
+        log.info(f"Update nodes section: section={section}, patch={patch} on {len(node_ids)} nodes.")
         bind_var = {"patch": patch, "node_ids": node_ids}
         trafo = self.document_to_instance_fn(model)
         with await db.aql(query=self.query_update_desired_metadata_many(section), bind_vars=bind_var) as cursor:
             for element in cursor:
                 yield trafo(element)
 
     async def delete_node(self, node_id: NodeId, model: Model, keep_history: bool = False) -> None:
+        log.info(f"Delete node {node_id}, keep_history={keep_history}")
+
         async def delete_children(element: Json) -> None:
             with await self.db.aql(query=self.query_count_direct_children(), bind_vars={"rid": node_id}) as cursor:
                 count = cursor.next()
@@ -467,6 +473,7 @@ async def update_security_section(
         model: Model,
         accounts: Optional[List[str]] = None,
     ) -> Tuple[int, int]:  # inserted, updated
+        log.info(f"Update security section. run_id={report_run_id} for accounts={accounts}")
         temp_collection = await self.get_tmp_collection(report_run_id)
         now = utc_str()
         nodes_vulnerable_new = 0
@@ -986,7 +993,7 @@ async def prepare_graph(
             return graph_info, ni, nu, nd, edge_inserts, edge_deletes
 
         roots, parent, graphs = GraphAccess.merge_graphs(graph_to_merge)
-        logging.info(f"merge_graph {len(roots)} merge nodes found. change_id={change_id}, is_batch={is_batch}.")
+        log.info(f"merge_graph {len(roots)} merge nodes found. change_id={change_id}, is_batch={is_batch}.")
 
         def parent_edges(edge_type: EdgeType) -> Tuple[str, Json]:
             edge_ids = [self.db_edge_key(f, t) for f, t, et in parent.g.edges(data="edge_type") if et == edge_type]

resotocore/resotocore/web/accesslog.py

@@ -0,0 +1,15 @@
+from aiohttp.web_log import AccessLogger
+from aiohttp.web_request import BaseRequest
+from aiohttp.web_response import StreamResponse
+
+RoutesToIgnore = {"/system/ready", "/system/ping"}
+
+
+class ResotoAccessLogger(AccessLogger):
+    """
+    Override the default aiohttp access logger to ignore certain routes.
+    """
+
+    def log(self, request: BaseRequest, response: StreamResponse, time: float) -> None:
+        if request.path not in RoutesToIgnore:
+            super().log(request, response, time)