core: stdcm: log plenty of stuff when postprocessing fail

Signed-off-by: Eloi Charpentier <[email protected]>

core/src/main/kotlin/fr/sncf/osrd/stdcm/graph/PostProcessingSimulation.kt

@@ -12,6 +12,7 @@ import fr.sncf.osrd.envelope_sim.allowances.utils.AllowanceValue
 import fr.sncf.osrd.railjson.schema.rollingstock.Comfort
 import fr.sncf.osrd.reporting.exceptions.ErrorType
 import fr.sncf.osrd.reporting.exceptions.OSRDError
+import fr.sncf.osrd.stdcm.infra_exploration.InfraExplorerWithEnvelope
 import fr.sncf.osrd.stdcm.preprocessing.interfaces.BlockAvailabilityInterface
 import fr.sncf.osrd.train.RollingStock
 import fr.sncf.osrd.train.TrainStop
@@ -21,6 +22,10 @@ import fr.sncf.osrd.utils.units.Offset
 import fr.sncf.osrd.utils.units.meters
 import java.util.*
 import kotlin.math.max
+import org.slf4j.Logger
+import org.slf4j.LoggerFactory
+
+val postProcessingLogger: Logger = LoggerFactory.getLogger("postprocessing-STDCM")
 
 private data class FixedTimePoint(
     val time: Double,
@@ -91,9 +96,29 @@ fun buildFinalEnvelope(
                     edges,
                     updatedTimeData,
                 ) ?: return newEnvelope
-            if (fixedPoints.any { it.offset == conflictOffset })
-                break // Error case, we exit and fallback to the linear envelope
-            logger.info(
+            if (fixedPoints.any { it.offset == conflictOffset }) {
+                // Error case: a conflict prevents us from finding a solution,
+                // despite the exploration data identifying a valid opening.
+                // This is not supposed to happen, but we can still fallback
+                // linear allowance, and log as much info as we can
+                return handlePostProcessingConflict(
+                    graph,
+                    maxSpeedEnvelope,
+                    edges,
+                    standardAllowance,
+                    envelopeSimPath,
+                    rollingStock,
+                    timeStep,
+                    comfort,
+                    blockAvailability,
+                    stops,
+                    updatedTimeData,
+                    fixedPoints,
+                    conflictOffset,
+                    isMareco,
+                )
+            }
+            postProcessingLogger.info(
                 "Conflict when running final stdcm simulation at offset {}, adding a fixed time point",
                 conflictOffset
             )
@@ -105,7 +130,9 @@ fun buildFinalEnvelope(
                 // Mareco allowances must have a non-zero capacity speed limit,
                 // which may cause "too much time" errors.
                 // We can ignore this exception and move on to the linear allowance as fallback
-                logger.info("Can't slow down enough to match the given standard allowance")
+                postProcessingLogger.warn(
+                    "Can't slow down enough to match the given standard allowance"
+                )
                 break
             } else throw e
         }
@@ -115,7 +142,9 @@ fun buildFinalEnvelope(
             "Failed to compute a standard allowance that wouldn't cause conflicts"
         )
     } else {
-        logger.info("Failed to compute a mareco standard allowance, fallback to linear allowance")
+        postProcessingLogger.warn(
+            "Failed to compute a mareco standard allowance, fallback to linear allowance"
+        )
         return buildFinalEnvelope(
             graph,
             maxSpeedEnvelope,
@@ -262,14 +291,7 @@ private fun findConflictOffsets(
                 millimeters =
                     edges.stream().mapToLong { edge -> edge.length.distance.millimeters }.sum()
             )
-    val explorer =
-        edges
-            .last()
-            .infraExplorer
-            .withNewEnvelope(
-                envelope,
-            )
-            .updateStopDurations(updatedTimeData)
+    val explorer = getUpdatedExplorer(edges, envelope, updatedTimeData)
     assert(
         TrainPhysicsIntegrator.arePositionsEqual(envelope.endPos, (endOffset - startOffset).meters)
     )
@@ -286,6 +308,21 @@ private fun findConflictOffsets(
     return offsetDistance
 }
 
+/** Returns an infra explorer with envelope, with the given new envelope and updated time data */
+private fun getUpdatedExplorer(
+    edges: List<STDCMEdge>,
+    envelope: Envelope,
+    updatedTimeData: TimeData
+): InfraExplorerWithEnvelope {
+    return edges
+        .last()
+        .infraExplorer
+        .withReplacedEnvelope(
+            envelope,
+        )
+        .updateStopDurations(updatedTimeData)
+}
+
 /**
  * Run a full simulation, with allowances configured to match the given fixed points. If isMareco is
  * set to true, the allowances follow the mareco distribution (more accurate but less reliable).
@@ -343,3 +380,88 @@ private fun makeAllowanceRanges(
 
     return res
 }
+
+/**
+ * This method handles the case where we find a conflict in post-processing that wasn't supposed to
+ * be present according to what has been. This isn't supposed to happen, but when it does we want to
+ * log as much data as possible. We can also fallback from mareco to linear margins.
+ */
+private fun handlePostProcessingConflict(
+    graph: STDCMGraph,
+    maxSpeedEnvelope: Envelope,
+    edges: List<STDCMEdge>,
+    standardAllowance: AllowanceValue?,
+    envelopeSimPath: EnvelopeSimPath,
+    rollingStock: RollingStock,
+    timeStep: Double,
+    comfort: Comfort?,
+    blockAvailability: BlockAvailabilityInterface,
+    stops: List<TrainStop>,
+    updatedTimeData: TimeData,
+    fixedPoints: TreeSet<FixedTimePoint>,
+    conflictOffset: Offset<TravelledPath>,
+    isMareco: Boolean
+): Envelope {
+    postProcessingLogger.error(
+        "Conflicts detected in post-processing, mismatch with the exploration data"
+    )
+    val conflictTime = fixedPoints.first { it.offset == conflictOffset }.time
+    postProcessingLogger.info(
+        "    conflict happened at offset=$conflictOffset/${maxSpeedEnvelope.endPos.toInt()} " +
+            "and t=${conflictTime.toInt()}/${updatedTimeData.timeSinceDeparture.toInt()}"
+    )
+
+    var remainingDistance = conflictOffset.distance
+    for ((i, edge) in edges.withIndex()) {
+        val atStop = edge.endAtStop && remainingDistance == edge.length.distance
+        if (remainingDistance < edge.length.distance || atStop) {
+            val updatedTimeAtConflict =
+                edge.getApproximateTimeAtLocation(Offset(remainingDistance), updatedTimeData)
+            val updatedExplorer = getUpdatedExplorer(edges, maxSpeedEnvelope, updatedTimeData)
+            postProcessingLogger.info("    edge $i/${edges.size}: $edge")
+            postProcessingLogger.info("        offset $remainingDistance/${edge.length}")
+            postProcessingLogger.info("        original time data: ${edge.timeData}")
+            postProcessingLogger.info("        updated time data: $updatedTimeData")
+            postProcessingLogger.info(
+                "        original explorer stops: ${edge.infraExplorerWithNewEnvelope.getStops()}"
+            )
+            postProcessingLogger.info(
+                "        updated explorer stops: ${updatedExplorer.getStops()}"
+            )
+            postProcessingLogger.info(
+                "        updated start time: ${edge.timeData.getUpdatedEarliestReachableTime(updatedTimeData)}"
+            )
+            postProcessingLogger.info(
+                "        updated time at conflict location: $updatedTimeAtConflict"
+            )
+            break
+        }
+        remainingDistance -= edge.length.distance
+    }
+
+    if (isMareco) {
+        postProcessingLogger.info(
+            "The error happened with mareco allowances, try to fallback on linear allowances"
+        )
+        postProcessingLogger.info("(reset of fixed time points)")
+        return buildFinalEnvelope(
+            graph,
+            maxSpeedEnvelope,
+            edges,
+            standardAllowance,
+            envelopeSimPath,
+            rollingStock,
+            timeStep,
+            comfort,
+            blockAvailability,
+            stops,
+            updatedTimeData,
+            false,
+        )
+    } else {
+        throw RuntimeException(
+            "Failed to compute a simulation that wouldn't cause conflicts: " +
+                "mismatch between exploration and postprocessing (please open a bug report)"
+        )
+    }
+}

core/src/main/kotlin/fr/sncf/osrd/stdcm/graph/STDCMPathfinding.kt

@@ -137,8 +137,9 @@ class STDCMPathfinding(
                     graph.tag
                 ) ?: return null
         logger.info(
-            "departure time = ${res.departureTime.toInt()}s, " +
-                "total travel time = ${res.envelope.totalTime.toInt()}s"
+            "departure time = +${res.departureTime.toInt()}s, " +
+                "total travel time = ${res.envelope.totalTime.toInt()}s, " +
+                "total stop time = ${res.stopResults.sumOf { it.duration }.toInt()}s"
         )
         return res
     }

core/src/main/kotlin/fr/sncf/osrd/stdcm/graph/TimeData.kt

@@ -70,6 +70,9 @@ data class TimeData(
         extraStopTime: Double?,
         maxAdditionalStopTime: Double?
     ): TimeData {
+        assert((extraStopTime == null) == (maxAdditionalStopTime == null)) {
+            "Can't set just one of 'stop duration' or 'max additional stop duration' without the other"
+        }
         var newStopData = stopTimeData
         var maxDepartureDelayingWithoutConflict = maxDepartureDelayingWithoutConflict
         val nextEarliestReachableTime =

core/src/main/kotlin/fr/sncf/osrd/stdcm/infra_exploration/InfraExplorerWithEnvelope.kt

@@ -47,7 +47,7 @@ interface InfraExplorerWithEnvelope : InfraExplorer {
     /**
      * Returns a copy with the given envelope, the previous one is ignored. This keeps stop data.
      */
-    fun withNewEnvelope(envelope: Envelope): InfraExplorerWithEnvelope
+    fun withReplacedEnvelope(envelope: Envelope): InfraExplorerWithEnvelope
 
     /** Add a stop to the end of the last simulated envelope */
     fun addStop(stopDuration: Double)

core/src/main/kotlin/fr/sncf/osrd/stdcm/infra_exploration/InfraExplorerWithEnvelopeImpl.kt

@@ -70,7 +70,7 @@ data class InfraExplorerWithEnvelopeImpl(
         return this
     }
 
-    override fun withNewEnvelope(envelope: Envelope): InfraExplorerWithEnvelope {
+    override fun withReplacedEnvelope(envelope: Envelope): InfraExplorerWithEnvelope {
         return copy(
             envelopes =
                 appendOnlyLinkedListOf(
@@ -108,7 +108,7 @@ data class InfraExplorerWithEnvelopeImpl(
             envelopeCache = null
             spacingRequirementsCache = null
         } else {
-            assert(stops.isEmpty() || stops.last().duration == stopDuration)
+            assert(stops.last().duration == stopDuration)
         }
     }
 

core/src/test/kotlin/fr/sncf/osrd/stdcm/VisitedNodesTests.kt

@@ -5,12 +5,12 @@ import fr.sncf.osrd.stdcm.graph.TimeData
 import fr.sncf.osrd.stdcm.graph.VisitedNodes
 import fr.sncf.osrd.stdcm.infra_exploration.EdgeIdentifier
 import fr.sncf.osrd.utils.units.meters
-import org.junit.jupiter.api.Test
-import org.junit.jupiter.params.ParameterizedTest
-import org.junit.jupiter.params.provider.ValueSource
 import kotlin.test.assertEquals
 import kotlin.test.assertFalse
 import kotlin.test.assertTrue
+import org.junit.jupiter.api.Test
+import org.junit.jupiter.params.ParameterizedTest
+import org.junit.jupiter.params.provider.ValueSource
 
 class VisitedNodesTests {