Test Cleanup - Githubissues

@WesGilster - I'm close to getting the tests online into CI, but am running into two weird issues when running them locally.

The first issue is that after I run the tests several times, the image detector tests starts failing because one of the images gets modified, and another is deleted:

        modified:   images/houghspaceline.png
        deleted:    images/outputline.png

I'm not sure why the test changes the images that are input to it, and I'm also not sure why it doesn't always happen.

The second issue is that org.area515.resinprinter.job.AbstractPrintFileProcessorTest.usingUnsupportedBuildAreaWithLiftDistance throws unexpected FreeMarker exceptions during the test but pass anyway.

The console reports a "severe" Freemarker exception yet the test passes, although it seems like it never reaches the part of the code that is supposed to be tested given the template cannot be parsed:

    [junit] SEVERE: Error executing FreeMarker template
    [junit] FreeMarker template error:
    [junit] The following has evaluated to null or missing:
    [junit] ==> buildAreaMM  [in template "G99 ${1 + buildAreaMM * 2} ;dependent on buildArea" at line 1, column 11]
    [junit]
    [junit] ----
    [junit] Tip: If the failing expression is known to be legally refer to something that's null or missing, either specify a default value like myOptionalVar!myDefault, or use <#if myOptionalVar??>when-present<#else>when-missing</#if>. (These only cover the last step of the expression; to cover the whole expression, use parenthesis: (myOptionalVar.foo)!myDefault, (myOptionalVar.foo)??
    [junit] ----
    [junit]
    [junit] ----
    [junit] FTL stack trace ("~" means nesting-related):
    [junit]     - Failed at: ${1 + buildAreaMM * 2}  [in template "G99 ${1 + buildAreaMM * 2} ;dependent on buildArea" at line 1, column 5]
    [junit] ----
    [junit]
    [junit] Java stack trace (for programmers):
    [junit] ----
    [junit] freemarker.core.InvalidReferenceException: [... Exception message was already printed; see it above ...]
    [junit]     at freemarker.core.InvalidReferenceException.getInstance(InvalidReferenceException.java:108)
    [junit]     at freemarker.core.UnexpectedTypeException.newDesciptionBuilder(UnexpectedTypeException.java:60)
    [junit]     at freemarker.core.UnexpectedTypeException.<init>(UnexpectedTypeException.java:40)
    [junit]     at freemarker.core.NonNumericalException.<init>(NonNumericalException.java:44)
    [junit]     at freemarker.core.Expression.modelToNumber(Expression.java:103)
    [junit]     at freemarker.core.Expression.evalToNumber(Expression.java:96)
    [junit]     at freemarker.core.ArithmeticExpression._eval(ArithmeticExpression.java:48)
    [junit]     at freemarker.core.Expression.eval(Expression.java:76)
    [junit]     at freemarker.core.AddConcatExpression._eval(AddConcatExpression.java:55)
    [junit]     at freemarker.core.Expression.eval(Expression.java:76)
    [junit]     at freemarker.core.Expression.evalAndCoerceToString(Expression.java:80)
    [junit]     at freemarker.core.DollarVariable.accept(DollarVariable.java:40)
    [junit]     at freemarker.core.Environment.visit(Environment.java:257)
    [junit]     at freemarker.core.MixedContent.accept(MixedContent.java:57)
    [junit]     at freemarker.core.Environment.visit(Environment.java:257)
    [junit]     at freemarker.core.Environment.process(Environment.java:235)
    [junit]     at freemarker.template.Template.process(Template.java:262)
    [junit]     at org.area515.util.TemplateEngine.buildData(TemplateEngine.java:118)
    [junit]     at org.area515.resinprinter.gcode.GCodeControl.executeGCodeWithTemplating(GCodeControl.java:184)
    [junit]     at org.area515.resinprinter.gcode.eGENERICGCodeControl$$EnhancerByMockitoWithCGLIB$$83e9082b.CGLIB$executeGCodeWithTemplating$0(<generated>)
    [junit]     at org.area515.resinprinter.gcode.eGENERICGCodeControl$$EnhancerByMockitoWithCGLIB$$83e9082b$$FastClassByMockitoWithCGLIB$$dea980e5.invoke(<generated>)
    [junit]     at org.mockito.cglib.proxy.MethodProxy.invokeSuper(MethodProxy.java:216)
    [junit]     at org.powermock.api.mockito.repackaged.DelegatingMockitoMethodProxy.invokeSuper(DelegatingMockitoMethodProxy.java:19)
    [junit]     at org.mockito.internal.invocation.realmethod.DefaultRealMethod.invoke(DefaultRealMethod.java:21)
    [junit]     at org.mockito.internal.invocation.realmethod.CleanTraceRealMethod.invoke(CleanTraceRealMethod.java:30)
    [junit]     at org.mockito.internal.invocation.InvocationImpl.callRealMethod(InvocationImpl.java:112)
    [junit]     at org.mockito.internal.stubbing.answers.CallsRealMethods.answer(CallsRealMethods.java:41)
    [junit]     at org.mockito.internal.stubbing.StubbedInvocationMatcher.answer(StubbedInvocationMatcher.java:34)
    [junit]     at org.mockito.internal.handler.MockHandlerImpl.handle(MockHandlerImpl.java:91)
    [junit]     at org.mockito.internal.handler.NullResultGuardian.handle(NullResultGuardian.java:29)
    [junit]     at org.mockito.internal.handler.InvocationNotifierHandler.handle(InvocationNotifierHandler.java:38)
    [junit]     at org.powermock.api.mockito.repackaged.MethodInterceptorFilter.intercept(MethodInterceptorFilter.java:59)
    [junit]     at org.area515.resinprinter.gcode.eGENERICGCodeControl$$EnhancerByMockitoWithCGLIB$$83e9082b.executeGCodeWithTemplating(<generated>)
    [junit]     at org.area515.resinprinter.job.AbstractPrintFileProcessor.performPostSlice(AbstractPrintFileProcessor.java:177)
    [junit]     at org.area515.resinprinter.job.AbstractPrintFileProcessor$$EnhancerByMockitoWithCGLIB$$3bf930fa.CGLIB$performPostSlice$5(<generated>)
    [junit]     at org.area515.resinprinter.job.AbstractPrintFileProcessor$$EnhancerByMockitoWithCGLIB$$3bf930fa$$FastClassByMockitoWithCGLIB$$67381bbf.invoke(<generated>)
    [junit]     at org.mockito.cglib.proxy.MethodProxy.invokeSuper(MethodProxy.java:216)
    [junit]     at org.powermock.api.mockito.repackaged.DelegatingMockitoMethodProxy.invokeSuper(DelegatingMockitoMethodProxy.java:19)
    [junit]     at org.mockito.internal.invocation.realmethod.DefaultRealMethod.invoke(DefaultRealMethod.java:21)
    [junit]     at org.mockito.internal.invocation.realmethod.CleanTraceRealMethod.invoke(CleanTraceRealMethod.java:30)
    [junit]     at org.mockito.internal.invocation.InvocationImpl.callRealMethod(InvocationImpl.java:112)
    [junit]     at org.mockito.internal.stubbing.answers.CallsRealMethods.answer(CallsRealMethods.java:41)
    [junit]     at org.mockito.internal.handler.MockHandlerImpl.handle(MockHandlerImpl.java:93)
    [junit]     at org.mockito.internal.handler.NullResultGuardian.handle(NullResultGuardian.java:29)
    [junit]     at org.mockito.internal.handler.InvocationNotifierHandler.handle(InvocationNotifierHandler.java:38)
    [junit]     at org.powermock.api.mockito.repackaged.MethodInterceptorFilter.intercept(MethodInterceptorFilter.java:59)
    [junit]     at org.area515.resinprinter.job.AbstractPrintFileProcessor$$EnhancerByMockitoWithCGLIB$$3bf930fa.performPostSlice(<generated>)
    [junit]     at org.area515.resinprinter.job.AbstractPrintFileProcessorTest.usingUnsupportedBuildAreaWithLiftDistance(AbstractPrintFileProcessorTest.java:148)
    [junit]     at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    [junit]     at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    [junit]     at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    [junit]     at java.lang.reflect.Method.invoke(Method.java:497)
    [junit]     at org.junit.internal.runners.TestMethod.invoke(TestMethod.java:68)
    [junit]     at org.powermock.modules.junit4.internal.impl.PowerMockJUnit44RunnerDelegateImpl$PowerMockJUnit44MethodRunner.runTestMethod(PowerMockJUnit44RunnerDelegateImpl.java:310)
    [junit]     at org.junit.internal.runners.MethodRoadie$2.run(MethodRoadie.java:89)
    [junit]     at org.junit.internal.runners.MethodRoadie.runBeforesThenTestThenAfters(MethodRoadie.java:97)
    [junit]     at org.powermock.modules.junit4.internal.impl.PowerMockJUnit44RunnerDelegateImpl$PowerMockJUnit44MethodRunner.executeTest(PowerMockJUnit44RunnerDelegateImpl.java:294)
    [junit]     at org.powermock.modules.junit4.internal.impl.PowerMockJUnit47RunnerDelegateImpl$PowerMockJUnit47MethodRunner.executeTestInSuper(PowerMockJUnit47RunnerDelegateImpl.java:127)
    [junit]     at org.powermock.modules.junit4.internal.impl.PowerMockJUnit47RunnerDelegateImpl$PowerMockJUnit47MethodRunner.executeTest(PowerMockJUnit47RunnerDelegateImpl.java:82)
    [junit]     at org.powermock.modules.junit4.internal.impl.PowerMockJUnit44RunnerDelegateImpl$PowerMockJUnit44MethodRunner.runBeforesThenTestThenAfters(PowerMockJUnit44RunnerDelegateImpl.java:282)
    [junit]     at org.junit.internal.runners.MethodRoadie.runTest(MethodRoadie.java:87)
    [junit]     at org.junit.internal.runners.MethodRoadie.run(MethodRoadie.java:50)
    [junit]     at org.powermock.modules.junit4.internal.impl.PowerMockJUnit44RunnerDelegateImpl.invokeTestMethod(PowerMockJUnit44RunnerDelegateImpl.java:207)
    [junit]     at org.powermock.modules.junit4.internal.impl.PowerMockJUnit44RunnerDelegateImpl.runMethods(PowerMockJUnit44RunnerDelegateImpl.java:146)
    [junit]     at org.powermock.modules.junit4.internal.impl.PowerMockJUnit44RunnerDelegateImpl$1.run(PowerMockJUnit44RunnerDelegateImpl.java:120)
    [junit]     at org.junit.internal.runners.ClassRoadie.runUnprotected(ClassRoadie.java:34)
    [junit]     at org.junit.internal.runners.ClassRoadie.runProtected(ClassRoadie.java:44)
    [junit]     at org.powermock.modules.junit4.internal.impl.PowerMockJUnit44RunnerDelegateImpl.run(PowerMockJUnit44RunnerDelegateImpl.java:122)
    [junit]     at org.powermock.modules.junit4.common.internal.impl.JUnit4TestSuiteChunkerImpl.run(JUnit4TestSuiteChunkerImpl.java:106)
    [junit]     at org.powermock.modules.junit4.common.internal.impl.AbstractCommonPowerMockRunner.run(AbstractCommonPowerMockRunner.java:53)
    [junit]     at org.powermock.modules.junit4.PowerMockRunner.run(PowerMockRunner.java:59)
    [junit]     at org.junit.runners.Suite.runChild(Suite.java:128)
    [junit]     at org.junit.runners.Suite.runChild(Suite.java:27)
    [junit]     at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
    [junit]     at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
    [junit]     at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
    [junit]     at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
    [junit]     at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
    [junit]     at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
    [junit]     at junit.framework.JUnit4TestAdapter.run(JUnit4TestAdapter.java:38)
    [junit]     at org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.run(JUnitTestRunner.java:535)
    [junit]     at org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.launch(JUnitTestRunner.java:1182)
    [junit]     at org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.main(JUnitTestRunner.java:1033)
    [junit]

