Movie demo: Some DB reads will be missed due to `Interceptor` not firing

When applied to https://github.com/veracitylab/provenance-demonstrator-movie, some DB reads are being detected by the agent but are not occurring inside an Interceptor, so they will not be picked up.

App started with:

wtwhite@wtwhite-vuw-vm:~/code/provenance-demonstrator-movie$ java -jar with_exploded_embedded_provenance-agent_jar_and_dummy_controller_embedded_jar.war --debug

Specifically, logging in via the web app triggers DB reads, but this request is not intercepted by the Interceptor set up to do so:

2024-03-13 16:58:33.492 DEBUG 625064 --- [nio-8080-exec-9] o.s.w.s.handler.SimpleUrlHandlerMapping  : Mapped to ResourceHttpRequestHandler [URL [file:src/main/resources/static/], Classpath [static/], ServletContext [/]]
2024-03-13 16:58:33.573 DEBUG 625064 --- [nio-8080-exec-9] o.s.jdbc.core.JdbcTemplate               : Executing prepared SQL query
2024-03-13 16:58:33.573 DEBUG 625064 --- [nio-8080-exec-9] o.s.jdbc.core.JdbcTemplate               : Executing prepared SQL statement [select username,password,enabled from users where username = ?]
recordActivity(capturedReturn=null, activityTypes=DBRead!
GlobalProvenanceTracker.track(nz.ac.wgtn.veracity.provenance.injector.model.Invocation@39506f79) called!
GlobalProvenanceTracker.track(): There are now 1 invocations tracked so far.
recordActivity(capturedReturn=null, activityTypes=DBRead!
GlobalProvenanceTracker.track(nz.ac.wgtn.veracity.provenance.injector.model.Invocation@6fcd7a6b) called!
GlobalProvenanceTracker.track(): There are now 2 invocations tracked so far.
recordActivity(capturedReturn=null, activityTypes=DBRead!
GlobalProvenanceTracker.track(nz.ac.wgtn.veracity.provenance.injector.model.Invocation@c21c9b1) called!
GlobalProvenanceTracker.track(): There are now 3 invocations tracked so far.
recordActivity(capturedReturn=null, activityTypes=DBRead!
--snip--
GlobalProvenanceTracker.track(): There are now 13 invocations tracked so far.
recordActivity(capturedReturn=null, activityTypes=DBRead!
GlobalProvenanceTracker.track(nz.ac.wgtn.veracity.provenance.injector.model.Invocation@525cf66a) called!
GlobalProvenanceTracker.track(): There are now 14 invocations tracked so far.
2024-03-13 16:58:33.591 DEBUG 625064 --- [nio-8080-exec-9] o.s.jdbc.core.JdbcTemplate               : Executing prepared SQL query
2024-03-13 16:58:33.592 DEBUG 625064 --- [nio-8080-exec-9] o.s.jdbc.core.JdbcTemplate               : Executing prepared SQL statement [select username,authority from authorities where username = ?]

Positive example of requesting /testprov with curl for comparison (note the "pre handle" and "post handle" log lines):

2024-03-13 17:12:13.126 DEBUG 625064 --- [nio-8080-exec-7] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped to nz.ac.canterbury.dataprovenancedemo.controllers.ProvenancePickupController#testProv()
2024-03-13 17:12:13.126 DEBUG 625064 --- [nio-8080-exec-7] o.s.web.servlet.DispatcherServlet        : GET "/testprov", parameters={}
2024-03-13 17:12:13.126 DEBUG 625064 --- [nio-8080-exec-7] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped to nz.ac.canterbury.dataprovenancedemo.controllers.ProvenancePickupController#testProv()
2024-03-13 17:12:13.127  INFO 625064 --- [nio-8080-exec-7] o.a.c.c.C.[Tomcat].[localhost].[/]       : pre handle: /testprov
GlobalProvenanceTracker.start() called!
2024-03-13 17:12:13.127  INFO 625064 --- [nio-8080-exec-7] o.a.c.c.C.[Tomcat].[localhost].[/]       : DummyInterceptor pre handle: /testprov
BEFORE calling dummyStaticMethod()
DummyClassForTestingProvenance.dummyStaticMethod(x=42) called, will return 126!
recordActivity(capturedReturn=null, activityTypes=DummyStaticMethod!
GlobalProvenanceTracker.track(nz.ac.wgtn.veracity.provenance.injector.model.Invocation@73213d66) called!
GlobalProvenanceTracker.track(): There are now 1 invocations tracked so far.
AFTER calling dummyStaticMethod()
2024-03-13 17:12:13.127 DEBUG 625064 --- [nio-8080-exec-7] o.s.w.s.m.m.a.HttpEntityMethodProcessor  : Using 'text/plain', given [*/*] and supported [text/plain, */*, text/plain, */*, application/json, application/*+json, application/json, application/*+json]
2024-03-13 17:12:13.127 DEBUG 625064 --- [nio-8080-exec-7] o.s.w.s.m.m.a.HttpEntityMethodProcessor  : Writing ["Hello, wurld from the provenance testing endpoint!"]
2024-03-13 17:12:13.128  INFO 625064 --- [nio-8080-exec-7] o.a.c.c.C.[Tomcat].[localhost].[/]       : DummyInterceptor post handle: /testprov
2024-03-13 17:12:13.128  INFO 625064 --- [nio-8080-exec-7] o.a.c.c.C.[Tomcat].[localhost].[/]       : post handle: /testprov
GlobalProvenanceTracker.finish() called! Will move 1 invocations to outbox.
2024-03-13 17:12:13.128  INFO 625064 --- [nio-8080-exec-7] o.a.c.c.C.[Tomcat].[localhost].[/]       : DummyInterceptor after completion: /testprov
2024-03-13 17:12:13.128 DEBUG 625064 --- [nio-8080-exec-7] o.s.web.servlet.DispatcherServlet        : Completed 200 OK

Requesting the library page (list of movies) also works:

2024-03-13 17:15:52.699 DEBUG 625064 --- [nio-8080-exec-4] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped to nz.ac.canterbury.dataprovenancedemo.controllers.LibraryController#libraryPage(Model, Optional, Optional)
2024-03-13 17:15:52.700 DEBUG 625064 --- [nio-8080-exec-4] o.s.web.servlet.DispatcherServlet        : GET "/library", parameters={}
2024-03-13 17:15:52.700 DEBUG 625064 --- [nio-8080-exec-4] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped to nz.ac.canterbury.dataprovenancedemo.controllers.LibraryController#libraryPage(Model, Optional, Optional)
2024-03-13 17:15:52.701  INFO 625064 --- [nio-8080-exec-4] o.a.c.c.C.[Tomcat].[localhost].[/]       : pre handle: /library
GlobalProvenanceTracker.start() called!
2024-03-13 17:15:52.701  INFO 625064 --- [nio-8080-exec-4] o.a.c.c.C.[Tomcat].[localhost].[/]       : DummyInterceptor pre handle: /library
2024-03-13 17:15:52.746 DEBUG 625064 --- [nio-8080-exec-4] org.hibernate.SQL                        : select movie0_.id as id1_0_, movie0_.genres as genres2_0_, movie0_.poster_url as poster_u3_0_, movie0_.release_year as release_4_0_, movie0_.title as title5_0_ from movies movie0_ limit ?
recordActivity(capturedReturn=null, activityTypes=DBRead!
GlobalProvenanceTracker.track(nz.ac.wgtn.veracity.provenance.injector.model.Invocation@7c613055) called!
GlobalProvenanceTracker.track(): There are now 1 invocations tracked so far.
recordActivity(capturedReturn=null, activityTypes=DBRead!
GlobalProvenanceTracker.track(nz.ac.wgtn.veracity.provenance.injector.model.Invocation@218005c1) called!
GlobalProvenanceTracker.track(): There are now 2 invocations tracked so far.
recordActivity(capturedReturn=null, activityTypes=DBRead!
--snip--
GlobalProvenanceTracker.track(nz.ac.wgtn.veracity.provenance.injector.model.Invocation@17d7f72b) called!
GlobalProvenanceTracker.track(): There are now 248 invocations tracked so far.
recordActivity(capturedReturn=null, activityTypes=DBRead!
GlobalProvenanceTracker.track(nz.ac.wgtn.veracity.provenance.injector.model.Invocation@565262f3) called!
GlobalProvenanceTracker.track(): There are now 249 invocations tracked so far.
recordActivity(capturedReturn=null, activityTypes=DBRead!
GlobalProvenanceTracker.track(nz.ac.wgtn.veracity.provenance.injector.model.Invocation@36173083) called!
GlobalProvenanceTracker.track(): There are now 250 invocations tracked so far.
2024-03-13 17:15:52.815  INFO 625064 --- [nio-8080-exec-4] o.a.c.c.C.[Tomcat].[localhost].[/]       : DummyInterceptor post handle: /library
2024-03-13 17:15:52.815  INFO 625064 --- [nio-8080-exec-4] o.a.c.c.C.[Tomcat].[localhost].[/]       : post handle: /library
GlobalProvenanceTracker.finish() called! Will move 250 invocations to outbox.
2024-03-13 17:15:52.816 DEBUG 625064 --- [nio-8080-exec-4] o.s.w.s.v.ContentNegotiatingViewResolver : Selected 'text/html' given [text/html, application/xhtml+xml, image/avif, image/webp, application/xml;q=0.9, */*;q=0.8]
2024-03-13 17:15:52.857  INFO 625064 --- [nio-8080-exec-4] o.a.c.c.C.[Tomcat].[localhost].[/]       : DummyInterceptor after completion: /library
2024-03-13 17:15:52.857 DEBUG 625064 --- [nio-8080-exec-4] o.s.web.servlet.DispatcherServlet        : Completed 200 OK

The plot thickens: Although Firefox doesn't show provenance-id: HTTP header for GET /favicon.ico, it is there if we directly curl it:

wtwhite@wtwhite-vuw-vm:~$ curl -i http://localhost:8080/favicon.ico
HTTP/1.1 200 
Vary: Origin
Vary: Access-Control-Request-Method
Vary: Access-Control-Request-Headers
X-Clacks-Overhead: GNU Terry Pratchett
provenance-id: 18
Last-Modified: Fri, 15 Mar 2024 01:50:54 GMT
Accept-Ranges: bytes
X-Content-Type-Options: nosniff
X-XSS-Protection: 1; mode=block
Cache-Control: no-cache, no-store, max-age=0, must-revalidate
Pragma: no-cache
Expires: 0
X-Frame-Options: DENY
Content-Type: image/x-icon
Content-Length: 67646
Date: Fri, 15 Mar 2024 02:01:43 GMT

Warning: Binary output can mess up your terminal. Use "--output -" to tell 
Warning: curl to output it to your terminal anyway, or consider "--output 
Warning: <FILE>" to save to a file.

The above output also shows X-Clacks-Overhead: GNU Terry Pratchett, indicating that an example plain Filter (from here) also runs.

This made me hopeful that perhaps Firefox was also just hiding the provenance-id: header for the POST /login request as well -- but not only is that header not there even when using curl, the Filter (which I had hoped would operate at a lower, harder-to-disable level) does not fire either 😢:

wtwhite@wtwhite-vuw-vm:~$ curl -X POST -i http://localhost:8080/login
HTTP/1.1 302 
Vary: Origin
Vary: Access-Control-Request-Method
Vary: Access-Control-Request-Headers
Set-Cookie: JSESSIONID=68C7C0E8167F27D92DC834E7F8995232; Path=/; HttpOnly
X-Content-Type-Options: nosniff
X-XSS-Protection: 1; mode=block
Cache-Control: no-cache, no-store, max-age=0, must-revalidate
Pragma: no-cache
Expires: 0
X-Frame-Options: DENY
Location: http://localhost:8080/?error
Content-Length: 0
Date: Fri, 15 Mar 2024 02:02:58 GMT

Could it be that the Filter was running, but the HTTP header it added was getting removed by later processing? No, since both the Filter and the Interceptor log to stdout but Spring logs show no sign of either of them:

2024-03-15 15:02:58.081 DEBUG 695178 --- [nio-8080-exec-2] o.s.w.s.handler.SimpleUrlHandlerMapping  : Mapped to ResourceHttpRequestHandler [URL [file:src/main/resources/static/], Classpath [static/], ServletContext [/]]
2024-03-15 15:02:58.142 DEBUG 695178 --- [nio-8080-exec-2] o.s.jdbc.core.JdbcTemplate               : Executing prepared SQL query
2024-03-15 15:02:58.143 DEBUG 695178 --- [nio-8080-exec-2] o.s.jdbc.core.JdbcTemplate               : Executing prepared SQL statement [select username,password,enabled from users where username = ?]
recordActivity(capturedReturn=null, activityTypes=DBRead!
ThreadLocalProvenanceTracker.track(nz.ac.wgtn.veracity.provenance.injector.model.Invocation@c2a56ed) called for ID NO_ACTIVE_REQUEST!
ThreadLocalProvenanceTracker.track(): There are now 1 invocations tracked so far for ID NO_ACTIVE_REQUEST.
recordActivity(capturedReturn=null, activityTypes=DBRead!
ThreadLocalProvenanceTracker.track(nz.ac.wgtn.veracity.provenance.injector.model.Invocation@3cae1e9b) called for ID NO_ACTIVE_REQUEST!
ThreadLocalProvenanceTracker.track(): There are now 2 invocations tracked so far for ID NO_ACTIVE_REQUEST.
recordActivity(capturedReturn=null, activityTypes=DBRead!
ThreadLocalProvenanceTracker.track(nz.ac.wgtn.veracity.provenance.injector.model.Invocation@5e361f75) called for ID NO_ACTIVE_REQUEST!
ThreadLocalProvenanceTracker.track(): There are now 3 invocations tracked so far for ID NO_ACTIVE_REQUEST.
recordActivity(capturedReturn=null, activityTypes=DBRead!
ThreadLocalProvenanceTracker.track(nz.ac.wgtn.veracity.provenance.injector.model.Invocation@1bfc108c) called for ID NO_ACTIVE_REQUEST!
ThreadLocalProvenanceTracker.track(): There are now 4 invocations tracked so far for ID NO_ACTIVE_REQUEST.

Is the issue POST requests generally? No, since posting to a different (and nonexistent) page triggers both the Filter and the Interceptor:

wtwhite@wtwhite-vuw-vm:~$ curl -X POST -i http://localhost:8080/nonexistent-page
HTTP/1.1 404 
Vary: Origin
Vary: Access-Control-Request-Method
Vary: Access-Control-Request-Headers
X-Clacks-Overhead: GNU Terry Pratchett
provenance-id: 19
X-Content-Type-Options: nosniff
X-XSS-Protection: 1; mode=block
Cache-Control: no-cache, no-store, max-age=0, must-revalidate
Pragma: no-cache
Expires: 0
X-Frame-Options: DENY
provenance-id: 20
Content-Type: application/json
Transfer-Encoding: chunked
Date: Fri, 15 Mar 2024 02:03:43 GMT

{"timestamp":"2024-03-15T02:03:43.635+00:00","status":404,"error":"Not Found","path":"/nonexistent-page"}wtwhite@wtwhite-vuw-vm:~$

Conclusion: Spring's auth mechanism somehow overrides the normal Servlet-spec handling for specific HTTP requests (like POST /login here) to turn off Filters (as well as turn off its own Interceptor mechanism) 😢

veracitylab / provenance-injector

Movie demo: Some DB reads will be missed due to `Interceptor` not firing #20