Tracking `URL.openConnection()` invocations for outgoing HTTP requests conflicts with `URLClassLoader`

[wtwhite]

We want to enable the provenance injector to track server-side outgoing HTTP requests, which can be funneled back to the client via the existing HTTP header mechanism.

A good candidate method to trap for this is URL.openConnection(), which is passed a URL and returns a (subclass of) URLConnection. If the URL has a http: or https: scheme, this will create a (subclass of) HttpURLConnection. (Note that despite its name, this method does not actually open a network connection -- that doesn't happen until connect() is called on the returned object. But it's reasonable to assume that this will be called.)

However, injecting the movie demo app with 41785b09df825f89ffef681b2523c48b612fd545 and a bind-jdbc.json modified to include activity and return-value entity trapping for URL.openConnection() gives the following NoClassDefFoundError for nz/ac/wgtn/veracity/provenance/injector/instrumentation/InvocationTrackingInjector at startup:

wtwhite@wtwhite-vuw-vm:~/code/provenance-demonstrator-movie$ !java
java -jar with_outgoing_web_request.war --debug
Hello world from the ProvenanceAgent!
(in ProvenanceAgent) DEBUG_testCrossAppCommunication=44
(Running inside ProvenanceAgent) ClassLoader chain for class nz.ac.wgtn.veracity.provenance.injector.instrumentation.ProvenanceAgent:
loader=jdk.internal.loader.ClassLoaders$AppClassLoader@55054057, class=class jdk.internal.loader.ClassLoaders$AppClassLoader, name=jdk.internal.loader.ClassLoaders$AppClassLoader, canonicalName=jdk.internal.loader.ClassLoaders.AppClassLoader, simpleName=AppClassLoader, typeName=jdk.internal.loader.ClassLoaders$AppClassLoader
(null, meaning the bootstrap ClassLoader)
The end.
{"executions":[{"call":{"owner":"java.net.URL","name":"openConnection"}}],"activity":"https://veracity.wgtn.ac.nz/app-provenance#MakeHttpRequest","group":"http"}
{"executions":[{"call":{"owner":"nz.ac.canterbury.dataprovenancedemo.DummyClassForTestingProvenance","name":"dummyStaticMethod"}}],"activity":"https://veracity.wgtn.ac.nz/app-provenance#DummyStaticMethod","group":"dummy"}
{"executions":[{"call":{"owner":"java.sql.DriverManager","name":"getConnection"}},{"call":{"owner":"java.sql.Statement","name":"execute*"}}],"activity":"https://veracity.wgtn.ac.nz/app-provenance#DBAccess","group":"jdbc"}
{"executions":[{"call":{"owner":"java.sql.ResultSet","signature":"()Z","name":"next"}},{"call":{"owner":"java.sql.ResultSet","name":"get*"}},{"call":{"owner":"java.sql.Statement","signature":"()Ljava/sql/ResultSet;","name":"executeQuery"}},{"call":{"owner":"java.sql.PreparedStatement","signature":"()Ljava/sql/ResultSet;","name":"executeQuery"}}],"activity":"https://veracity.wgtn.ac.nz/app-provenance#DBRead","group":"jdbc"}
{"executions":[{"call":{"owner":"java.sql.Statement","signature":"()I","name":"executeUpdate*"}},{"call":{"owner":"java.sql.PreparedStatement","signature":"()I","name":"executeUpdate"}}],"activity":"https://veracity.wgtn.ac.nz/app-provenance#DBWrite","group":"jdbc"}
{"call":{"owner":"java.net.URL","name":"openConnection"},"entity":"https://veracity.wgtn.ac.nz/app-provenance#HttpRequest","group":"http"}
{"call":{"owner":"java.sql.DriverManager","name":"getConnection"},"create":true,"source":"arg","sourceIndex":0,"entity":"https://veracity.wgtn.ac.nz/app-provenance#Database","group":"jdbc","target":"return"}
{"call":{"owner":"java.sql.Connection","name":"createStatement"},"source":"this","target":"return"}
recordActivity(capturedReturn=null, activityTypes=MakeHttpRequest)! Stacktrace:
java.lang.Throwable
    at nz.ac.wgtn.veracity.provenance.injector.instrumentation.InvocationTrackingInjector.recordActivity(InvocationTrackingInjector.java:227)
    at org.springframework.boot.loader.jar.Handler.captureJarContextUrl(Handler.java:422)
    at org.springframework.boot.loader.jar.JarFile.registerUrlProtocolHandler(JarFile.java:422)
    at org.springframework.boot.loader.Launcher.launch(Launcher.java:53)
    at org.springframework.boot.loader.WarLauncher.main(WarLauncher.java:59)
