GroovyScripeEngine fails to properly reload when dependent class is updated

I've ran into a similar issue. For me, the problem presented itself as a class cast exception after a runtime update of some scripts.

The attached patches are:

• a patch to the GroovyScriptEngineReloadTest, for testing for this (non-deterministic) phenomenon. Both the case reported by David and 'my' problem are included as test cases.
• a patch to the GroovyScriptEngine that solves this problem. The solution works, but is pretty crude.

Both patches are relative to the 1.8.4 sources.

I hope this can be included in the next release. We're using the script engine inside a process engine we've written to replace BPEL in our organisation, using Groovy as a process definition language. Works great, but because of this issue we have to restart the entire engine every time we change a process.

in the CompilerConfiguration is a reloading interval as option you can influence... could that be used here?

Hi Jochen,

I've looked into that, but that doesn't solve the problem. The unit tests I provided set the config.minimumRecompilationInterval value to 0 ms, and sleep for 20ms between modifying the scripts and using them through the scripting engine. This should be non-problematic, but it is.

Regards,
Frans

only the thing is, your patch more or less sets the time code for every entry to about 1s in the past. Unless minimumRecompilationInterval is set higher it will not have any effect anymore. minimumRecompilationInterval has a certain impact on performance of the engine, that is why it was introduced. Also there is the problem with getting an exact time on windows. currentTimeMillis has a resolution of about 1ms on Linux systems, but on for example XP it 15ms or more. I remember on older windows versions it was even higher. That's also why we set the minimumRecompilationInterval to 100 by default, to avoid such strange timing problems. If you wait only 20ms (or even less), then it can happen that current time will still be the same as before, thus no recompilation will happen.

Looking at isSourceNewer

 
    protected boolean isSourceNewer(ScriptCacheEntry entry) throws ResourceException {
        if (entry == null) return true;
        long now = System.currentTimeMillis();

        for (String scriptName : entry.dependencies) {
            ScriptCacheEntry depEntry = scriptCache.get(scriptName);
            long nextPossibleRecompilationTime = depEntry.lastModified + config.getMinimumRecompilationInterval();
            if (nextPossibleRecompilationTime > now) continue;

            URLConnection conn = rc.getResourceConnection(scriptName);
            // getLastModified() truncates up to 999 ms from the true modification time, let's fix that
            long lastMod = ((conn.getLastModified() / 1000) + 1) * 1000 - 1;
            // getResourceConnection() opening the inputstream, let's ensure all streams are closed
            forceClose(conn);

            if (depEntry.lastModified < lastMod) {
                ScriptCacheEntry newEntry = new ScriptCacheEntry(depEntry.scriptClass, lastMod, depEntry.dependencies);
                scriptCache.put(scriptName, newEntry);
                return true;
            }
        }

        return false;
    }

especially the

 URLConnection conn = rc.getResourceConnection(scriptName);
 // getLastModified() truncates up to 999 ms from the true modification time, let's fix that long lastMod = ((conn.getLastModified() / 1000) + 1) * 1000 - 1; 

makes me wonder if the problem is not here to be found. With reloading intervals below 1s this code may set times in the future, since we use lastMod to create a new ScriptCacheEntry. The code was added as a reaction to GROOVY-4492, the lastMod as time for the new entry is used due to GROOVY-2811 and GROOVY-4286, but I cannot see why. But I feel the fix should be in this part instead actually

There is definitely a problem. The problem is with ScriptCacheEntry.dependencies, not the timing.
The dependency graph is not correct for a second script that loads dependencies that have already been loaded.

It's demonstrated in both test. isSourceNewer is failing because ScriptCacheEntry.dependencies does not contain all of the correct entries for the second script.

It's easily evident if the tests are run in a debug session w/breakpoints set in isSourceNewer inspecting entry.dependencies.

David is correct. My original solution only hides the problem. I've run a new test similar to my original ones (attached) with a minimum recompilation interval of 2000 ms and sleeps of 5000 ms between modifying the source and using it. This is slow enough to eliminate all timing issues. In this case, the problem shows up deterministically, 100% of the time.

Any ideas on how this should be properly solved? I do have some time available to work on this, but some pointers would be useful.

I've inserted some logging into the scripting engine and my test case, results are shown below. The entire dependency between Extractor and MyBean is not managed, and looking at the code, I see nothing that should manage it. Disabling the timestamp check in 'isSourceNewer' solves the problem at the expense of disabling the entire mechanism.

