Updating PrusaSlicer 2.1.1 to 2.3.0, and plugin to 1.2.1 causes broken gcode

[Bougakov]

Hi. I've just installed a fresh 1.2.1 version of the plugin and added PrusaSlicer 2.3.0 to my system.

New binary is stored at /usr/bin/prusa-slicer, and old one is at /usr/local/bin/prusa-slicer.old.

Running both binaries manually works nicely:

/usr/local/bin/prusa-slicer.old --load /home/octoprint/.octoprint/slicingProfiles/slic3r/2020-11-15.profile -g  /home/octoprint/.octoprint/uploads/xyzCalibration_cube.stl

produces a gcode file which starts with

; generated by PrusaSlicer 2.1.1 on 2021-01-13 at 00:59:10 UTC

while

/usr/bin/prusa-slicer --load /home/octoprint/.octoprint/slicingProfiles/slic3r/2020-11-15.profile -g  /home/octoprint/.octoprint/uploads/xyzCalibration_cube.stl

gives me

; generated by PrusaSlicer 2.3.0 on 2021-01-13 at 00:58:06 UTC

So everything is fine "under the hood". But slicing from the web interface produces broken garbled binary g-code.

Old version produced a rather shorl log:

2020-11-14 23:59:53,910 ----------------------------------------
2020-11-15 00:29:33,359 ### Slicing /home/octoprint/.octoprint/uploads/xyzCalibration_cube.stl to /tmp/tmpTItog4.gco using profile stored at /tmp/slicing-profile-temp-uSc0LO.profile
2020-11-15 00:29:44,270 stdout: 10 => Processing triangulated mesh
2020-11-15 00:29:44,272 stdout: 20 => Generating perimeters
2020-11-15 00:29:44,273 stdout: 70 => Infilling layers
2020-11-15 00:29:44,274 stdout: 30 => Preparing infill
2020-11-15 00:29:44,275 stdout: 88 => Generating skirt
2020-11-15 00:29:44,276 stdout: 88 => Generating brim
2020-11-15 00:29:44,278 stdout: 90 => Exporting G-code to /tmp/tmpTItog4.gco
2020-11-15 00:29:44,279 stdout: Slicing result exported to /tmp/tmpTItog4.gco
2020-11-15 00:29:44,280 ### Finished, returncode 0
2020-11-15 00:29:47,169 Analysis found in gcode: None

while newer is more verbose:

