.Zip of images failing on repeat of a print

[WGAndrew]

Failed Unable to delete directory /tmp/printdir/charmander_starter_1gen_flowalistik.STL.zipextract/slices.Zip of Slice Images (can post the full log if needed but seems pretty straightfoward)

I'm guessing this is just a quick case of needing to delete the old dir on either cancel, print fail or print success?

[WesGilster]

Yeah, sounds pretty simple. I'll fix tonight.

[WesGilster]

I'm not able to reproduce this. I may need the full logs. Is this easily reproducible?

[WesGilster]

I've tried cancelling and then starting the job. I've also tried allowing the job to complete and then starting the job again.

[WGAndrew]

Sorry Wes, only had a chance to get to the log files today. Here's the pertinent bit: [basically started this on a new install, so there wasn't anything prior in the directory.]

2016-10-27 17:36:21,890 INFO o.a.r.j.ZipImagesFileProcessor [qtp3625098-16] Accepting new printable charmander_starter_1gen_flowalistik.STL.zip as a Zip of Slice Images 2016-10-27 17:36:22,161 ERROR o.a.u.ExceptionMarshaller [qtp3625098-16] Error caught by exception marshaller and relayed to browser org.area515.resinprinter.exception.SliceHandlingException: org.area515.resinprinter.job.JobManagerException: Couldn't clean directory for new job:/tmp/printdir/charmander_starter_1gen_flowalistik.STL.zipextract at org.area515.resinprinter.job.ZipImagesFileProcessor.renderPreviewImage(ZipImagesFileProcessor.java:139) ~[photonic3d.jar:?] at org.area515.resinprinter.job.AbstractPrintFileProcessor.buildPreviewSlice(AbstractPrintFileProcessor.java:470) ~[photonic3d.jar:?] at org.area515.resinprinter.services.CustomizerService.projectImage(CustomizerService.java:139) ~[photonic3d.jar:?] at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.8.0_101] at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:1.8.0_101] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_101] at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_101] at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:137) ~[resteasy-jaxrs-3.0.9.Final.jar:?] at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTarget(ResourceMethodInvoker.java:296) ~[resteasy-jaxrs-3.0.9.Final.jar:?] at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:250) ~[resteasy-jaxrs-3.0.9.Final.jar:?] at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:237) ~[resteasy-jaxrs-3.0.9.Final.jar:?] at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:356) [resteasy-jaxrs-3.0.9.Final.jar:?] at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:179) [resteasy-jaxrs-3.0.9.Final.jar:?] at org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher.service(ServletContainerDispatcher.java:220) [resteasy-jaxrs-3.0.9.Final.jar:?] at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:56) [resteasy-jaxrs-3.0.9.Final.jar:?] at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:51) [resteasy-jaxrs-3.0.9.Final.jar:?] at javax.servlet.http.HttpServlet.service(HttpServlet.java:790) [javax.servlet-api-3.1.0.jar:3.1.0] at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:835) [jetty-servlet-9.3.7.v20160115.jar:9.3.7.v20160115] at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1685) [jetty-servlet-9.3.7.v20160115.jar:9.3.7.v20160115] at org.eclipse.jetty.websocket.server.WebSocketUpgradeFilter.doFilter(WebSocketUpgradeFilter.java:225) [websocket-server-9.3.7.v20160115.jar:9.3.7.v20160115] at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1668) [jetty-servlet-9.3.7.v20160115.jar:9.3.7.v20160115] at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:581) [jetty-servlet-9.3.7.v20160115.jar:9.3.7.v20160115] at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:224) [jetty-server-9.3.7.v20160115.jar:9.3.7.v20160115] at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1158) [jetty-server-9.3.7.v20160115.jar:9.3.7.v20160115] at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:511) [jetty-servlet-9.3.7.v20160115.jar:9.3.7.v20160115] at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:185) [jetty-server-9.3.7.v20160115.jar:9.3.7.v20160115] at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1090) [jetty-server-9.3.7.v20160115.jar:9.3.7.v20160115] at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) [jetty-server-9.3.7.v20160115.jar:9.3.7.v20160115] at org.eclipse.jetty.server.handler.HandlerList.handle(HandlerList.java:52) [jetty-server-9.3.7.v20160115.jar:9.3.7.v20160115] at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:119) [jetty-server-9.3.7.v20160115.jar:9.3.7.v20160115] at org.eclipse.jetty.server.Server.handle(Server.java:517) [jetty-server-9.3.7.v20160115.jar:9.3.7.v20160115] at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:308) [jetty-server-9.3.7.v20160115.jar:9.3.7.v20160115] at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:242) [jetty-server-9.3.7.v20160115.jar:9.3.7.v20160115] at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:273) [jetty-io-9.3.7.v20160115.jar:9.3.7.v20160115] at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:95) [jetty-io-9.3.7.v20160115.jar:9.3.7.v20160115] at org.eclipse.jetty.io.SelectChannelEndPoint$2.run(SelectChannelEndPoint.java:75) [jetty-io-9.3.7.v20160115.jar:9.3.7.v20160115] at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.produceAndRun(ExecuteProduceConsume.java:213) [jetty-util-9.3.7.v20160115.jar:9.3.7.v20160115] at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.run(ExecuteProduceConsume.java:147) [jetty-util-9.3.7.v20160115.jar:9.3.7.v20160115] at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:654) [jetty-util-9.3.7.v20160115.jar:9.3.7.v20160115] at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:572) [jetty-util-9.3.7.v20160115.jar:9.3.7.v20160115] at java.lang.Thread.run(Thread.java:745) [?:1.8.0_101] Caused by: org.area515.resinprinter.job.JobManagerException: Couldn't clean directory for new job:/tmp/printdir/charmander_starter_1gen_flowalistik.STL.zipextract at org.area515.resinprinter.job.CreationWorkshopSceneFileProcessor.prepareEnvironment(CreationWorkshopSceneFileProcessor.java:248) ~[photonic3d.jar:?] at org.area515.resinprinter.job.ZipImagesFileProcessor.renderPreviewImage(ZipImagesFileProcessor.java:116) ~[photonic3d.jar:?] ... 40 more Caused by: java.io.IOException: Unable to delete directory /tmp/printdir/charmander_starter_1gen_flowalistik.STL.zipextract/slices. at org.apache.commons.io.FileUtils.deleteDirectory(FileUtils.java:1541) ~[commons-io-2.4.jar:2.4] at org.apache.commons.io.FileUtils.forceDelete(FileUtils.java:2270) ~[commons-io-2.4.jar:2.4] at org.apache.commons.io.FileUtils.cleanDirectory(FileUtils.java:1653) ~[commons-io-2.4.jar:2.4] at org.apache.commons.io.FileUtils.deleteDirectory(FileUtils.java:1535) ~[commons-io-2.4.jar:2.4] at org.area515.resinprinter.job.CreationWorkshopSceneFileProcessor.prepareEnvironment(CreationWorkshopSceneFileProcessor.java:246) ~[photonic3d.jar:?] at org.area515.resinprinter.job.ZipImagesFileProcessor.renderPreviewImage(ZipImagesFileProcessor.java:116) ~[photonic3d.jar:?] ... 40 more