[junit] Writing source code at Mon Dec 05 17:59:42 CET 2011
[junit]
[junit]
[junit] Sleeping for 10 seconds
[junit]
[junit]
[junit] Using source code
[junit] Instantiating bean
[junit] Putting into scriptcache (in parseClass): /MyBean.groovy
[junit] lastmod: Mon Dec 05 17:59:52 CET 2011
[junit] dependencies: [/MyBean.groovy]
[junit] Instantiating extractor
[junit] Putting into scriptcache (in parseClass): /Extractor.groovy
[junit] lastmod: Mon Dec 05 17:59:52 CET 2011
[junit] dependencies: [/Extractor.groovy]
[junit]
[junit]
[junit] Sleeping for 10 seconds
[junit]
[junit]
[junit] Modifying MyBean source code at Mon Dec 05 18:00:02 CET 2011
[junit]
[junit]
[junit] Sleeping for 10 seconds
[junit]
[junit]
[junit] Using modified source code
[junit] Instantiating bean
[junit] Calling isSourceNewer for entry MyBean
[junit] Checking dependency /MyBean.groovy
[junit] Putting into scriptcache (in isSourceNewer): /MyBean.groovy
[junit] lastmod: Mon Dec 05 18:00:02 CET 2011
[junit] dependencies: [/MyBean.groovy]
[junit] Putting into scriptcache (in parseClass): /MyBean.groovy
[junit] lastmod: Mon Dec 05 18:00:12 CET 2011
[junit] dependencies: [/MyBean.groovy]
[junit] Instantiating extractor
[junit] Calling isSourceNewer for entry Extractor
[junit] Checking dependency /Extractor.groovy
[junit] Not putting into scriptcache (in isSourceNewer): /Extractor.groovy
[junit] lastmod: Mon Dec 05 17:59:42 CET 2011
[junit] depEntry.lastModified: Mon Dec 05 17:59:52 CET 2011

Frans, having a test that fails deterministically each time is worth a lot! Since we now know that the dependencies are set wrong, we can concentrate on that part better and stop thinking about timing problems (the code in isSourceNewer still looks wrong to me, but we can maybe fix that one later on)

That means there might be a bug in org.codehaus.groovy.tools.gse.DependencyTracker then - or its usage... so I guess a first step would be to check if the tracker gets the dependency between MyBean and Extractor right and if they both appear then correctly in the transitive hull.

Should that work, then the next step would be to check the way the dependencies are stored, and if that is right. This part is also not so easy code and may have the bug we search for.

Jochen, I put logging into the DependencyTracker and that seems to be working correctly. I also checked how they are stored in the scriptcache, and how the transitive hull is calculated. Seems to be working correctly as well. I think the problem is that this information is not being used.

I changed GroovyScriptEngine#isSourceNewer in such a way that when an entry is updated, existing entries that depend on the updated entry are removed from the cache. This forces recompilation when they are accessed. The relevant fragment is shown below. With this modification, the unit test passes. Is this an acceptable solution?

 
if (depEntry.lastModified < lastMod) {
     ScriptCacheEntry newEntry = new ScriptCacheEntry(depEntry.scriptClass, lastMod, depEntry.dependencies);
     scriptCache.put(scriptName, newEntry);
     /* Removing entries from cache that depended on the entry we just updated; these should be recompiled. */ 
     for(Map.Entry<String, ScriptCacheEntry> currentEntry : scriptCache.entrySet()) {
          if(!currentEntry.getKey().equals(scriptName) &&
              currentEntry.getValue().dependencies.contains(scriptName)) {
              scriptCache.remove(currentEntry.getKey());
          }
     }
     return true;
}

Some more results: the change I proposed in my previous comment certainly fixes one problem, but not all. In the more complex case, the registration/calculation of the dependencies seems broken as well. I'll look into that next.

I've created a new patch to fix this issue. It contains a new unit test, a small change to DependencyTracker, and several changes to GroovyScriptEngine.

To summarise, I found and (I think) corrected the following issues:

1. After a class is updated because a newer version of the script is found, all classes that directly or indirectly depend on it are no longer valid. This means they must be removed from the scriptcache (as per my previous comment), but also from the classloader cache (new in this patch).