2021-01-13 03:36:05,955 ----------------------------------------
2021-01-13 03:44:07,892 ### Slicing /home/octoprint/.octoprint/uploads/xyzCalibration_cube.stl to /tmp/tmp3C0h61.gco using profile stored at /tmp/slicing-profile-temp-YfaCzc.profile
2021-01-13 03:44:28,561 stdout: 0% => Hollowing model
2021-01-13 03:44:28,563 stdout: 5% => Drilling holes into model.
2021-01-13 03:44:28,564 stdout: 10% => Slicing model
2021-01-13 03:44:28,565 stdout: 15% => Generating support points
2021-01-13 03:44:28,566 stdout: 16% => Generating support points
2021-01-13 03:44:28,566 stdout: 17% => Generating support points
2021-01-13 03:44:28,567 stdout: 18% => Generating support points
2021-01-13 03:44:28,568 stdout: 19% => Generating support points
2021-01-13 03:44:28,568 stdout: 20% => Generating support points
2021-01-13 03:44:28,569 stdout: 21% => Generating support points
2021-01-13 03:44:28,570 stdout: 22% => Generating support points
2021-01-13 03:44:28,570 stdout: 23% => Generating support points
2021-01-13 03:44:28,571 stdout: 24% => Generating support points
2021-01-13 03:44:28,572 stdout: 25% => Generating support points
2021-01-13 03:44:28,573 stdout: 25% => Generating support tree
2021-01-13 03:44:28,573 stdout: 26% => Generating support tree
2021-01-13 03:44:28,574 stdout: 27% => Generating support tree
2021-01-13 03:44:28,575 stdout: 28% => Generating support tree
2021-01-13 03:44:28,575 stdout: 29% => Generating support tree
2021-01-13 03:44:28,576 stdout: 30% => Generating support tree
2021-01-13 03:44:28,576 stdout: 30% => Generating pad
2021-01-13 03:44:28,577 stdout: 30% => Slicing supports
2021-01-13 03:44:28,578 stdout: 50% => Merging slices and calculating statistics
2021-01-13 03:44:28,578 stdout: 55% => Rasterizing layers
2021-01-13 03:44:28,579 stdout: 56% => Rasterizing layers
2021-01-13 03:44:28,580 stdout: 57% => Rasterizing layers
2021-01-13 03:44:28,580 stdout: 58% => Rasterizing layers
2021-01-13 03:44:28,581 stdout: 59% => Rasterizing layers
2021-01-13 03:44:28,582 stdout: 60% => Rasterizing layers
2021-01-13 03:44:28,582 stdout: 61% => Rasterizing layers
2021-01-13 03:44:28,583 stdout: 62% => Rasterizing layers
2021-01-13 03:44:28,583 stdout: 63% => Rasterizing layers
2021-01-13 03:44:28,584 stdout: 64% => Rasterizing layers
2021-01-13 03:44:28,585 stdout: 65% => Rasterizing layers
2021-01-13 03:44:28,585 stdout: 66% => Rasterizing layers
2021-01-13 03:44:28,586 stdout: 67% => Rasterizing layers
2021-01-13 03:44:28,587 stdout: 68% => Rasterizing layers
2021-01-13 03:44:28,587 stdout: 69% => Rasterizing layers
2021-01-13 03:44:28,588 stdout: 70% => Rasterizing layers
2021-01-13 03:44:28,589 stdout: 71% => Rasterizing layers
2021-01-13 03:44:28,589 stdout: 72% => Rasterizing layers
2021-01-13 03:44:28,590 stdout: 73% => Rasterizing layers
2021-01-13 03:44:28,591 stdout: 74% => Rasterizing layers
2021-01-13 03:44:28,592 stdout: 75% => Rasterizing layers
2021-01-13 03:44:28,592 stdout: 76% => Rasterizing layers
2021-01-13 03:44:28,593 stdout: 77% => Rasterizing layers
2021-01-13 03:44:28,594 stdout: 78% => Rasterizing layers
2021-01-13 03:44:28,594 stdout: 79% => Rasterizing layers
2021-01-13 03:44:28,595 stdout: 80% => Rasterizing layers
2021-01-13 03:44:28,595 stdout: 81% => Rasterizing layers
2021-01-13 03:44:28,596 stdout: 82% => Rasterizing layers
2021-01-13 03:44:28,597 stdout: 83% => Rasterizing layers
2021-01-13 03:44:28,597 stdout: 84% => Rasterizing layers
2021-01-13 03:44:28,598 stdout: 85% => Rasterizing layers
2021-01-13 03:44:28,599 stdout: 86% => Rasterizing layers
2021-01-13 03:44:28,599 stdout: 87% => Rasterizing layers
2021-01-13 03:44:28,600 stdout: 88% => Rasterizing layers
2021-01-13 03:44:28,601 stdout: 89% => Rasterizing layers
2021-01-13 03:44:28,601 stdout: 90% => Rasterizing layers
2021-01-13 03:44:28,602 stdout: 91% => Rasterizing layers
2021-01-13 03:44:28,603 stdout: 92% => Rasterizing layers
2021-01-13 03:44:28,603 stdout: 93% => Rasterizing layers
2021-01-13 03:44:28,604 stdout: 94% => Rasterizing layers
2021-01-13 03:44:28,605 stdout: 95% => Rasterizing layers
2021-01-13 03:44:28,606 stdout: 96% => Rasterizing layers
2021-01-13 03:44:28,606 stdout: 97% => Rasterizing layers
2021-01-13 03:44:28,607 stdout: 98% => Rasterizing layers
2021-01-13 03:44:28,608 stdout: 99% => Rasterizing layers
2021-01-13 03:44:28,609 stdout: 100% => Rasterizing layers
2021-01-13 03:44:28,609 stdout: 100% => Slicing done
2021-01-13 03:44:28,610 stdout: Slicing result exported to /tmp/tmp3C0h61.gco
2021-01-13 03:44:28,611 ### Finished, returncode 0
2021-01-13 03:44:28,640 Analysis found in gcode: None
2021-01-13 03:44:28,641 ----------------------------------------

and the produced file contains some binary garbage mixed with the parts of the profile:

;Generated from xyzCalibration_cube.stl (hash: d316cc8422b4622151bc32fe2910f6a8731736bb)
.'-R
config.ini]?OO?0
                ?????FI?1:?
                           C?L?go5?4%I???qZ&???߳??
                                                 ?d|ǯyL?~?;??T?M?)󋱸