recordActivity(): end of stacktrace.
ThreadLocalProvenanceTracker.track(nz.ac.wgtn.veracity.provenance.injector.model.Invocation@7f690630) 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=MakeHttpRequest)! Stacktrace:
java.lang.Throwable
    at nz.ac.wgtn.veracity.provenance.injector.instrumentation.InvocationTrackingInjector.recordActivity(InvocationTrackingInjector.java:227)
    at org.springframework.boot.loader.LaunchedURLClassLoader.lambda$definePackage$0(LaunchedURLClassLoader.java:222)
    at java.base/java.security.AccessController.doPrivileged(Native Method)
    at org.springframework.boot.loader.LaunchedURLClassLoader.definePackage(LaunchedURLClassLoader.java:217)
    at org.springframework.boot.loader.LaunchedURLClassLoader.definePackageIfNecessary(LaunchedURLClassLoader.java:199)
    at org.springframework.boot.loader.LaunchedURLClassLoader.loadClass(LaunchedURLClassLoader.java:140)
    at java.base/java.lang.ClassLoader.loadClass(ClassLoader.java:527)
    at java.base/java.lang.Class.forName0(Native Method)
    at java.base/java.lang.Class.forName(Class.java:398)
    at org.springframework.boot.loader.MainMethodRunner.run(MainMethodRunner.java:46)
    at org.springframework.boot.loader.Launcher.launch(Launcher.java:108)
    at org.springframework.boot.loader.Launcher.launch(Launcher.java:58)
    at org.springframework.boot.loader.WarLauncher.main(WarLauncher.java:59)
recordActivity(): end of stacktrace.
ThreadLocalProvenanceTracker.track(nz.ac.wgtn.veracity.provenance.injector.model.Invocation@6574b225) called for ID NO_ACTIVE_REQUEST!
ThreadLocalProvenanceTracker.track(): There are now 2 invocations tracked so far for ID NO_ACTIVE_REQUEST.
Exception in thread "main" java.lang.NoClassDefFoundError: nz/ac/wgtn/veracity/provenance/injector/instrumentation/InvocationTrackingInjector
    at java.base/java.net.URLClassLoader.getPermissions(URLClassLoader.java:753)
    at java.base/java.security.SecureClassLoader$1.apply(SecureClassLoader.java:251)
    at java.base/java.security.SecureClassLoader$1.apply(SecureClassLoader.java:247)
    at java.base/java.util.concurrent.ConcurrentHashMap.computeIfAbsent(ConcurrentHashMap.java:1705)
    at java.base/java.security.SecureClassLoader.getProtectionDomain(SecureClassLoader.java:247)
    at java.base/java.security.SecureClassLoader.defineClass(SecureClassLoader.java:174)
    at java.base/java.net.URLClassLoader.defineClass(URLClassLoader.java:555)
    at java.base/java.net.URLClassLoader$1.run(URLClassLoader.java:458)
    at java.base/java.net.URLClassLoader$1.run(URLClassLoader.java:452)
    at java.base/java.security.AccessController.doPrivileged(Native Method)
    at java.base/java.net.URLClassLoader.findClass(URLClassLoader.java:451)
    at java.base/java.lang.ClassLoader.loadClass(ClassLoader.java:594)
    at org.springframework.boot.loader.LaunchedURLClassLoader.loadClass(LaunchedURLClassLoader.java:151)
    at java.base/java.lang.ClassLoader.loadClass(ClassLoader.java:527)
    at java.base/java.lang.Class.forName0(Native Method)
    at java.base/java.lang.Class.forName(Class.java:398)
    at org.springframework.boot.loader.MainMethodRunner.run(MainMethodRunner.java:46)
    at org.springframework.boot.loader.Launcher.launch(Launcher.java:108)
    at org.springframework.boot.loader.Launcher.launch(Launcher.java:58)
    at org.springframework.boot.loader.WarLauncher.main(WarLauncher.java:59)