2. If we have dependencies (A->C) and (B->C), and we first compile A (compilation unit (A,C)), compiling B later on would fail to detect the dependency on C. The reason was that in this case, class C is not identified as a primary node in the semantic analysis and is thus ignored in the dependency tracker. I've modified the tracker and the scripting engine to ignore the 'primary node' status in case we're dealing with a previously seen scripted class.

Finally got around to trying this patch.
It works beautifully thus far. Thanks Frans.

Hopefully the groovy team will include this is a release soon.

Hi David,

Thanks for trying it out. I've discussed this patch on the Groovy dev list. Jochen Theodorou had some very valid criticisms on this patch, it runs fine in the unit tests but it's not completely reliable in all circumstances.

Once I find some time (hopefully next week) I'll try to create a new patch that addresses these problems.

Regards,
Frans

Any update on this? We believe this bug may be causing a nasty side effect of recompiling scripts on each use resulting
in frequent PermGen errors for server side applications.

http://groups.google.com/group/gaelyk/browse_thread/thread/58ff42f7d679b23b

Frans, did you have time to integrate Jochen's suggestions in a new patch?

Shouldn't DependencyTracker#visitCastExpression(org.codehaus.groovy.ast.expr.CastExpression) be called for that cast to MyBean in Extractor.groovy (see GroovyScriptEngineReloadingSlowTest.groovy), so that MyBean.groovy, along with Extractor.groovy, gets registered as dependency of Extractor?

When I debuged, visitCastExpression didn't get called, and Extractor, like in Frans' log output, had only Extractor.groovy as dependency.

I am looking now into this again freshly... RealodTest#testReloadWith2ScriptsDependentOnSameBean looks good and produces the problem, so I will use that... In a first call we request script1, that will create a dependency for script1 on itself and Bean, as it should. In the next run we request script2, that also depends on Bean, but as found out earlier in here, it is not added as dependency, because it is no primary node.

Frans patch tried to change that here and ignore the primary node state. Doing so will correctly ensure the dependency, but it will not recompile Bean the first time. That means if we would make a test in which first script2 is loaded and we then change Bean to then load script1, we would still not get a recompiled Bean. Testing this with a modified version of ReloadTest I can confirm this.

Solving this problem would most probably also solve the other problems

After further thinking I tend to say that ResolveVisitor is here not doing the right thing for us. ResolveVisitor resolves Bean to a precompiled class, as it already exists. It is done with that and now happily assumes all is fine. But in our case we want Bean maybe to be enlisted in the compilation queue, with our own check for if the source is newer or not. ResolveVisitor is clearly lacking some abstraction in that section, making a nice solution difficult.

The issue should be fixed now. It required me to hook into ResolveVisitor in a way, that was not planned before, but well, there is a clean way now and the reload test from before works now. It would be nice to here of you people here if this new versions resolves the issues you had

I'm testing w/1.8.8-SNAPSHOT and I'm getting the same result. The test is also still failing for me.

if you say you test with 1.8.8 SNAPSHOT, you mean you compiled it from our repository? And you say the here attached ReloadTest.groovy does not work for you?

I just tested to be sure. I got the SNAPSHOT from http://snapshots.repository.codehaus.org/org/codehaus/groovy/groovy-all/1.8.8-SNAPSHOT/ and executed ReloadTest.groovy. Actually ReloadTest.groovy has a bug, the line:

path = new File(dir + "ReloadTest");

should be (on my system at least)

path = new File(dir,"ReloadTest");

. After changing the two times this appaears the test executes and works for me

Tried again, the tests did pass for me.

So you tried ReloadTest and the test just failed by saying the bean had the wrong value? Or was there any exception? Any idea what could be wrong?

Everything is good. All tests in ReloadTest passed for me. No exceptions.

Ah sorry David... don't know what I was smoking You actually confirmed it being fixed. Thanks for the help

Groovy 1.8.8 does not solve the problem for me. The tests (both the Groovy one and Java one) still fail randomly, both when launched from IntelliJ IDEA and when run manually from the command line. The Java test fails much more often, though - you may have to run the Groovy test several times in a row before getting a failure.

I observed a couple of facts, that I report here in hope that they will help someone who knows the GSE internals better than me to find a solution.

1. When the test fails, the 2nd dependent script has its dependencies incorrectly computed: it only depends on itself, not on the shared Bean.