[WesGilster]

I assume you didn't mean to close this bug. I believe this to be an issue with permissions, so let me know if you think this could have happened.

At some point in the past the following directory structure was created with root: /tmp/printdir/charmander_starter_1gen_flowalistik.STL.zipextract

Photonic3D was reinstalled and executed as a "non-root" user(pi perhaps) and an image preview was executed which eventually tried to clean up the environment:

at org.area515.resinprinter.job.CreationWorkshopSceneFileProcessor.prepareEnvironment(CreationWorkshopSceneFileProcessor.java:246)

At that point, Apache file utils started traversing the directories and found a directory it couldn't delete which was: /tmp/printdir/charmander_starter_1gen_flowalistik.STL.zipextract/slices

I know you guys made some fixes to start.sh to ensure the application was run as root which will fix this problem in the future. It also reinforces the idea that Photonic3d may have been accidentally executed with non-root privileges. We don't have that information now, but when you do a log dump, I'm able to tell which user you were running Photonic3d at the time and that could be helpful information. The problem is that I won't have file permissions for all of the files on the OS so you might have to help me out there. The only other reason that it couldn't clean the directories might be that the OS already wiped it out right as it's about to clean. That seems unlikely though.

[WesGilster]

Actually forget that bit about the OS wiping out the directory first. The Apache file utils won't throw an error on missing files.

[WGAndrew]

Just hit it again on vanilla photonic build 1.0.12 - this time i've caught all the logs (happily) LogBundle (12).zip

[WGAndrew]

that's in the same photonic session (i.e. it hasn't been restarted or ran as a different user) - so it can't be root user permissions or anything like that. The first print of the file had completed successfully [as a simulated print] I'm currently chasing a memory issue on our build which is why i was trying the same file in vanilla photonic but starting the second print, it immediately had the same error as i've hit before with being unable to delete that directory

[WesGilster]

Could you attach that zip to this bug? I'm having a tough time coming up with scenarios where the directory can't be cleaned.

[WGAndrew]

Sorry Wes, it was actually already attached to this comment: https://github.com/area515/Photonic3D/issues/279#issuecomment-258132004

[WesGilster]

I meant the actual zip of slices, and not the log.zip, as I'm not able to reproduce the bug with the file I'm using. I don't think I'll need it though. I'm starting to think it doesn't have anything to do with the stl.zip file, and more to do with a quirk between java's listFiles() and the deleteDirectory() in the Apache FileUtils.

I've committed some pretty extensive debugging and a fix based on what I believe the problem is. Next time it happens(you may not see it) the logs will give me a snapshot of the directory structure based on the OS perspective, and not Java's listFiles() interpretation.

[WesGilster]

Development branch has rather extensive deletion fallback process here: org.area515.resinprinter.job.CreationWorkshopSceneFileProcessor.deleteDirectory(File)

It even falls back on listing files through debug when if Java fails to delete. Feel free to open if this problem happens again.