I'm not sure why the test changes the images that are input to it, and I'm also not sure why it doesn't always happen.

I assume the unit test fails by throwing an exception since there are no asserts in that test. If it is indeed throwing an exception, I would need to see a stacktrace to determine what the exception is and how to fix it. What I can tell you is that those files aren't input based files. They are output only. In fact, everything contained in the images/ folder is for output purposes only. Image files that are used for input purposes are loaded through the Java's resource loading mechanism and are contained in the testing package: org.area515.resinprinter.inkdetection.visual

...unexpected FreeMarker exceptions during the test but pass anyway.

The test(and line of code) in question is: org.area515.resinprinter.job.AbstractPrintFileProcessorTest.usingUnsupportedBuildAreaWithLiftDistance(AbstractPrintFileProcessorTest.java:148)

The purpose of this test is to ensure that we are robust enough to handle different PrintFileProcessor support scenarios. Specially it defines a difference between how we handle supported vs. unsupported variables.

A completely unknown variable(UnknownVariable) will throw an InappropriateDeviceException and be handled through exception.
A known variable(buildAreaMM) that some PrintFileProcessor doesn't support, shouldn't cause the entire print to fail. It also allows a PrintFileProcessor to return 'null' for these variables and not makeup a some bad value(-1 or something) that all gcode scripts need to check as some special indicator.