2. I modified the generated scripts to print their classloader, as well as the one that loaded the Bean class. When the test passes, each script gets its own classloader, which is always also the classloader of the Bean class. In other words, each script class gets its own version of the Bean class. When the test fails, the 2nd script has a different classloader than the first, but it sees the Bean class as loaded from the 1st classloader (which I suppose should be the expected behaviour). Somehow that causes the script not be reloaded. To make it clearer, this is a printout of two sample runs:

test PASS

class script2
script classloader: groovy.lang.GroovyClassLoader$InnerLoader@186fa9fc
Instantiating bean class: groovy.lang.GroovyClassLoader$InnerLoader@186fa9fc
bean classloader: groovy.lang.GroovyClassLoader$InnerLoader@186fa9fc
class script1
script classloader: groovy.lang.GroovyClassLoader$InnerLoader@2918958e
Instantiating bean class: groovy.lang.GroovyClassLoader$InnerLoader@2918958e
bean classloader: groovy.lang.GroovyClassLoader$InnerLoader@2918958e
class script1
script classloader: groovy.lang.GroovyClassLoader$InnerLoader@87e9ce2
Instantiating bean class: groovy.lang.GroovyClassLoader$InnerLoader@87e9ce2
bean classloader: groovy.lang.GroovyClassLoader$InnerLoader@87e9ce2
class script2
script classloader: groovy.lang.GroovyClassLoader$InnerLoader@5567d7fb
Instantiating bean class: groovy.lang.GroovyClassLoader$InnerLoader@5567d7fb
bean classloader: groovy.lang.GroovyClassLoader$InnerLoader@5567d7fb

test FAIL

class script2
script classloader: groovy.lang.GroovyClassLoader$InnerLoader@36b60b93
Instantiating bean class: groovy.lang.GroovyClassLoader$InnerLoader@36b60b93
bean classloader: groovy.lang.GroovyClassLoader$InnerLoader@36b60b93
class script1
script classloader: groovy.lang.GroovyClassLoader$InnerLoader@741827d1
bean classloader: groovy.lang.GroovyClassLoader$InnerLoader@36b60b93
class script1
script classloader: groovy.lang.GroovyClassLoader$InnerLoader@741827d1
bean classloader: groovy.lang.GroovyClassLoader$InnerLoader@36b60b93
//FAIL

Note: this is from the test method testReloadWith2ScriptsDependentOnSameBeanOrderSwitched(), but similar stuff happen with testReloadWith2ScriptsDependentOnSameBean(). "Instantiating bean class" is printed from a static initializer in Bean.

Alessio, what OS are you using? Because the only part that I can imagine still failing here is that an update of the file is not seen, because of timing issues of the OS. That would also explain why it fails only sometimes. Before it should have failed always.

I'm using OSX, but I also tested it on Linux, with the same outcome. I don't think it's related to timing and the OS, because I can arbitrarily increase the wait time between writing the bean and reloading the dependent scripts, and I still get failures. The test above was using a 500ms wait, but I went up to 4500ms to no avail. Also, the two different classloader behaviours are already apparent before any reload happens: the shared Bean is modified just before the line "class script1" is printed for the second time in my example.

I made the following... I downloaded Groovy 2.0.2 and let it execute raw.github.com/groovy/groovy-core/master/src/test/groovy/util/GroovyScriptEngineReloadingTest.groovy 10 times in a row. And indeed the test is failing about once in ten times.... maybe every 6th time.

But I don't understand why. If it is no timing issue, then I would have put my finger on a concurrency issue, but with 4500ms wait time, that is unlikely as well. The symptoms are clear of course. I mean the classloader being the same and all. The question is more what the cause is.

Why does it work one time and another time it does not?

One thing that I thought that could cause nondeterminism is the garbage collector. I saw that a few caches are held in thread-local weak references; maybe if they're garbage collected too early some important information could be lost. I passed the -verbose:gc flag to the JVM, but it only prints something at the beginning; OTOH, I don't know whether it only prints full GC or it is more detailed.

As for concurrency, I'm convinced that there's only one thread; I put print statements in a few places to be sure.

Closing now that spam removed.

I took my analysis further and I can now say that timing is, indeed, part of the issue - but only because it's exposing a deeper problem.

There are two timestamps being compared to decide whether to recompile a file: one is the file modification time, rounded up to the next second; the other is the script compilation time, not rounded. The first is computed at line 595 in GroovyScriptEngine - long lastMod = ((conn.getLastModified() / 1000) + 1) * 1000 - 1;. The second is at line 240, long now = System.currentTimeMillis();. When a file is compiled (the shared Bean in our case), the rounded up time may end up being earlier or later than the compilation time, in a nondetermistic way, because of the rounding. This alone should not be a big problem - at worst, it would sometimes cause unnecessary recompilations. But...

