Graceful timeout error handling by t2gran · Pull Request #5130 · opentripplanner/OpenTripPlanner

t2gran · 2023-05-19T14:12:04Z

Summary

fix: The Response.Status.fromStatusCode fails with exception if the status code is 422

We want to return HTTP Status code 422, and not 500 for timeouts.

Refactor: Cleanup error handling in PlannerResource

Handle SYSTEM_ERROR and PROCESSING_TIMEOUT the same way. Timeout and
system-error will show up in the OTP Debug Client.

debug: Add a busyWaitOnce() method for manual testing timeouts

The busyWaitOnce() is a method witch make it possible to test timeouts
without interfering with the interrupts.

feature: Improve on the GraphQL performance on timeout

The data-fetchers do not abort when a timeout occurs. This commit
improves on the situation and in the end causes the GraphQL instance
to exit with a timeout exception.

The "notprivacysafe.graphql" logger should be turned off to prevent
the TimeOut exception to be logged. The AbortOnTimeoutExecutionStrategy
will log the timeout. There might be more than 100 000 pending data-fetchers
witch all are inerrupted with a timeout, so we use the progress logger:

17:51:02.872 INFO [grizzly-0] (AbortOnTimeoutExecutionStrategy.java:42) TIMEOUT! Abort GraphQL query progress tracking started.
17:51:07.402 INFO [grizzly-0] (AbortOnTimeoutExecutionStrategy.java:42) TIMEOUT! Abort GraphQL query progress: 175 000 done
17:51:12.502 INFO [grizzly-0] (AbortOnTimeoutExecutionStrategy.java:42) TIMEOUT! Abort GraphQL query progress: 375 000 done
17:51:14.425 INFO [grizzly-0] (AbortOnTimeoutExecutionStrategy.java:47) TIMEOUT! Abort GraphQL query progress tracking complete. 451 693 done in 12s (35 894 per second).

…tatus code is 422 We want to return HTTP Status code 422, and not 500 for timeouts.

Handle SYSTEM_ERROR and PROCESSING_TIMEOUT the same way. Timeout and system-error will show up in the OTP Debug Client.

The busyWaitOnce() is a method witch make it possible to test timeouts without interfering with the interrupts.

codecov · 2023-05-24T14:52:35Z

Codecov Report

Patch coverage: 3.03% and project coverage change: +0.12 🎉

Comparison is base (e2e58c5) 64.98% compared to head (89c94ed) 65.11%.

Additional details and impacted files

@@              Coverage Diff              @@
##             dev-2.x    #5130      +/-   ##
=============================================
+ Coverage      64.98%   65.11%   +0.12%     
- Complexity     14216    14325     +109     
=============================================
  Files           1735     1743       +8     
  Lines          67576    67763     +187     
  Branches        7228     7225       -3     
=============================================
+ Hits           43915    44123     +208     
+ Misses         21223    21195      -28     
- Partials        2438     2445       +7

Impacted Files	Coverage Δ
...entripplanner/ext/transmodelapi/TransmodelAPI.java	`0.00% <0.00%> (ø)`
...tripplanner/ext/transmodelapi/TransmodelGraph.java	`0.00% <0.00%> (ø)`
...elapi/support/AbortOnTimeoutExecutionStrategy.java	`0.00% <0.00%> (ø)`
...nsmodelapi/support/GraphQLToWebResponseMapper.java	`0.00% <0.00%> (ø)`
.../ext/transmodelapi/support/OtpExecutionResult.java	`0.00% <0.00%> (ø)`
...opentripplanner/api/common/OTPExceptionMapper.java	`0.00% <0.00%> (ø)`
.../opentripplanner/api/resource/PlannerResource.java	`7.14% <0.00%> (+1.26%)`	⬆️
...mework/application/OTPRequestTimeoutException.java	`20.00% <0.00%> (ø)`
...tripplanner/framework/logging/ProgressTracker.java	`82.25% <0.00%> (-17.75%)`	⬇️
.../org/opentripplanner/framework/time/TimeUtils.java	`68.62% <15.38%> (-18.56%)`	⬇️

... and 62 files with indirect coverage changes

☔ View full report in Codecov by Sentry.
📢 Do you have feedback about the report comment? Let us know in this issue.

