Return typed errors from realtime updates, prepare for realtime statistics #4424

leonardehrenfried · 2022-08-30T10:34:07Z

Summary

Right now the realtime updates return either a false or null to indicate an error. Instead of proper statistics OTP instead logs lots of errors which are hard to analyse.

In this PR I return proper error types:

Optional<UpdateError>
Result<TripTimesPatch, UpdateError>

Result is a newly introduced type that contains two result states of a computation: a success or a failure. This is very similar to an Either in functional languages.

Future

This PR enables future development where you can aggregate metrics and return them in Prometheus or an HTTP endpoint.

Basically what is described in #4206.

Log improvements

Before

Lots and lots of these:

09:36:59.761 WARN (TimetableSnapshotSource.java:1044) [feedId: 1, tripId: 491676271] No pattern found for tripId. Skipping cancellation.
09:36:59.761 WARN (TimetableSnapshotSource.java:1044) [feedId: 1, tripId: 491676271] Failed to apply TripUpdate.
09:36:59.761 WARN (TimetableSnapshotSource.java:1044) [feedId: 1, tripId: 491676301] No pattern found for tripId. Skipping cancellation.
09:36:59.761 WARN (TimetableSnapshotSource.java:1044) [feedId: 1, tripId: 491676301] Failed to apply TripUpdate.
09:36:59.761 WARN (TimetableSnapshotSource.java:1044) [feedId: 1, tripId: 491676331] No pattern found for tripId. Skipping cancellation.
09:36:59.761 WARN (TimetableSnapshotSource.java:1044) [feedId: 1, tripId: 491676331] Failed to apply TripUpdate.
09:36:59.767 WARN (TimetableSnapshotSource.java:1044) [feedId: 1, tripId: 472992051] No pattern found for tripId. Skipping cancellation.
09:36:59.767 WARN (TimetableSnapshotSource.java:1044) [feedId: 1, tripId: 472992051] Failed to apply TripUpdate.
09:36:59.767 WARN (TimetableSnapshotSource.java:1044) [feedId: 1, tripId: 472992061] No pattern found for tripId. Skipping cancellation.
09:36:59.767 WARN (TimetableSnapshotSource.java:1044) [feedId: 1, tripId: 472992061] Failed to apply TripUpdate.
09:36:59.767 WARN (TimetableSnapshotSource.java:1044) [feedId: 1, tripId: 472992071] No pattern found for tripId. Skipping cancellation.
09:36:59.767 WARN (TimetableSnapshotSource.java:1044) [feedId: 1, tripId: 472992071] Failed to apply TripUpdate.
09:36:59.767 WARN (TimetableSnapshotSource.java:1044) [feedId: 1, tripId: 472992081] No pattern found for tripId. Skipping cancellation.
09:36:59.767 WARN (TimetableSnapshotSource.java:1044) [feedId: 1, tripId: 472992081] Failed to apply TripUpdate.
09:36:59.767 WARN (TimetableSnapshotSource.java:1044) [feedId: 1, tripId: 472992091] No pattern found for tripId. Skipping cancellation.
09:36:59.767 WARN (TimetableSnapshotSource.java:1044) [feedId: 1, tripId: 472992091] Failed to apply TripUpdate.
09:36:59.767 WARN (TimetableSnapshotSource.java:1044) [feedId: 1, tripId: 472992101] No pattern found for tripId. Skipping cancellation.
09:36:59.767 WARN (TimetableSnapshotSource.java:1044) [feedId: 1, tripId: 472992101] Failed to apply TripUpdate.
09:36:59.767 WARN (TimetableSnapshotSource.java:1044) [feedId: 1, tripId: 472992111] No pattern found for tripId. Skipping cancellation.
09:36:59.767 WARN (TimetableSnapshotSource.java:1044) [feedId: 1, tripId: 472992111] Failed to apply TripUpdate.
09:36:59.767 WARN (TimetableSnapshotSource.java:1044) [feedId: 1, tripId: 472992121] No pattern found for tripId. Skipping cancellation.
09:36:59.767 WARN (TimetableSnapshotSource.java:1044) [feedId: 1, tripId: 472992121] Failed to apply TripUpdate.
09:36:59.768 WARN (TimetableSnapshotSource.java:1044) [feedId: 1, tripId: 472992131] No pattern found for tripId. Skipping cancellation.
09:36:59.768 WARN (TimetableSnapshotSource.java:1044) [feedId: 1, tripId: 472992131] Failed to apply TripUpdate.
09:36:59.768 WARN (TimetableSnapshotSource.java:1044) [feedId: 1, tripId: 472992141] No pattern found for tripId. Skipping cancellation.