Note: The provenance injector instrumentation inserts calls to recordActivity() immediately after the method invocation corresponding to a tracked activity (here, URL.openConnection()) returns, so its stacktrace logs show no stack frame for that specific method invocation.

It's confusing that the error is NoClassDefFoundError, since recordActivity() is defined inside that very class, and logs show it definitely executes, so the JVM must have found the class successfully at least once. But I can see how there could be some kind of chicken-and-egg problem: The second call to recordActivity() takes place while trying to load some class (i.e., with java.base/java.lang.ClassLoader.loadClass() higher in the stack) -- i.e., in the process of Spring Boot (or possibly the JVM itself) trying to load some class, it calls java.net.URLClassLoader.getPermissions() which itself calls URL.openConnection() (not an exact line number match, but close), triggering the trap.

Possible solutions:

1. Hopefully we can simply add java.net.URLClassLoader to a new, special ignore list that specifies class names in addition to packages (just adding java.net to ignorePackages would be too broad). This is easy and should fix this specific case, but it might be that lots of other code in the JVM or Spring Boot also calls URL.openConnection() and we wind up playing whack-a-mole. Evidence for whack-a-mole:
   • the first logged call to recordActivity() occurs inside a call to org.springframework.boot.loader.jar.Handler.captureJarContextUrl(), which presumably calls URL.openConnection() to load files from a jar
   • there's a second URL.openConnection() callsite within URLClassLoader
2. Change the current semantics for trapping of PROV-DM activities from trapping on exactly-matching "static" method call signatures (which will trap calls that wind up going to overriding methods in subclasses) to exactly-matching the actually-dynamically-called methods, and change our trap in bind-jdbc.json to be on all subclasses of URLStreamHandler that handle HTTP or HTTPS connections. The assumption behind trapping on URLStreamHandler subclasses is that URL.openConnection() simply delegates to these (this is suggested by the former's javadoc and is plausible). This approach also doesn't guarantee that whack-a-mole won't be needed, but I think it would prevent the error here and would also get rid of the jar: scheme false positive. But:
   • It's tricky, since exactly-matching "dynamic" called methods means trapping inside called methods instead of at callsites (similar to how entity tracking works now).
   • It's fragile: The user needs to determine and specify entries in bind-jdbc.json for the complete list of all subclasses that could ever be called. Eventually we'd want to give the user the option to build this list automatically at instrumentation time (i.e., simulate the current exact-static-call matching behaviour), which would make it more robust but is more work.
   • We may want to keep the option of supporting both kinds of matching

Next step: Try possible solution 1, and hope for low mole count.

[wtwhite]

In fact we can reuse the existing ignorePackages since it just does a prefix match on the fully qualified class name.

Doing this (df28b66befd1302821f906d57d0c9ee0b31f3c2e) gives us 70573 presumably-irrelevant provenance records before any HTTP requests are handled, but no crash at startup:

--snip--
recordActivity(capturedReturn=null, activityTypes=MakeHttpRequest)! Stacktrace:
java.lang.Throwable
    at nz.ac.wgtn.veracity.provenance.injector.instrumentation.InvocationTrackingInjector.recordActivity(InvocationTrackingInjector.java:227)
    at org.springframework.boot.loader.LaunchedURLClassLoader.clearCache(LaunchedURLClassLoader.java:305)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.base/java.lang.reflect.Method.invoke(Method.java:566)
    at org.springframework.boot.ClearCachesApplicationListener.clearClassLoaderCaches(ClearCachesApplicationListener.java:44)
    at org.springframework.boot.ClearCachesApplicationListener.onApplicationEvent(ClearCachesApplicationListener.java:35)
    at org.springframework.boot.ClearCachesApplicationListener.onApplicationEvent(ClearCachesApplicationListener.java:30)
    at org.springframework.context.event.SimpleApplicationEventMulticaster.doInvokeListener(SimpleApplicationEventMulticaster.java:176)
    at org.springframework.context.event.SimpleApplicationEventMulticaster.invokeListener(SimpleApplicationEventMulticaster.java:169)
    at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:143)
    at org.springframework.context.support.AbstractApplicationContext.publishEvent(AbstractApplicationContext.java:421)
    at org.springframework.context.support.AbstractApplicationContext.publishEvent(AbstractApplicationContext.java:378)
    at org.springframework.context.support.AbstractApplicationContext.finishRefresh(AbstractApplicationContext.java:938)
    at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:586)
    at org.springframework.boot.web.servlet.context.ServletWebServerApplicationContext.refresh(ServletWebServerApplicationContext.java:145)
    at org.springframework.boot.SpringApplication.refresh(SpringApplication.java:754)
    at org.springframework.boot.SpringApplication.refreshContext(SpringApplication.java:434)
    at org.springframework.boot.SpringApplication.run(SpringApplication.java:338)
    at org.springframework.boot.SpringApplication.run(SpringApplication.java:1343)
    at org.springframework.boot.SpringApplication.run(SpringApplication.java:1332)
    at nz.ac.canterbury.dataprovenancedemo.DataProvenanceDemoApplication.main(DataProvenanceDemoApplication.java:30)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.base/java.lang.reflect.Method.invoke(Method.java:566)
    at org.springframework.boot.loader.MainMethodRunner.run(MainMethodRunner.java:49)
    at org.springframework.boot.loader.Launcher.launch(Launcher.java:108)
    at org.springframework.boot.loader.Launcher.launch(Launcher.java:58)
    at org.springframework.boot.loader.WarLauncher.main(WarLauncher.java:59)