The data-fetchers do not abort when a timeout occurs. This commit improves on the situation and in the end causes the GraphQL instance to exit with a timeout exception. The "notprivacysafe.graphql" logger should be turned off to prevent the TimeOut exception to be logged. The risk is little, since any exception logged here also propagate to the otp code calling 'GraphQL.execute()'.

t2gran · 2023-05-24T16:04:31Z

The logging does not log the query or any information about the query. I suggest using this with a correlationId to match the timeout with other log events or your audit-log(if you have one).

leonardehrenfried · 2023-05-25T14:58:26Z

  @POST
  @Path("/graphql/batch")
  @Consumes(MediaType.APPLICATION_JSON)
+  @Deprecated


I would even be fine if that was removed. Batch queries have dubious value in the era of HTTP2.

I will remove it in a separate PR

leonardehrenfried

I picked up on a few spelling errors.

Co-authored-by: Leonard Ehrenfried <mail@leonard.io>

* Add changelog entry for opentripplanner#5100 [ci skip] * refactor: Add proper progress tracking for GraphQL timeouts. * refactor: Fix spelling 'guarantied' -> 'guaranteed' * review: Fix documentation * feature: Trace HTTP request headers * Add changelog entry for opentripplanner#5081 [ci skip] * Add changelog entry for opentripplanner#5091 [ci skip] * Add changelog entry for opentripplanner#5133 [ci skip] * Remove unused code * Generate full POM for shaded jar [ci skip] * Add elevation data to Transmodel API * Finetune elevation format * Update documentation * Add changelog entry for opentripplanner#5142 [ci skip] * fix: Make sure the log key is removed from the Grizzly thread log context * Apply suggestions from code review Co-authored-by: Thomas Gran <t2gran@gmail.com> * Remove San Francisco fare calculator * Remove TimeBasedVehicleRentalFareService * Add documentation about deleted calculators * Remove empty lines * Refactor null check on from and to vertices * review: Apply review feedback * Apply suggestions from code review Co-authored-by: Leonard Ehrenfried <mail@leonard.io> * feature: Add sanity check for HTTP header value The value must match `[^\p{Cntrl}\v]{1,512}` * test: Add test regular expression for HTTP header value * Apply suggestions from code review Co-authored-by: Leonard Ehrenfried <mail@leonard.io> * feature: Remove batch query from Transmodel API * refactor: re-generate doc * fix(deps): update dependency com.google.guava:guava to v32 * fix(deps): update dependency com.graphql-java:graphql-java to v20.3 * Add changelog entry for opentripplanner#5130 [ci skip] * fix(deps): update dependency com.google.guava:guava to v32 * Use git to figure out last-modified date * Debug last modified check * Increase fetch depth * Make update frequency a Duration * fix(deps): update dependency com.fasterxml.jackson.core:jackson-annotations to v2.15.2 * Update log messages * Update docs * Remove link to 1.x-dev docs * refactor: Avoid creating builders unnecessary. * test: Add test for bug in TripRequestMapperTest * Add changelog entry for opentripplanner#5131 [ci skip] * Bump serialization version id for opentripplanner#5131 * Add changelog entry for opentripplanner#5141 [ci skip] * Bump serialization version id for opentripplanner#5141 * Improve money documentation * Implement stop sequence in GraphQL * Add stop sequence and test * Fix docs, formatting and tests * Add test for walk step mapping * fix: Fix bug in maxDirectDurationForMode and refactor - The code is not DRY, so I refactored it - this also fixes the bug * refactor: Extract mappers out off PreferencesMapper * fix(deps): update dependency com.google.cloud:libraries-bom to v26.15.0 * fix(deps): update dependency org.onebusaway:onebusaway-gtfs to v1.4.3 * Make absolute direction optional * Add test for GraphQL API * Add changelog entry for opentripplanner#5140 [ci skip] * Update documentation * Add changelog entry for opentripplanner#5145 [ci skip] * Consider level and layer tags when linking public transit stop area nodes E.g. transit entrances above ground should not get directly linked to subway platforms * Add test for ensuring that entrances do not link to platforms across different layers/levels * Update documentation and mapping * test: Add regression test. * fix: Fix validation of flex area, assert isComplete and isConsistent, before isStopTimesIncreasing * refactor: Cleanup AbstractStopTimeAdaptor * Improve documentation * Handle stop areas with many platforms properly Entrances and other unconnected nodes included in stop area relation were linked only with the first platform area. Now they are matched with all platforms. Walkable area builder won't create connections if node is outside a platform. * Update documenation * Create interline transfers for trips that share the same service date and block * Connect area boundary to entrance points inside it to prevent pruning * Add better test data for testing area processing of stop_area relations * Validate to/from in routing request * Add changelog entry for opentripplanner#5152 [ci skip] * Bump serialization version id for opentripplanner#5152 * Stop area linking tests * Changing default value for earlyStartSec * Add some documetation about stop area relations * Fix formatting * Add support for mapping NeTEx operating day in operating period * Add error mapping in REST API * Update documentation * Add new doc page to mkdocs.yml * Move getLevel to OSMWithTags andd simplify it * Test also layer tag relevance in stop area processing * Fix misleading data report issue content from stop area processing * Use multimap for storing stop area link nodes * Remove obsolete issue Stop area which does not have entrances or other link points is really not any kind of error * Add changelog entry for opentripplanner#5147 [ci skip] * Improve updater log messages * refactor: Apply code review - Change `earlyStartSec:int` to `earlyStart:Duration` - Add more doc on parameter * Relax validity check for flex trip with null duration * Make FlexPath fields final * refactor: Make `SiriSXUpdaterParameters#timeout` a Duration * Apply suggestions from code review * refactor: Make Siri Updaters use Duration, not int, for reminding parameters - This also remove a bit of unnecessary mapping code. * Update src/main/java/org/opentripplanner/standalone/config/routerconfig/updaters/SiriSXUpdaterConfig.java Co-authored-by: Leonard Ehrenfried <mail@leonard.io> * chore(deps): update dependency org.apache.maven.plugins:maven-surefire-plugin to v3.1.2 * Refactor shutdown hook * Add changelog entry for opentripplanner#5159 [ci skip] * Update pull_request_template.md [ci skip] * fix(deps): update dependency com.graphql-java:graphql-java to v20.4 * Use hashmultimap in src/main/java/org/opentripplanner/graph_builder/module/osm/OsmDatabase.java> Co-authored-by: Leonard Ehrenfried <mail@leonard.io> * Add HashMultimap import * Refactor first/last date getters * Split method in two * Update src/main/java/org/opentripplanner/graph_builder/module/interlining/InterlineProcessor.java Co-authored-by: Thomas Gran <t2gran@gmail.com> * More accurate tagging instructions, one example relation linked * Log warning if GBFS status reports unexpected vehicle type * Code cleanup * refactor: Cleanup TransitRouter and AccessEgressMapper * refactor: Sort values in DurationForEnum.toString to make it deterministic * refactor: Add State.containsModeWalkOnly() and DefaultAccessEgress.isWalkOnly() These methods will make it simpler to filter access/egress later * refactor: Add Duration#requireNonNegative(Duration) : Duration to DurationUtils * refactor: Implement openingHoursToString() for AccessEgress for testing Having to brows through many classes and hairy logic is time-consuming when debugging FLEX access/egress, this simplifies the process. * refactor: Move RaptorConstants into raptor.api.model package * feature: Search before the earliest-departure-time in Raptor with searchWindowAccessSlack. * refactor: Move AccessEgresses to street package * refactor: Cleanup DoubleUtils * refactor: Add requireXyz to IntUtils * refactor: Add Cost value-object * refactor: Improve int and double utilities * refactor: Small cleanups * Apply suggestions from code review Co-authored-by: Thomas Gran <t2gran@gmail.com> * Formatting * Add changelog entry for opentripplanner#5161 [ci skip] * Add changelog entry for opentripplanner#5162 [ci skip] * Add changelog entry for opentripplanner#5168 [ci skip] * Apply review suggestions * Apply review suggestions * Fix bicyle optimise type in TransmodelApi * Add test for optimize type in GraphQL API * fix(deps): update dependency com.google.guava:guava to v32.0.1-jre * Add changelog entry for opentripplanner#5167 [ci skip] * Add reusable method * Add union type for stop position * Simplify type resolving * Use interface type in data fetcher * Applied review suggestion * Add documentation * Add documentation * Apply review feedback Co-authored-by: Joel Lappalainen <lappalj8@gmail.com> * Generate new SiriUpdater doc * Add changelog entry for opentripplanner#5169 [ci skip] * Add changelog entry for opentripplanner#5175 [ci skip] * Add changelog entry for opentripplanner#5164 [ci skip] * Add changelog entry for opentripplanner#5165 [ci skip] * review: Remove serialVersionUID * Validate that from and to temporary vertices are distinct * review: Extract TestVehicleRentalStationBuilder * Reduce log severity for non-optimized transfers * Return an int as the stopPosition for StopTimes * doc: Move JavaDoc to accessors, fix typo. * fix: Improve error handling and prevent OTP from going down when connecting to external http services. The VehicleRentalServiceDirectoryFetcher went down with a IllegalSateException when the http endpoint failed. Instead of returning null in some error-cases and throwing IOExceptions in others the HttpUtils is changed to throw an IOException in all cases. This make it more robust, and the checked exception forces the client to handle it. * Use Finland OSM mapping as basis for constant speed mapper * Add support for taxi mode * Rename ConstansSpeedMapper to describe the new super class * Add changelog entry for opentripplanner#5153 [ci skip] * Update micrometer.version to v1.11.1 * Update src/main/java/org/opentripplanner/routing/algorithm/mapping/RaptorPathToItineraryMapper.java Co-authored-by: Thomas Gran <t2gran@gmail.com> * Apply review feedback * Update dependency ch.qos.logback:logback-classic to v1.4.8 * Add changelog entry for opentripplanner#5135 [ci skip] * Separate words with underscore in osm tag mapper enum value * Update docs * Bump serialization version id for opentripplanner#5176 * Make stop area linking more precise and capable to handle elevators * Add changelog entry for opentripplanner#5181 [ci skip] * Use EnumSet instead of Stream * Add changelog entry for opentripplanner#5183 [ci skip] * Add changelog entry for opentripplanner#5179 [ci skip] * Fix formatting in RouterConfig.md * improve: add language argument to Quay and StopPlace types deprecate lang arguments * fix: the overloaded getLocale method does not use the language argument * improve: extract shared code into helper method in transmodel GqlUtil * add test for GqlUtil.getLocale * Fix default value for bicycle safety report * Update dependency org.apache.maven.plugins:maven-shade-plugin to v3.5.0 * Update dependency net.logstash.logback:logstash-logback-encoder to v7.4 * Update dependency org.mockito:mockito-core to v5.4.0 * Add more tests for stop area linking - Test that elevators get linked - Test that stop positions will not get linked * Fix typo * Update src/main/java/org/opentripplanner/openstreetmap/model/OSMWithTags.java Co-authored-by: Leonard Ehrenfried <mail@leonard.io> * Return set * Update src/main/java/org/opentripplanner/openstreetmap/model/OSMWithTags.java Co-authored-by: Joel Lappalainen <lappalj8@gmail.com> * Update src/main/java/org/opentripplanner/openstreetmap/model/OSMWithTags.java Co-authored-by: Joel Lappalainen <lappalj8@gmail.com> * Add changelog entry for opentripplanner#5166 [ci skip] --------- Co-authored-by: Leonard Ehrenfried <mail@leonard.io> Co-authored-by: OTP Changelog Bot <changelog-bot@opentripplanner.org> Co-authored-by: Thomas Gran <t2gran@gmail.com> Co-authored-by: vpaturet <46598384+vpaturet@users.noreply.github.com> Co-authored-by: Vincent Paturet <vincent.paturet@entur.org> Co-authored-by: renovate[bot] <29139614+renovate[bot]@users.noreply.github.com> Co-authored-by: OTP Serialization Version Bot <serialization-version-bot@opentripplanner.org> Co-authored-by: Vesa Meskanen <vesa.meskanen@cgi.com> Co-authored-by: Joel Lappalainen <lappalj8@gmail.com> Co-authored-by: Lasse Tyrihjell <lassetyr@gmail.com> Co-authored-by: Vesa Meskanen <vesa@realsoft.com> Co-authored-by: Tom Erik Støwer <testower@gmail.com>