y>7b?SCK?
?
UrH\??|????V??nM??????????,?`?C????J???????a????6?JN0??r?????H?1?6????s.-?R??M:??o?R????1<??)C?ƚ#?"L??_,?(???????s͆????
??Ⲛ]??Pi??/?.'-Rprusaslicer.ini?Wۮ?F}?+P??a???EGyH?$???F?*?????4?E??q??k3'?m?^?g??fϥȒ?.?FǤ??y???}?ΞgIsb??v???M?[??M???ۥEQl?? 
                                                                                                                             ?m??wqЅ??bo`t?z??ב??,w?0?V??   ??????7?z??n?n?/?0?z???aO?:}?[ŝ??iݝ???ww?O??i[=m{?U?x~???\L-?Z?k#?Ssw???v??6

Older version produced clean ASCII files:

;Generated from xyzCalibration_cube.stl (hash: d316cc8422b4622151bc32fe2910f6a8731736bb)
; generated by PrusaSlicer 2.1.1 on 2021-01-13 at 00:57:00 UTC

; 

Attached are the generated g-code files:

xyzCalibration_cubeOLD1.gco.zip xyzCalibration_cubeNEW1.gco.zip

[Bougakov]

On a side note: it would be very helpful, if plugin_slic3r_engine.log contained the raw command with all the parameters.

[eyal0]

Thanks for giving it a shot. I don't even own a 3d printer so it's hard for me to test.

I'll dig into it.

[eyal0]

@Bougakov Okay, weird, turns out that pruseslicer is making a zip file! There must be some option that I'm accidentally setting that causes it to make a zip file?

You can try it yourself. Run file <your filename> on it and you'll see. You can also unzip it and the output is a big list of images along with to ini files.

Super weird. Maybe the arguments to prusaslicer are weird? You should be able to see them in the octoprint slic3r log. I see them there, I think.

Anyway, there's work to be done. I'll get on it in a couple hours.

[Bougakov]

No, I've archived the gcode because GitHub wouldn't let me attach it otherwise.

[Bougakov]

I've just upgraded to 1.2.2 and I am glad to report that the issue was resolved. I am getting proper ASCII g-code files, as expected:

;Generated from xyzCalibration_cube.stl (hash: d316cc8422b4622151bc32fe2910f6a8731736bb)
; generated by PrusaSlicer 2.3.0 on 2021-01-13 at 12:22:51 UTC

[lukasmatena]

@Bougakov Hi, I'm writing as a PrusaSlicer collaborator. Could you please post the config file that you are loading (2020-11-15.profile) and that suffered from this issue? Thanks.

[Bougakov]

@lukasmatena, check the former gcode file that I've attached above - the one which has "OLD" in its name. PrusaSlicer copies the INI file used for slicing at the very end of the file. The same config file was used with both versions of the slicer binary.

[lukasmatena]

@Bougakov It copies the options that were used, not the contents of the INI file. What I mostly wanted to see was the header of the INI. I have a suspicion it is actually generated by Slic3r, not PrusaSlicer. There probably really is a bug in PrusaSlicer (that I will describe later), but I would first like to be sure what the problem is.

[Bougakov]

OctoPrint Slic3r adds four lines of text on top as it imports the INI file. The rest was absolutely identical to what is being saved to the g-code by the slicer (I used diff when I investigated the behavior of 2.2 and 2.3 so I am sure). All parameters are sorted alphabetically.

# Name: 2020-11-15

# Description: Imported from 2020-11-15.ini on 2020-11-15 17:27

(sorry but turns out I've modified that file later on manually and can't share it)

[lukasmatena]

@Bougakov @eyal0 Apparently the handling of the command line arguments really changed, but the change is a bug, not intentional. What is happening in this case is that PrusaSlicer slices in SLA mode and names the output as gcode (SLA output file is a zip in disguise). When --slice is used, it should switch the technologies based on the content of the ini file. The bug is in incorrect handling of a case when this information is missing in the ini. Old PS versions defaulted to FDM, the new one does what I described. It is quite unfortunate, sorry about that. We'll try to do something about it.

That's why I was so curious about the INI. If you're using a Slic3r config file in PrusaSlicer, I would not do it. But what you have described will affect all Slic3rPE configs from pre-SLA times. Hopefully not newer ones.

[eyal0]

No, I've archived the gcode because GitHub wouldn't let me attach it otherwise.

Yes, I know that you zipped it but the .gco file is also a zip. It's a zip file in a zip file. If you look at the binary garbage, you'll see that it begins with "PK". That is the signifier for a PKZip file. If you rename the file to .zip, it will unzip to a bunch of png images.

My fix was to add the "-g" parameter when using prusaslicer 2.3. I had the "--slice" parameter before.