From 5a83e230de9df45ce69c19a3f48c211a7987f75c Mon Sep 17 00:00:00 2001 From: hamz2a Date: Tue, 26 Nov 2024 16:07:13 +0100 Subject: [PATCH] editoast: log stdcm requests Signed-off-by: hamz2a --- editoast/editoast_models/src/tables.rs | 17 +++++ .../down.sql | 1 + .../up.sql | 8 +++ editoast/openapi.yaml | 64 +++++++++++++++++++ editoast/src/core/conflict_detection.rs | 2 +- editoast/src/core/mod.rs | 1 + editoast/src/core/simulation.rs | 2 +- editoast/src/core/stdcm.rs | 16 +++-- editoast/src/models/mod.rs | 2 + editoast/src/models/stdcm_log.rs | 27 ++++++++ editoast/src/views/timetable/stdcm.rs | 64 +++++++++++++++---- 11 files changed, 182 insertions(+), 22 deletions(-) create mode 100644 editoast/migrations/2024-11-21-145205_create_stdcm_logs/down.sql create mode 100644 editoast/migrations/2024-11-21-145205_create_stdcm_logs/up.sql create mode 100644 editoast/src/models/stdcm_log.rs diff --git a/editoast/editoast_models/src/tables.rs b/editoast/editoast_models/src/tables.rs index db0a4992c0d..35d64cbc684 100644 --- a/editoast/editoast_models/src/tables.rs +++ b/editoast/editoast_models/src/tables.rs @@ -596,6 +596,21 @@ diesel::table! { } } +diesel::table! { + use diesel::sql_types::*; + use postgis_diesel::sql_types::*; + + stdcm_logs (id) { + id -> Int8, + #[max_length = 32] + trace_id -> Varchar, + request -> Jsonb, + response -> Jsonb, + created -> Timestamptz, + user_id -> Int8, + } +} + diesel::table! { use diesel::sql_types::*; use postgis_diesel::sql_types::*; @@ -798,6 +813,7 @@ diesel::joinable!(search_project -> project (id)); diesel::joinable!(search_scenario -> scenario (id)); diesel::joinable!(search_signal -> infra_object_signal (id)); diesel::joinable!(search_study -> study (id)); +diesel::joinable!(stdcm_logs -> authn_user (user_id)); diesel::joinable!(stdcm_search_environment -> electrical_profile_set (electrical_profile_set_id)); diesel::joinable!(stdcm_search_environment -> infra (infra_id)); diesel::joinable!(stdcm_search_environment -> temporary_speed_limit_group (temporary_speed_limit_group_id)); @@ -851,6 +867,7 @@ diesel::allow_tables_to_appear_in_same_query!( search_signal, search_study, search_track, + stdcm_logs, stdcm_search_environment, study, temporary_speed_limit, diff --git a/editoast/migrations/2024-11-21-145205_create_stdcm_logs/down.sql b/editoast/migrations/2024-11-21-145205_create_stdcm_logs/down.sql new file mode 100644 index 00000000000..83466c32b52 --- /dev/null +++ b/editoast/migrations/2024-11-21-145205_create_stdcm_logs/down.sql @@ -0,0 +1 @@ +DROP TABLE stdcm_logs; diff --git a/editoast/migrations/2024-11-21-145205_create_stdcm_logs/up.sql b/editoast/migrations/2024-11-21-145205_create_stdcm_logs/up.sql new file mode 100644 index 00000000000..37e510fa4e5 --- /dev/null +++ b/editoast/migrations/2024-11-21-145205_create_stdcm_logs/up.sql @@ -0,0 +1,8 @@ +CREATE TABLE stdcm_logs ( + id int8 PRIMARY KEY GENERATED BY DEFAULT AS IDENTITY, + trace_id VARCHAR(32) UNIQUE NOT NULL, + request jsonb NOT NULL, + response jsonb NOT NULL, + created timestamptz NOT NULL DEFAULT NOW(), + user_id bigint NOT NULL REFERENCES authn_user ON DELETE CASCADE +); diff --git a/editoast/openapi.yaml b/editoast/openapi.yaml index 173ff46f20d..611c32937af 100644 --- a/editoast/openapi.yaml +++ b/editoast/openapi.yaml @@ -8622,6 +8622,45 @@ components: type: integer format: int64 nullable: true + Response: + oneOf: + - type: object + required: + - simulation + - path + - departure_time + - status + properties: + departure_time: + type: string + format: date-time + path: + $ref: '#/components/schemas/PathfindingResultSuccess' + simulation: + $ref: '#/components/schemas/SimulationResponse' + status: + type: string + enum: + - success + - type: object + required: + - status + properties: + status: + type: string + enum: + - path_not_found + - type: object + required: + - error + - status + properties: + error: + $ref: '#/components/schemas/SimulationResponse' + status: + type: string + enum: + - preprocessing_simulation_error RjsPowerRestrictionRange: type: object description: A range along the train path where a power restriction is applied. @@ -10228,6 +10267,31 @@ components: type: array items: $ref: '#/components/schemas/RangeAllowance' + StdcmLog: + type: object + required: + - id + - trace_id + - request + - response + - created + - user_id + properties: + created: + type: string + format: date-time + id: + type: integer + format: int64 + request: + $ref: '#/components/schemas/Request' + response: + $ref: '#/components/schemas/Response' + trace_id: + type: string + user_id: + type: integer + format: int64 StdcmSearchEnvironment: type: object required: diff --git a/editoast/src/core/conflict_detection.rs b/editoast/src/core/conflict_detection.rs index c50fdc4ba10..45689d7f083 100644 --- a/editoast/src/core/conflict_detection.rs +++ b/editoast/src/core/conflict_detection.rs @@ -29,7 +29,7 @@ pub struct ConflictDetectionRequest { pub work_schedules: Option, } -#[derive(Debug, Clone, Serialize)] +#[derive(Debug, Clone, Serialize, Deserialize)] pub struct TrainRequirements { pub start_time: DateTime, pub spacing_requirements: Vec, diff --git a/editoast/src/core/mod.rs b/editoast/src/core/mod.rs index 48fce5b6cea..680386f71dc 100644 --- a/editoast/src/core/mod.rs +++ b/editoast/src/core/mod.rs @@ -36,6 +36,7 @@ editoast_common::schemas! { simulation::schemas(), pathfinding::schemas(), conflict_detection::schemas(), + stdcm::schemas(), } #[derive(Debug, Clone)] diff --git a/editoast/src/core/simulation.rs b/editoast/src/core/simulation.rs index a9a61ad2811..86a34fedf64 100644 --- a/editoast/src/core/simulation.rs +++ b/editoast/src/core/simulation.rs @@ -34,7 +34,7 @@ editoast_common::schemas! { SimulationResponse, } -#[derive(Debug, Serialize, Derivative)] +#[derive(Debug, Clone, Serialize, Deserialize, Derivative)] #[derivative(Hash)] pub struct PhysicsConsist { pub effort_curves: EffortCurves, diff --git a/editoast/src/core/stdcm.rs b/editoast/src/core/stdcm.rs index 19703288fee..45dbd469fbc 100644 --- a/editoast/src/core/stdcm.rs +++ b/editoast/src/core/stdcm.rs @@ -19,7 +19,11 @@ use super::simulation::SimulationResponse; use crate::core::AsCoreRequest; use crate::core::Json; -#[derive(Debug, Serialize)] +editoast_common::schemas! { + Response, +} + +#[derive(Debug, Clone, Serialize, Deserialize)] pub struct Request { /// Infrastructure id pub infra: i64, @@ -61,7 +65,7 @@ pub struct Request { pub temporary_speed_limits: Vec, } -#[derive(Debug, Serialize)] +#[derive(Debug, Clone, Serialize, Deserialize)] pub struct PathItem { /// The track offsets of the path item pub locations: Vec, @@ -72,7 +76,7 @@ pub struct PathItem { } /// Contains the data of a step timing, when it is specified -#[derive(Debug, Serialize)] +#[derive(Debug, Clone, Serialize, Deserialize)] pub struct StepTimingData { /// Time the train should arrive at this point pub arrival_time: DateTime, @@ -83,7 +87,7 @@ pub struct StepTimingData { } /// Lighter description of a work schedule, with only the relevant information for core -#[derive(Debug, Serialize)] +#[derive(Debug, Clone, Serialize, Deserialize)] pub struct WorkSchedule { /// Start time as a time delta from the stdcm start time in ms pub start_time: u64, @@ -94,7 +98,7 @@ pub struct WorkSchedule { } /// Lighter description of a work schedule with only the relevant information for core -#[derive(Debug, Serialize)] +#[derive(Debug, Clone, Serialize, Deserialize)] pub struct TemporarySpeedLimit { /// Speed limitation in m/s pub speed_limit: f64, @@ -114,7 +118,7 @@ pub struct UndirectedTrackRange { pub end: u64, } -#[derive(Serialize, Deserialize, Clone, Debug, PartialEq)] +#[derive(Serialize, Deserialize, Clone, Debug, PartialEq, ToSchema)] #[serde(tag = "status", rename_all = "snake_case")] // We accepted the difference of memory size taken by variants // Since there is only on success and others are error cases diff --git a/editoast/src/models/mod.rs b/editoast/src/models/mod.rs index f8b1b28148a..28a96bedf55 100644 --- a/editoast/src/models/mod.rs +++ b/editoast/src/models/mod.rs @@ -6,6 +6,7 @@ pub mod fixtures; pub mod infra; pub mod infra_objects; pub mod layers; +pub mod stdcm_log; // We allow unused until models is moved to a separate crate pub mod auth; pub mod pagination; @@ -41,6 +42,7 @@ editoast_common::schemas! { infra::schemas(), projects::schemas(), rolling_stock_model::schemas(), + stdcm_log::schemas(), } #[cfg(test)] diff --git a/editoast/src/models/stdcm_log.rs b/editoast/src/models/stdcm_log.rs new file mode 100644 index 00000000000..e5f9709c695 --- /dev/null +++ b/editoast/src/models/stdcm_log.rs @@ -0,0 +1,27 @@ +use chrono::DateTime; +use chrono::Utc; +use editoast_derive::Model; +use serde::Deserialize; +use serde::Serialize; +use utoipa::ToSchema; + +use crate::core::stdcm::Request; +use crate::core::stdcm::Response; + +editoast_common::schemas! { + StdcmLog, +} + +#[derive(Clone, Debug, Serialize, Deserialize, Model, ToSchema)] +#[model(table = editoast_models::tables::stdcm_logs)] +#[model(gen(ops = c))] +pub struct StdcmLog { + pub id: i64, + pub trace_id: String, + #[model(json)] + pub request: Request, + #[model(json)] + pub response: Response, + pub created: DateTime, + pub user_id: i64, +} diff --git a/editoast/src/views/timetable/stdcm.rs b/editoast/src/views/timetable/stdcm.rs index a906dc57990..7f9bc9702b4 100644 --- a/editoast/src/views/timetable/stdcm.rs +++ b/editoast/src/views/timetable/stdcm.rs @@ -17,6 +17,7 @@ use editoast_schemas::train_schedule::Margins; use editoast_schemas::train_schedule::ReceptionSignal; use editoast_schemas::train_schedule::ScheduleItem; use failure_handler::SimulationFailureHandler; +use opentelemetry::trace::TraceContextExt; use request::convert_steps; use request::Request; use serde::Deserialize; @@ -24,6 +25,8 @@ use serde::Serialize; use std::collections::HashMap; use std::sync::Arc; use thiserror::Error; +use tracing::Instrument; +use tracing_opentelemetry::OpenTelemetrySpanExt; use utoipa::IntoParams; use utoipa::ToSchema; @@ -36,6 +39,8 @@ use crate::core::simulation::{RoutingRequirement, SimulationResponse, SpacingReq use crate::core::AsCoreRequest; use crate::core::CoreClient; use crate::error::Result; +use crate::models::prelude::*; +use crate::models::stdcm_log::StdcmLog; use crate::models::timetable::TimetableWithTrains; use crate::models::train_schedule::TrainSchedule; use crate::models::Infra; @@ -46,8 +51,6 @@ use crate::views::train_schedule::train_simulation_batch; use crate::views::AuthenticationExt; use crate::views::AuthorizationError; use crate::AppState; -use crate::Retrieve; -use crate::RetrieveBatch; use crate::ValkeyClient; editoast_common::schemas! { @@ -135,7 +138,7 @@ async fn stdcm( } let db_pool = app_state.db_pool_v2.clone(); - let conn = &mut db_pool.get().await?; + let mut conn = db_pool.get().await?; let valkey_client = app_state.valkey.clone(); let core_client = app_state.core_client.clone(); @@ -143,19 +146,21 @@ async fn stdcm( let infra_id = query.infra; // 1. Retrieve Timetable / Infra / Trains / Simulation / Rolling Stock - let timetable_trains = TimetableWithTrains::retrieve_or_fail(conn, timetable_id, || { + let timetable_trains = TimetableWithTrains::retrieve_or_fail(&mut conn, timetable_id, || { StdcmError::TimetableNotFound { timetable_id } }) .await?; - let infra = - Infra::retrieve_or_fail(conn, infra_id, || StdcmError::InfraNotFound { infra_id }).await?; + let infra = Infra::retrieve_or_fail(&mut conn, infra_id, || StdcmError::InfraNotFound { + infra_id, + }) + .await?; let (train_schedules, _): (Vec<_>, _) = - TrainSchedule::retrieve_batch(conn, timetable_trains.train_ids.clone()).await?; + TrainSchedule::retrieve_batch(&mut conn, timetable_trains.train_ids.clone()).await?; let rolling_stock = - RollingStockModel::retrieve_or_fail(conn, stdcm_request.rolling_stock_id, || { + RollingStockModel::retrieve_or_fail(&mut conn, stdcm_request.rolling_stock_id, || { StdcmError::RollingStockNotFound { rolling_stock_id: stdcm_request.rolling_stock_id, } @@ -186,7 +191,7 @@ async fn stdcm( // 3. Get scheduled train requirements let simulations: Vec<_> = train_simulation_batch( - conn, + &mut conn, valkey_client.clone(), core_client.clone(), &train_schedules, @@ -206,7 +211,7 @@ async fn stdcm( ); // 4. Retrieve work schedules - let work_schedules = stdcm_request.get_work_schedules(conn).await?; + let work_schedules = stdcm_request.get_work_schedules(&mut conn).await?; // 5. Build STDCM request let stdcm_request = crate::core::stdcm::Request { @@ -221,17 +226,19 @@ async fn stdcm( total_length: stdcm_request.total_length, total_mass: stdcm_request.total_mass, towed_rolling_stock: stdcm_request - .get_towed_rolling_stock(conn) + .get_towed_rolling_stock(&mut conn) .await? .map(From::from), traction_engine: rolling_stock.into(), } .into(), temporary_speed_limits: stdcm_request - .get_temporary_speed_limits(conn, simulation_run_time) + .get_temporary_speed_limits(&mut conn, simulation_run_time) .await?, comfort: stdcm_request.comfort, - path_items: stdcm_request.get_stdcm_path_items(conn, infra_id).await?, + path_items: stdcm_request + .get_stdcm_path_items(&mut conn, infra_id) + .await?, start_time: earliest_departure_time, trains_requirements, maximum_departure_delay: stdcm_request.get_maximum_departure_delay(simulation_run_time), @@ -251,7 +258,36 @@ async fn stdcm( let stdcm_response = stdcm_request.fetch(core_client.as_ref()).await?; - // 6. Handle STDCM Core Response + // 6. Check if the current tracing level is debug or lower, and if so, log STDCM request and response + if tracing::level_filters::LevelFilter::current() >= tracing::Level::DEBUG { + let user_id = auth.authorizer()?.user_id(); + let stdcm_response_for_spawn = stdcm_response.clone(); + let trace_id = tracing::Span::current() + .context() + .span() + .span_context() + .trace_id(); + let stdcm_log_changeset = StdcmLog::changeset() + .trace_id(trace_id.to_string()) + .request(stdcm_request) + .response(stdcm_response_for_spawn) + .user_id(user_id); + let _ = tokio::spawn( + // We just don't await the creation of the log entry since we want + // the endpoint to return as soon as possible, and because failing + // to persist a log entry is not a very important error here. + async move { + let _ = stdcm_log_changeset + .create(&mut conn) + .await + .map_err(|e| tracing::error!("Failed during log operation: {e}")); + } + .in_current_span(), + ) + .await; + } + + // 7. Handle STDCM Core Response match stdcm_response { crate::core::stdcm::Response::Success { simulation,