...the logic that records dependencies between files is flawed; a dependency between file A and file B is only recorded when B is compiled in the same compilation unit as A. If B is not recompiled, the dependency is not recorded. This is caused by the fact that the DependencyTracker is invoked by a PrimaryClassNodeOperation (GSE, lines 165 - 175). I don't know the specifications of the various compiler phases, but certainly I can see that, by manually altering the source file last modification date, I can cause the dependency to be deterministically recorded or not, i.e. dt.visitClass(classNode); (line 173) being executed or not, depending on whether the modification date is forcibly set in the future or in the past. You can obtain the same effect also by causing a big enough sleep (say, 2000ms) between writing Bean.groovy and writing the scripts.

So, those unnecessary recompilations caused by the timing problem are actually necessary for the dependency to be recorded. That's why in our app it consistently fails - the shared classes are compiled much later than their last modification.

Does it make sense to you?

I am currently preparing a fix for the first issue you mention. It seems this new version is excluding the timing issue finally. I am going to push that soon and it would be good of you if you could test it as well. I will comment here as soon as it is available, since it is getting late here.

The second part of your comment is something that should not be true anymore. Since the latest version there is a new element called ClassNodeResolver involved. This is used to resolve class names and eventually enqueue new sources. For every script cache entry of GSE that has been requested, a new source unit will be added, if the source is newer. If not, then no recompilation will happen. It is true that the dependencies are not fully right then, yes... but actually I think the dependency tracking is now surplus, since the ClassNodeResolver will do that job implicitly and much better. Actually I am wondering if I should not remove the tracker even.

I filled GROOVY-5713 as follow-up issue

Thanks for addressing the timing issue!

As for the other point, I hadn't realized that the ClassNodeResolver was meant to replace the PrimaryClassNodeOperation. Unfortunately, I don't think that you can do without dependency tracking. The ClassNodeResolver is only invoked when a file is compiled; what if a file is not modified (compared to the cached version), but one of its dependencies was modified? Without dependency tracking, the dependency won't be recompiled. In other words, the ClassNodeResolver works top-down, while the decision to recompile or not should be a bottom-up process.

You are right... as often, almost right after writing that we may not need the tracker it dawned on me, that I said something stupid Of course some of the logic would have to be moved to the ClassNodeResolver and there we don't know the "cause" of the request, this it is impossible to make the connection, thus we need the tracker in the end still.

I just did the commit for GROOVY_1_8_X with my new version. Is it possible for you to check if that helps you?

Nope, I ran the test again with 1.8.9-SNAPSHOT from Git and it still fails nondeterministically.

full determinism is impossible to achieve. UrlConnection.getLastModified may not know milliseconds, that is why there is this truncation. truncating the modification time means that if your change has been done too fast, it cannot be picked up, since it has the same time as before. So you need 1000 ms minimum delay to ensure the time in last modified is updated properly. But it is actually more, since the OS has a timer with differing resolution. A delay of 1100ms should catch most cases, but that does not guarantee the change will be picked up right away. actually the next possible point of a recompilation is time of last compilation plus 1100 plus minimum recompilation interval.

Ok, let's step back a bit: I don't have a problem with nondeterminism per se - the problem is that GSE doesn't properly reload dependencies, ever, unless a dependency is found to be modified later than it was compiled (due to nondeterminism). That is, nondeterminism is what makes the test pass sometimes, not fail. If you eliminate nondeterminism (for example, by ensuring that there is a long enough sleep between writing Bean.groovy and loading the scripts for the first time), the test always fails.

Alessio, after totally rewriting the tests to not to use the file system anymore, but something custom I found that you are right in more than one way. It was indeed the case that a precompiled dependency is not picked up. This is now basically fixed. I still have a problem to solve though...

In he current setup if I have script1 depending on Bean and script2 depending on it as well, if I recompiled script1 and Bean, because Bean changed, then script2 will not be recompiled, because the entries are all up to date

the issue was marked as fixed for 2.0.2 and 1.8.8, but it seems due to the tests not always showing the real problem it was only partially fixed. This new version in 2.0.5 and 1.8.9 should finally fix the issue of not picking up dependencies. It is still no 100% satisfying solution to me, but at least it works