After

09:38:55.167 INFO (TimetableSnapshotSource.java:322) [feedId: 1] 245 of 323 update messages were applied successfully
09:38:55.172 ERROR (TimetableSnapshotSource.java:336) [feedId: 1] 7 failures of type UNKNOWN: [1:548853331, 1:562522371, 1:537942001, 1:559810471, 1:537942011, 1:548854041, 1:571903591]
09:38:55.173 ERROR (TimetableSnapshotSource.java:336) [feedId: 1] 71 failures of type TRIP_ID_NOT_FOUND: [1:518239181, 1:491667061, 1:472992111, 1:472994451, 1:472994571, 1:472995141, 1:472994371, 1:472995261, 1:472995061, 1:472992071, 1:491676081, 1:518238971, 1:491653421, 1:491676001, 1:491675871, 1:491676201, 1:472994811, 1:518239261, 1:491667071, 1:518239141, 1:472994731, 1:472994741, 1:491652801, 1:472992121, 1:472994461, 1:472994581, 1:472994381, 1:472995271, 1:472995151, 1:472995071, 1:472992081, 1:491676051, 1:491653251, 1:491653691, 1:491676131, 1:491676331, 1:491653451, 1:518238881, 1:491675841, 1:472994821, 1:472994941, 1:472994631, 1:491667041, 1:472992131, 1:491675811, 1:472994871, 1:472995201, 1:472992051, 1:472992091, 1:491676181, 1:518238911, 1:491676021, 1:518239001, 1:491676221, 1:491676301, 1:491652751, 1:472994511, 1:472994521, 1:472994641, 1:472995211, 1:472994881, 1:472992101, 1:472992061, 1:472992141, 1:491653391, 1:491676191, 1:491676271, 1:518238941, 1:518239231, 1:491676111, 1:491652781]
09:38:55.173 INFO (TimetableSnapshotSource.java:346) [feedId: 1] Failures by scheduleRelationship {CANCELED=71, SCHEDULED=7}

Unit tests

Added.

Documentation

n/a

codecov-commenter · 2022-08-30T10:40:53Z

Codecov Report

Attention: Patch coverage is 38.42105% with 117 lines in your changes missing coverage. Please review.

Project coverage is 58.23%. Comparing base (00e710e) to head (ad76407).
Report is 8935 commits behind head on dev-2.x.

Files with missing lines	Patch %	Lines
...nner/updater/stoptime/TimetableSnapshotSource.java	14.92%	55 Missing and 2 partials ⚠️
...pplanner/ext/siri/SiriTimetableSnapshotSource.java	0.00%	36 Missing ⚠️
.../org/opentripplanner/ext/siri/TimetableHelper.java	0.00%	11 Missing ⚠️
...main/java/org/opentripplanner/model/Timetable.java	55.00%	9 Missing ⚠️
.../java/org/opentripplanner/common/model/Result.java	93.54%	2 Missing ⚠️
...in/java/org/opentripplanner/model/UpdateError.java	91.66%	2 Missing ⚠️

Additional details and impacted files

@@             Coverage Diff             @@
##             dev-2.x    #4424    +/-   ##
===========================================
  Coverage      58.22%   58.23%            
- Complexity     11204    11215    +11     
===========================================
  Files           1480     1482     +2     
  Lines          59131    59249   +118     
  Branches        6783     6784     +1     
===========================================
+ Hits           34431    34502    +71     
- Misses         22644    22686    +42     
- Partials        2056     2061     +5

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

src/main/java/org/opentripplanner/common/model/Result.java

optionsome

