iota_graphql_rpc/extensions/
logger.rs

1// Copyright (c) Mysten Labs, Inc.
2// Modifications Copyright (c) 2024 IOTA Stiftung
3// SPDX-License-Identifier: Apache-2.0
4
5use std::{fmt::Write, net::SocketAddr, sync::Arc};
6
7use async_graphql::{
8    PathSegment, Response, ServerError, ServerResult, ValidationResult, Variables,
9    extensions::{
10        Extension, ExtensionContext, ExtensionFactory, NextExecute, NextParseQuery, NextResolve,
11        NextValidation, ResolveInfo,
12    },
13    parser::types::{ExecutableDocument, OperationType, Selection},
14};
15use async_graphql_value::ConstValue;
16use tracing::{debug, error, info, warn};
17use uuid::Uuid;
18
19use crate::{error::code, metrics::Metrics};
20
21#[derive(Clone, Debug)]
22pub struct LoggerConfig {
23    pub log_request_query: bool,
24    pub log_response: bool,
25    pub log_complexity: bool,
26}
27
28impl Default for LoggerConfig {
29    fn default() -> Self {
30        Self {
31            log_request_query: false,
32            log_response: true,
33            log_complexity: true,
34        }
35    }
36}
37
38#[derive(Clone, Debug, Default)]
39pub struct Logger {
40    config: LoggerConfig,
41}
42
43impl ExtensionFactory for Logger {
44    fn create(&self) -> Arc<dyn Extension> {
45        Arc::new(LoggerExtension {
46            config: self.config.clone(),
47        })
48    }
49}
50
51struct LoggerExtension {
52    config: LoggerConfig,
53}
54
55#[async_trait::async_trait]
56impl Extension for LoggerExtension {
57    // This hook is used to get the top level node name for recording in the metrics
58    // which top level nodes are being called.
59    async fn resolve(
60        &self,
61        ctx: &ExtensionContext<'_>,
62        info: ResolveInfo<'_>,
63        next: NextResolve<'_>,
64    ) -> ServerResult<Option<ConstValue>> {
65        if info.path_node.parent.is_none() {
66            ctx.data_unchecked::<Metrics>()
67                .request_metrics
68                .num_queries_top_level
69                .with_label_values(&[info.name])
70                .inc();
71        }
72        next.run(ctx, info).await
73    }
74
75    async fn parse_query(
76        &self,
77        ctx: &ExtensionContext<'_>,
78        query: &str,
79        variables: &Variables,
80        next: NextParseQuery<'_>,
81    ) -> ServerResult<ExecutableDocument> {
82        let document = next.run(ctx, query, variables).await?;
83        let is_schema = document
84            .operations
85            .iter()
86            .filter(|(_, operation)| operation.node.ty == OperationType::Query)
87            .any(|(_, operation)| operation.node.selection_set.node.items.iter().any(|selection| matches!(&selection.node, Selection::Field(field) if field.node.name.node == "__schema")));
88        let query_id: &Uuid = ctx.data_unchecked();
89        let session_id: &SocketAddr = ctx.data_unchecked();
90        if !is_schema && self.config.log_request_query {
91            info!(
92                %query_id,
93                %session_id,
94                "[Query] {}",
95                ctx.stringify_execute_doc(&document, variables)
96            );
97        }
98        Ok(document)
99    }
100
101    async fn validation(
102        &self,
103        ctx: &ExtensionContext<'_>,
104        next: NextValidation<'_>,
105    ) -> Result<ValidationResult, Vec<ServerError>> {
106        let res = next.run(ctx).await?;
107        let query_id: &Uuid = ctx.data_unchecked();
108        let session_id: &SocketAddr = ctx.data_unchecked();
109        if self.config.log_complexity {
110            info!(
111                %query_id,
112                %session_id,
113                complexity = res.complexity,
114                depth = res.depth,
115                "[Validation]",
116            );
117        }
118        Ok(res)
119    }
120
121    async fn execute(
122        &self,
123        ctx: &ExtensionContext<'_>,
124        operation_name: Option<&str>,
125        next: NextExecute<'_>,
126    ) -> Response {
127        let resp = next.run(ctx, operation_name).await;
128        let query_id: &Uuid = ctx.data_unchecked();
129        let session_id: &SocketAddr = ctx.data_unchecked();
130        if resp.is_err() {
131            for err in &resp.errors {
132                let error_code = &err.extensions.as_ref().and_then(|x| x.get("code"));
133                if !err.path.is_empty() {
134                    let mut path = String::new();
135                    for (idx, s) in err.path.iter().enumerate() {
136                        if idx > 0 {
137                            path.push('.');
138                        }
139                        match s {
140                            PathSegment::Index(idx) => {
141                                let _ = write!(&mut path, "{}", idx);
142                            }
143                            PathSegment::Field(name) => {
144                                let _ = write!(&mut path, "{}", name);
145                            }
146                        }
147                    }
148
149                    if let Some(async_graphql_value::ConstValue::String(error_code)) = error_code {
150                        if error_code.as_str() == code::INTERNAL_SERVER_ERROR {
151                            error!(
152                                %query_id,
153                                %session_id,
154                                error_code,
155                                "[Response] path={} message={}",
156                                path,
157                                err.message,
158                            );
159                        } else {
160                            info!(
161                                %query_id,
162                                %session_id,
163                                error_code,
164                                "[Response] path={} message={}",
165                                path,
166                                err.message,
167                            );
168                        }
169                    } else {
170                        warn!(
171                            %query_id,
172                            %session_id,
173                            error_code = code::UNKNOWN,
174                            "[Response] path={} message={}",
175                            path,
176                            err.message,
177                        );
178                    }
179                } else {
180                    let error_code = if let Some(error_code) = error_code {
181                        error_code.to_string()
182                    } else {
183                        code::UNKNOWN.to_string()
184                    };
185                    info!(
186                        %query_id,
187                        %session_id,
188                        error_code,
189                        "[Response] message={}", err.message
190                    )
191                }
192            }
193        } else if self.config.log_response {
194            match operation_name {
195                Some("IntrospectionQuery") => {
196                    debug!(
197                        %query_id,
198                        %session_id,
199                        "[Schema] {}", resp.data
200                    );
201                }
202                _ => info!(
203                        %query_id,
204                        %session_id,
205                        "[Response] {}", resp.data
206                ),
207            }
208        }
209        resp
210    }
211}
iota_graphql_rpc/extensions/logger.rs

iota_graphql_rpc/extensions/
logger.rs