recordActivity(): end of stacktrace.
ThreadLocalProvenanceTracker.track(nz.ac.wgtn.veracity.provenance.injector.model.Invocation@60cd13d7) called for ID NO_ACTIVE_REQUEST!
ThreadLocalProvenanceTracker.track(): There are now 70573 invocations tracked so far for ID NO_ACTIVE_REQUEST.
2024-05-27 15:46:56.785  INFO 2696190 --- [           main] n.a.c.d.DataProvenanceDemoApplication    : Started DataProvenanceDemoApplication in 42.183 seconds (JVM running for 44.057)
2024-05-27 15:46:56.844 DEBUG 2696190 --- [           main] o.s.b.a.ApplicationAvailabilityBean      : Application availability state LivenessState changed to CORRECT
2024-05-27 15:46:56.845 DEBUG 2696190 --- [           main] o.s.b.a.ApplicationAvailabilityBean      : Application availability state ReadinessState changed to ACCEPTING_TRAFFIC

Rating a movie indeed records a MakeHttpRequest activity, though the associatedEntities array is empty (EDIT: use correct version):

--snip--
    {
        "activities": [
            {
                "id": "e87dc041-d6c3-4c6f-a3cd-77b8d947e4df",
                "type": "MakeHttpRequest",
                "endTime": "2024-05-27T04:40:07.415968Z"
            }
        ],
        "associatedEntities": []
    }
--snip--

Server logs also show that recordActivity() is being called with a null first argument instead of the return value we want:

--snip--
ThreadLocalProvenanceTracker.track(): There are now 6 invocations tracked so far for ID 37.
2024-05-27 16:40:07.272  INFO 2699499 --- [nio-8080-exec-6] n.a.c.d.controllers.LibraryController    : Server will send outgoing HTTP request to https://app.veracity.homes/omar-notifications-main-menu.html?name=jens&movieId=44&stars=4 -- let's see if it's picked up.
recordActivity(capturedReturn=null, activityTypes=MakeHttpRequest)! Stacktrace:
java.lang.Throwable
    at nz.ac.wgtn.veracity.provenance.injector.instrumentation.InvocationTrackingInjector.recordActivity(InvocationTrackingInjector.java:227)
    at nz.ac.canterbury.dataprovenancedemo.controllers.LibraryController.getHTML(LibraryController.java:171)
    at nz.ac.canterbury.dataprovenancedemo.controllers.LibraryController.rateMovie(LibraryController.java:161)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