I think I misunderstood you in the developer meeting. I thought you meant you had changed the default log level of these classes from the logback config but instead you have changed the log level of some calls. I think this is ok. Only minor problem is that there is quite a lot of spam on the debug log level (at least when using an MQTT updater). Should we have these realtime classes grouped in the logback.xml file so that the log level could be easily changed by a developer?

src/ext/java/org/opentripplanner/ext/siri/SiriTimetableSnapshotSource.java

src/main/java/org/opentripplanner/model/Timetable.java

src/main/java/org/opentripplanner/updater/stoptime/TimetableSnapshotSource.java

optionsome · 2022-09-01T20:40:47Z

src/main/java/org/opentripplanner/updater/stoptime/TimetableSnapshotSource.java

-      warn(tripId, "TripUpdate contains no updates, skipping.");
-      return false;
+      debug(tripId, "TripUpdate contains no updates, skipping.");
+      UpdateError.of(tripId, NO_UPDATES);


I think this check is duplicate of the check from createUpdatedTripTimes which returned the TOO_FEW_STOPS error. Should we remove one of these checks?

src/main/java/org/opentripplanner/updater/stoptime/TimetableSnapshotSource.java

src/ext/java/org/opentripplanner/ext/siri/SiriTimetableSnapshotSource.java

src/ext/java/org/opentripplanner/ext/siri/TimetableHelper.java

src/main/java/org/opentripplanner/model/Timetable.java

…apshotSource.java Co-authored-by: Hannes Junnila <[email protected]>

optionsome · 2022-09-02T16:25:01Z

src/ext/java/org/opentripplanner/ext/siri/SiriTimetableSnapshotSource.java