t2gran added !Bug Apply to issues describing a bug and PRs witch fixes it. !Improvement A functional improvement or micro feature labels May 19, 2023

t2gran added this to the 2.4 (next release) milestone May 19, 2023

t2gran added the Entur Test This is currently being tested at Entur label May 19, 2023

Bartosz-Kruba self-requested a review May 23, 2023 12:12

leonardehrenfried changed the title ~~Greacefull timeout error handling~~ Greaceful timeout error handling May 23, 2023

leonardehrenfried changed the title ~~Greaceful timeout error handling~~ Graceful timeout error handling May 23, 2023

t2gran added 2 commits May 24, 2023 16:31

fix: The Response.Status.fromStatusCode fails with exception if the s…

3485843

…tatus code is 422 We want to return HTTP Status code 422, and not 500 for timeouts.

refactor: Cleanup error handling in PlannerResource

9810eca

Handle SYSTEM_ERROR and PROCESSING_TIMEOUT the same way. Timeout and system-error will show up in the OTP Debug Client.

t2gran force-pushed the otp2_greaceful_error_handling branch from 44ec9c5 to cb58d1a Compare May 24, 2023 14:40

debug: Add a busyWaitOnce() method for manual testing timeouts

87e33ef

The busyWaitOnce() is a method witch make it possible to test timeouts without interfering with the interrupts.