--snip--

The absence of DEBUG: Called method: ... in the previous log shows that the instrumentation did not find any entities to record, though it should.

[wtwhite]

Part of the problem was I had been misusing a build script, causing bind-jdbc.json not to update the way it should. After fixing this, it partially works -- server logs now show the URL being captured:

--snip--
ThreadLocalProvenanceTracker.track(): There are now 6 invocations tracked so far for ID 37.
2024-05-27 17:12:03.543  INFO 2702242 --- [nio-8080-exec-6] n.a.c.d.controllers.LibraryController    : Server will send outgoing HTTP request to https://app.veracity.homes/omar-notifications-main-menu.html?name=jens&movieId=33&stars=4 -- let's see if it's picked up.
recordActivity(capturedReturn=sun.net.www.protocol.https.DelegateHttpsURLConnection:https://app.veracity.homes/omar-notifications-main-menu.html?name=jens&movieId=33&stars=4, activityTypes=MakeHttpRequest)! Stacktrace:
java.lang.Throwable
    at nz.ac.wgtn.veracity.provenance.injector.instrumentation.InvocationTrackingInjector.recordActivity(InvocationTrackingInjector.java:227)
    at nz.ac.canterbury.dataprovenancedemo.controllers.LibraryController.getHTML(LibraryController.java:171)
    at nz.ac.canterbury.dataprovenancedemo.controllers.LibraryController.rateMovie(LibraryController.java:161)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
--snip--

However, this info is not yet available in the recovered provenance data pulled down via curl -i http://localhost:8080/prov/37:

    {
        "activities": [
            {
                "id": "c5b855d6-c862-4ff1-858f-a65ff5e974aa",
                "type": "MakeHttpRequest",
                "endTime": "2024-05-27T05:12:03.659569Z"
            }
        ],
        "associatedEntities": []
    }

[wtwhite]

There are (at least) 2 problems:

1. recordParameter() calls are not being injected for URL.openConnection() at all (injections are absent from logs).
2. recordParameter() calls are being injected for java.sql.DriverManager.getConnection() (injections are present in logs), but recordParameter() is never actually running, implying that java.sql.DriverManager.getConnection() is never running either. This is puzzling, since even if getConnection() was being called reflectively (which I think would not currently trigger recordActivity()), the injected recordParameter() calls should still run (and log).

As a sanity check, I made GET /testprov directly call a dummy static method dummyStaticMethod() that just appends a string to a string argument and returns it, and added activity tracking and entity tracking to bind-jdbc.json for it. Fetching that endpoint with curl and then fetching the resulting provenance data with GET /prov/1 does produce associated entities!

--snip--
    {
        "activities": [
            {
                "id": "ac4a458b-f0e8-4dfd-9e71-16fc13243149",
                "type": "DummyStaticMethod",
                "endTime": "2024-05-28T02:28:20.981013Z"
            }
        ],
        "associatedEntities": [
            {
                "id": 2145212849,
                "type": "DummyStaticMethodArg",
                "value": "foo",
                "target": "foo<this added to the end by dummyStaticMethod()>"
            }
        ]
    },
--snip--

So the associated entity machinery is in some sense working -- the issue is elsewhere, possibly in deep magic done by Spring Boot 😬

[wtwhite]

Changing the activity name for java.sql.DriverManager.getConnection() calls from DBAccess to DBOpen (so that it won't be conflated with calls to execute*()) shows that none of the methods with this name (there are several) are actually being called (no DBOpen in logs). As noted above, logs show recordParameter() calls are being injected into these methods, and we do see DBAccess, DBRead and DBWrite activities recorded from subsequent calls to DB read and write methods, so either:

1. No getConnection() call is actually ever being made, implying that we are getting the DB handle (needed for later DB reads and writes) some other way, or
2. Something very weird is happening with classloaders, like DriverManager being loaded twice by different classloaders and "the wrong copy" being instrumented (let's hope it's not this).

First thing to try is to make a direct call to getConnection() from some dummy endpoint and see if we can see that call.

[wtwhite]

First mystery solved: java.sql.DriverManager.getConnection() is really not being called at all, getDrivers() is instead:

wtwhite@wtwhite-vuw-vm:~/code/provenance-demonstrator-movie$ grep -n DBGetDriver stdout.txt 
10:{"executions":[{"call":{"owner":"java.sql.DriverManager","name":"getDriver"}}],"activity":"https://veracity.wgtn.ac.nz/app-provenance#DBGetDriver","group":"jdbc"}
11:{"executions":[{"call":{"owner":"java.sql.DriverManager","name":"getDrivers"}}],"activity":"https://veracity.wgtn.ac.nz/app-provenance#DBGetDrivers","group":"jdbc"}
2454123:recordActivity(capturedReturn=null, activityTypes=DBGetDrivers)! Stacktrace:

This returns an Enumeration<Driver>, which the calling code will look through and call connect() on one of the Drivers to get a Connection, thus bypassing DriverManager.getConnection(). Some of the stacktrace:

2454123:recordActivity(capturedReturn=null, activityTypes=DBGetDrivers)! Stacktrace:
2454124-java.lang.Throwable
2454125-    at nz.ac.wgtn.veracity.provenance.injector.instrumentation.InvocationTrackingInjector.recordActivity(InvocationTrackingInjector.java:237)
2454126-    at com.zaxxer.hikari.util.DriverDataSource.<init>(DriverDataSource.java:60)
2454127-    at com.zaxxer.hikari.pool.PoolBase.initializeDataSource(PoolBase.java:331)
2454128-    at com.zaxxer.hikari.pool.PoolBase.<init>(PoolBase.java:114)
2454129-    at com.zaxxer.hikari.pool.HikariPool.<init>(HikariPool.java:108)
2454130-    at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:112)
2454131-    at org.springframework.boot.autoconfigure.h2.H2ConsoleAutoConfiguration.lambda$h2Console$0(H2ConsoleAutoConfiguration.java:67)
2454132-    at org.springframework.beans.factory.support.DefaultListableBeanFactory$DependencyObjectProvider.ifAvailable(DefaultListableBeanFactory.java:2035)
2454133-    at org.springframework.boot.autoconfigure.h2.H2ConsoleAutoConfiguration.h2Console(H2ConsoleAutoConfiguration.java:66)
2454134-    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
2454135-    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
2454136-    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
2454137-    at java.base/java.lang.reflect.Method.invoke(Method.java:566)

I don't yet see how to "thread" the resulting Connection through to later DB read/write method calls, but that's a problem for down the road. The immediate problem now is to figure out why recordParameter() calls are not being injected for URL.openConnection() at all, even though they are for DriverManager.getConnection().

[wtwhite]

URL.openConnection() never gets a call to recordParameter() injected into it because it is never passed to our implementation of ClassFileTransformer.transform(), which will be because it was already loaded by the JVM by the time the agent is installed (presumably the JVM itself uses it to access resources inside jars) 🤪 This is despite the fact that we call Instrumentation.addTransformer() with the canRetransform parameter set to true, and META-INF/MANIFEST.MF includes

Can-Redefine-Classes: true
Can-Retransform-Classes: true

Instrumentation has a method redefineClasses(), which hopefully can be used to wriggle out of this situation.

[wtwhite]

[Instrument.getAllLoadedClasses()](https://docs.oracle.com/en/java/javase/11/docs/api/java.instrument/java/lang/instrument/Instrumentation.html#getAllLoadedClasses()) shows that java.net.URL is indeed already loaded by the time our agentmain() runs:

wtwhite@wtwhite-vuw-vm:~/code/provenance-demonstrator-movie$ grep 'java.net.URL ' stdout.txt 
Already loaded class: java.net.URL (loader: null)

[wtwhite]

af7a2a0e9fb45618cc26e14ad7a2366b13f04a13 calls retransform() specifically for java.net.URL, and logs show that it completes without throwing, but nevertheless there is no call to transform() in the logs and no associated entities after rating a movie. 😢