@@ -302,7 +308,7 @@ public void applyEstimatedTimetable(
                }
              } else {
                // Updated trip
-                if (handleModifiedTrip(transitModel, fuzzyTripMatcher, feedId, journey)) {
+                if (handleModifiedTrip(transitModel, fuzzyTripMatcher, feedId, journey).isEmpty()) {


This still has this check

This method returns a List<UpdateError>. Would you prefer it to return a Result<Void, List<UpdateError>>?

After having thought about it for a bit I think that using a Result is correct, even though it's a slightly overcomplicated type. WDYT?

optionsome · 2022-09-02T16:31:43Z

src/main/resources/logback.xml

+  <logger name="org.opentripplanner.model.Timetable" level="warn" />
+  <logger name="org.opentripplanner.ext.siri.SiriTimetableSnapshotSource" level="warn" />
+  <logger name="org.opentripplanner.ext.siri.TimetableHelper" level="warn" />


Is it intentional that these have warn as default? I don't know if it's better for these classes than info but just wanted to ask if you had left them like that by accident.

hannesj · 2022-09-05T13:46:11Z

src/ext/java/org/opentripplanner/ext/siri/SiriTimetableSnapshotSource.java

@@ -1104,12 +1115,12 @@ private boolean addTripToGraphAndBuffer(
    );

    // Add new trip times to the buffer and return success
-    final boolean updated = buffer.update(pattern, updatedTripTimes, serviceDate);
+    var maybeError = buffer.update(pattern, updatedTripTimes, serviceDate);


Should we convert this into a Result?

leonardehrenfried requested a review from a team as a code owner August 30, 2022 10:34

leonardehrenfried force-pushed the typed-realtime-errors branch from a6d26cc to b31a2e7 Compare August 30, 2022 10:39

leonardehrenfried added the Real-Time Update The issue/PR is related to RealTime updates label Aug 30, 2022

leonardehrenfried mentioned this pull request Aug 30, 2022

Prometheus metrics for realtime-data #4206

Closed

hannesj reviewed Aug 30, 2022

View reviewed changes

src/main/java/org/opentripplanner/common/model/Result.java Outdated Show resolved Hide resolved

leonardehrenfried changed the title ~~Return typed error from realtime updates, prepare for realtime statistics~~ Return typed errors from realtime updates, prepare for realtime statistics Aug 30, 2022

leonardehrenfried force-pushed the typed-realtime-errors branch from 0294a0e to 16e962e Compare August 30, 2022 12:38

hannesj requested a review from optionsome September 1, 2022 13:36

optionsome reviewed Sep 1, 2022

View reviewed changes

hannesj requested changes Sep 2, 2022

View reviewed changes

leonardehrenfried force-pushed the typed-realtime-errors branch from 3cd8494 to 2c3247d Compare September 2, 2022 13:11

leonardehrenfried added 18 commits September 2, 2022 16:00

Add typed realtime errors

d1be48e

Update timetable tests

447a9f2

Lower log level

8a0ae5b

Print summary of updates

cbacb42

Clean up tests

83c227e

Rename ApplicationResult to Result

db3830a

Remove casts from Result class

62c462c

Add tests

a0e71c3

Return proper type for DUPLICATED

b3f1d4a

Return raw value in tests

8d33afc

Change type parameter names

69a5115

Update Javadoc

2371746

Rename log method

21efd00

Add return statements

f86fd22

Introduce more errors

9d943f0

Use more precise errors

158e795

Use INVALID_INPUT_STRUCTURE

e44c9a7

Use more precise error types

a6b494a

leonardehrenfried and others added 5 commits September 2, 2022 16:00

Update src/main/java/org/opentripplanner/updater/stoptime/TimetableSn…

f5b29f4

…apshotSource.java Co-authored-by: Hannes Junnila <[email protected]>

Add errors for unimplemented relationships

fa0b128

Return Result instead of Optional

7e465f1

Return more Result instances

5f5f19b

Use more Result types

8e24059

leonardehrenfried force-pushed the typed-realtime-errors branch from 5dbeded to 8e24059 Compare September 2, 2022 14:00

Improve logging and error types

24288a9

leonardehrenfried requested review from hannesj and optionsome September 2, 2022 14:42

optionsome reviewed Sep 2, 2022

View reviewed changes

Use more Result instances

ad76407

optionsome approved these changes Sep 5, 2022

View reviewed changes

hannesj reviewed Sep 5, 2022

View reviewed changes

hannesj approved these changes Sep 8, 2022

View reviewed changes

leonardehrenfried merged commit a46bf1d into opentripplanner:dev-2.x Sep 8, 2022

leonardehrenfried deleted the typed-realtime-errors branch September 8, 2022 14:13

t2gran pushed a commit that referenced this pull request Sep 8, 2022

Add changelog entry for #4424 [ci skip]

c9c94ef

This was referenced Sep 23, 2022

Upstream merge 2022-09-23 ibi-group/OpenTripPlanner#128

Merged

Metrics for realtime trip updaters #4471

Merged

t2gran added this to the 2.2 milestone Oct 25, 2022

leonardehrenfried mentioned this pull request Jan 13, 2023

OTP gives "INVALID_STOP_SEQUENCE" error for "overcomplete" GTFS-RT data #4702

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Return typed errors from realtime updates, prepare for realtime statistics #4424

Return typed errors from realtime updates, prepare for realtime statistics #4424

leonardehrenfried commented Aug 30, 2022 •

edited

Loading

codecov-commenter commented Aug 30, 2022 •

edited by codecov bot

Loading

optionsome left a comment

optionsome Sep 1, 2022

optionsome Sep 2, 2022

leonardehrenfried Sep 2, 2022

optionsome Sep 2, 2022

hannesj Sep 5, 2022

Return typed errors from realtime updates, prepare for realtime statistics #4424

Return typed errors from realtime updates, prepare for realtime statistics #4424

Conversation

leonardehrenfried commented Aug 30, 2022 • edited Loading

Summary

Future

Log improvements

Before

After

Unit tests

Documentation

codecov-commenter commented Aug 30, 2022 • edited by codecov bot Loading

Codecov Report

optionsome left a comment

Choose a reason for hiding this comment

optionsome Sep 1, 2022

Choose a reason for hiding this comment

optionsome Sep 2, 2022

Choose a reason for hiding this comment

leonardehrenfried Sep 2, 2022

Choose a reason for hiding this comment

optionsome Sep 2, 2022

Choose a reason for hiding this comment

hannesj Sep 5, 2022

Choose a reason for hiding this comment

leonardehrenfried commented Aug 30, 2022 •

edited

Loading

codecov-commenter commented Aug 30, 2022 •

edited by codecov bot

Loading