t2gran force-pushed the otp2_greaceful_error_handling branch from cb58d1a to 0f6b69f Compare May 24, 2023 14:43

t2gran force-pushed the otp2_greaceful_error_handling branch from 0f6b69f to 0645d76 Compare May 24, 2023 15:50

refactor: Add proper progress tracking for GraphQL timeouts.

77c5ba2

t2gran force-pushed the otp2_greaceful_error_handling branch from 0645d76 to 77c5ba2 Compare May 24, 2023 15:58

t2gran marked this pull request as ready for review May 24, 2023 15:58

t2gran requested a review from a team as a code owner May 24, 2023 15:58

leonardehrenfried self-requested a review May 25, 2023 13:54

leonardehrenfried reviewed May 25, 2023

View reviewed changes

Comment thread src/main/java/org/opentripplanner/framework/logging/ProgressTracker.java Outdated

leonardehrenfried reviewed May 25, 2023

View reviewed changes

Comment thread src/main/java/org/opentripplanner/framework/time/TimeUtils.java Outdated

leonardehrenfried requested changes May 25, 2023

View reviewed changes

Apply suggestions from code review

89c94ed

Co-authored-by: Leonard Ehrenfried <mail@leonard.io>

t2gran requested a review from leonardehrenfried May 26, 2023 21:29