The template engine itself doesn't understand the difference between these two types of variables so it throws the same error in either case, but we suppress it in the case of a known variable. There is probably an option to stop the InvalidReferenceException from being thrown by FreeMarker, but I didn't find a huge priority behind that research. If you are concerned about it showing up in the logs, we can always suppress it with log4j2 as another option.

If the images are output only, then that is indeed mysterious. I'll make sure to get more info the next time it happens.

I was confused by seeing an InvalidReferenceException at the Freemarker level and wasn't sure if that was intentionally being turned into an InappropriateDeviceException or not up the call chain. Since it is, this isn't a problem, I'll make a note of what you mentioned in the comments in case I forget later.

I fixed some pretty nasty bugs that I got tired of working around in the gui and pushed another build. I'm trying to use the new build process, and I think it's working without using the old process at all. I did however get one strange issue. Both my build and release caught the wrong commit(and tag) the first time I ran the build. Without doing anything, I ran the build a second time, and it worked fine. The one thing that I noticed is that it seemed to pull a previous commit between the two tags instead of the most recent. I'll try to record the exact output next time since I'm pretty sure I can recreate it. I didn't capture the precise commit SHA below...

Notice it picked up DEV011 instead of DEV012 (even though I specifically typed DEV012)

:setupRelease
Releasing to: [https://github.com/WesGilster/Creation-Workshop-Host]
Repo Owner: WesGilster / Repo Name: Creation-Workshop-Host
----------------------------------------------
Description of current commit: DEV011 (The commit number that occurred between DEV011 and DEV12)
UNCOMMITTED STAGED CHANGES: org.ajoberstar.grgit.Status$Changes(added:[], modified:[], removed:[])
UNCOMMITTED UNSTAGED CHANGES: org.ajoberstar.grgit.Status$Changes(added:[host/cwhClient-0.283.zip, host/cwhTestKit-0.283.zip, host/cwh.log, host/libs/pdf/PDFRenderer-0.9.0.jar, host/cwh-0.283.zip], modified:[host/build.number], removed:[])
----------------------------------------------
:githubRelease

Immediately afterwards I saw the wrong commit and ran it again without any changes, and it looked better:

:setupRelease
Releasing to: [https://github.com/WesGilster/Creation-Workshop-Host]
Repo Owner: WesGilster / Repo Name: Creation-Workshop-Host
----------------------------------------------
Description of current commit: DEV012
UNCOMMITTED STAGED CHANGES: org.ajoberstar.grgit.Status$Changes(added:[], modified:[], removed:[])
UNCOMMITTED UNSTAGED CHANGES: org.ajoberstar.grgit.Status$Changes(added:[host/cwhClient-0.283.zip, host/cwhTestKit-0.283.zip, host/cwh.log, host/libs/pdf/PDFRenderer-0.9.0.jar, host/cwh-0.283.zip], modified:[host/build.number], removed:[])
----------------------------------------------
:githubRelease

I think this is a case where the logic of the release task induces user error. What happens is that the tag picked up and used in the build is primarily not the tag you enter in the dialog, but rather the last tag you made directly with git tag before you do a gradle dist.

The tag you enter basically tells the githubRelease target which tag to upload the release to. However, the choice here is an illusion. The tag you want to upload the release to must be the tag that was in place when you did dist, because that's the tag which is baked into build.number and represents the repo state that is actually in the zip files. Since dist always happens before githubRelease, there's no way for it to know what you will enter in the future, thus the necessary procedure to release is:

git push all the source changes to make sure that there are no conflicts
git tag with a name
gradle dist
gradle githubRelease
Enter the same tag as step 2, thus making all displayed tags match up

The fact that steps 2 and 5 require the human to enter the exact same thing twice induces human error.

There are two possible ways I could simplify things, depending on how much logic we wanted to push into the build process:

Incorporate the git tag and gradle dist into an uber tag-build-release task. In this case, the script will prompt you for a tag, and then use it consistently. The drawback here is that if you didn't do a git push before running the uber task, then weird things may happen when the githubRelease target tries to push the tag back to the remote and things don't go smoothly. The interaction with push done through the gradle git plugin is lobotomized compared to the real git client, and there are many potential push conflicts that the gradle plugin can't handle.
Don't prompt for the tag. Check that the current tag is exactly in sync with the commits in the repo. If it is, then just use the current tag. If it's not, abort. This forces the user to properly tag the repo prior to running githubRelease. Forcing the user gesture reduces, but does not eliminate, the possibility that the user didn't also push the commits prior to running githubRelease, but generally speaking git operations done via git directly are less likely to result in inscrutable errors than when done via the gradle git plugin.

Which do you think is preferable?

Also, what happened in your case is that your existing repo tag was DEV011 and the tag you entered was DEV012. When you ran it the first time, setupRelease created tag DEV012, and then you canceled the release process. Thus, when you went in the second time, DEV012 was now the current tag.

However, the build process is tricking you into thinking that what you enter into the prompt matters. What's actually inside the zip file could be DEV011 or DEV011-#-###### (which indicates some number of commits past the last tag), but is definitely not DEV012 since you didn't create that name until after you did dist.

I had previously leanded towards (2), but now I think maybe option 1 is the way to go. I can do a dry-run of a push at the beginning and display the output, asking the user to simply confirm whether they want to proceed after seeing the results of that (strangely, the Grgit API does not give me an object that I can programmatically inspect for the dry-run status, it only logs output).

Then, it can do the tag, dist, and release all at once. I'll put together a fullRelease target that does this and we can see if we like it.

It seems like you are saying that I didn't perform the code commit and push the DEV012 tag to the remote repo before I performed the build. I don't believe that was the case, but I certainly can't say this for sure.

I'll do a better job at keeping track of commit hashes on step next time so I can be positive. If you want to know my honest opinion, I like option 1, but I'm not 100% sure the process needs to change, I just need to know precisely what I've done wrong.

I'm removing deprecated methods to eventually prepare for a stable API release(this will break compatibility with the old GUI). Open a PR when you are ready and I'll push a build with your changes.

Your question solidifies for me why option 1 is necessary. If you had pushed the DEV012 tag to remote before performing the build, you would be unable to complete the githubRelease target because it will try to push a tag that already exists and would result in an error like:

 ! [rejected]        d007 -> d007 (already exists)
error: failed to push some refs to 'git@github.com:jmkao/Creation-Workshop-Host.git'
hint: Updates were rejected because the tag already exists in the remote.

Thus, there is exactly one golden path that a release must follow, which is kind of silly because if a human has to do all these steps in the exact right order, it might as well be automated...

I'm drafting up an option (1) type task now. :)

I think you nailed the issue. I get it, I was only supposed to commit locally(I'm sure you mentioned that, I just didn't follow directions...) :(

I understand the purpose of modularizing these scripts, but I also think option 1 is our best path.

one day the armies of other contributors will thank us :)

area515 / Photonic3D

Test Cleanup #186