Bartosz-Kruba approved these changes May 29, 2023

View reviewed changes

leonardehrenfried approved these changes May 30, 2023

View reviewed changes

t2gran merged commit bd29e0d into opentripplanner:dev-2.x May 30, 2023

t2gran deleted the otp2_greaceful_error_handling branch May 30, 2023 07:45

t2gran pushed a commit that referenced this pull request May 30, 2023

Add changelog entry for #5130 [ci skip]

a197c46

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

Graceful timeout error handling#5130

Graceful timeout error handling#5130
t2gran merged 6 commits into
opentripplanner:dev-2.xfrom
entur:otp2_greaceful_error_handling

t2gran commented May 19, 2023 •

edited

Loading

Uh oh!

codecov Bot commented May 24, 2023 •

edited

Loading

Uh oh!

t2gran commented May 24, 2023

Uh oh!

leonardehrenfried May 25, 2023

Uh oh!

t2gran May 26, 2023

Uh oh!

Uh oh!

Uh oh!

leonardehrenfried left a comment

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants

Uh oh!

Conversation

t2gran commented May 19, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Summary

fix: The Response.Status.fromStatusCode fails with exception if the status code is 422

Refactor: Cleanup error handling in PlannerResource

debug: Add a busyWaitOnce() method for manual testing timeouts

feature: Improve on the GraphQL performance on timeout

Uh oh!

codecov Bot commented May 24, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Codecov Report

Uh oh!

t2gran commented May 24, 2023

Uh oh!

leonardehrenfried May 25, 2023

Choose a reason for hiding this comment

Uh oh!

t2gran May 26, 2023

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

leonardehrenfried left a comment

Choose a reason for hiding this comment

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants

t2gran commented May 19, 2023 •

edited

Loading

codecov Bot commented May 24, 2023 •

edited

Loading