Firmware 8.1 Bug? ERR999 on API "pause" call,

[walterww 2]

I've got a script running that pauses our Ultimakers when they print without authorization. 

The new firmware seems to crash when the scripts tries to pause the printer while it is resuming from a prior pause.

The API command I'm using is PUT /print_job/state with payload {"target": "pause"} and I'm calling it without checking first if the printer is already paused or has just been unpaused and not resumed printing yet.

This worked flawlessly for years now, so I think this is due to a change in the last firmware update.

 

So in order to reproduce: Start a print. Pause the print. Resume and immediately send PUT /print_job/state with payload {"target": "pause"}

 

The print bed goes down and I think it crashes.

On the display there's an ERR999 and Reboot button

The Management Console says: Unhandled exception from ProcedureStep TEST_IF_NOT_PAUSED

 

And the log file says:

 

Quote

Feb 24 09:26:47.401979 ultimakersystem-xxx PrinterService[1611]: INF - printJobStateProperty:79 - New print job state: resuming -> pausing

Feb 24 09:26:47.407767 ultimakersystem-xxx PrinterService[1611]: INF - printerService:169 - Procedure start: PAUSE_PRINT: TEST_IF_NOT_PAUSED
Feb 24 09:26:47.420796 ultimakersystem-xxx PrinterService[1611]: INF - printerService:195 - Procedure next step: PAUSE_PRINT: TEST_IF_NOT_PAUSED
Feb 24 09:26:47.427072 ultimakersystem-xxx PrinterService[1611]: ERR - procedureStep:113 - Exception caught from step: TEST_IF_NOT_PAUSED
Feb 24 09:26:47.427072 ultimakersystem-xxx PrinterService[1611]: Traceback (most recent call last):
Feb 24 09:26:47.427072 ultimakersystem-xxx PrinterService[1611]:   File "/usr/share/griffin/griffin/printer/procedures/procedureStep.py", line 89, in _run
Feb 24 09:26:47.427072 ultimakersystem-xxx PrinterService[1611]:     outcome = self.run()
Feb 24 09:26:47.427072 ultimakersystem-xxx PrinterService[1611]:   File "/usr/share/griffin/griffin/printer/procedures/print/testPausedStep.py", line 24, in run
Feb 24 09:26:47.427072 ultimakersystem-xxx PrinterService[1611]:     raise ValueError("expected the system to be %s but is %s" % (toString(self._expected), toString(not self.
_expected)))
Feb 24 09:26:47.427072 ultimakersystem-xxx PrinterService[1611]: ValueError: expected the system to be running but is paused
Feb 24 09:26:47.494983 ultimakersystem-xxx MarvinService[956]: INF - marvinService:273 - Reporting fault <Fault: level=2 code=102 message='Unhandled exception from ProcedureS
tep TEST_IF_NOT_PAUSED' data='dbus.Dictionary({}, signature=dbus.Signature('sv'))'> to Sentry...
Feb 24 09:26:47.710087 ultimakersystem-xxx Okuda[2514]: INFO     Okuda.DBus.PrinterServiceProxy Processing PrinterError(level: 2, code: 102, msg: 'Unhandled exception from Pr
ocedureStep TEST_IF_NOT_PAUSED')
Feb 24 09:26:47.710087 ultimakersystem-xxx Okuda[2514]: "149021.725 qml [bootup] ErrorDialog overlay: Code,Level,text= 102 2 An unexpected error has occurred. Restart the pri
nter, or go to ultimaker.com/ER999."
Feb 24 09:26:47.710087 ultimakersystem-xxx Okuda[2514]: INFO     Okuda.Components.screen_saver modeChanged: Mode.Printing --> Mode.AttentionRequired
Feb 24 09:26:47.713932 ultimakersystem-xxx PrinterService[1611]: INF - procedure:470 - PausePrintProcedure(key='PAUSE_PRINT', outcome=OutcomeBase.Error) transitioning from 'T
estPausedStep(key='TEST_IF_NOT_PAUSED')' >  'None'
Feb 24 09:26:47.713932 ultimakersystem-xxx PrinterService[1611]: INF - printJobStateProperty:79 - New print job state: pausing -> resuming
Feb 24 09:26:47.713932 ultimakersystem-xxx PrinterService[1611]: INF - procedure:355 - Message: 'ABORT' for procedure 'PrintProcedure(key='PRINT', outcome=None)'
Feb 24 09:26:47.713932 ultimakersystem-xxx PrinterService[1611]: INF - printerService:174 - Procedure finished: PAUSE_PRINT
Feb 24 09:26:47.713932 ultimakersystem-xxx PrinterService[1611]: INF - procedure:322 - PrintProcedure(key='PRINT', outcome=None) is going to be aborted (machine:False)
Feb 24 09:26:47.713932 ultimakersystem-xxx PrinterService[1611]: INF - printerStateProperty:80 - State change: printing -> error
Feb 24 09:26:47.713932 ultimakersystem-xxx PrinterService[1611]: INF - procedureStep:161 - Aborting step: PrintFileStep(key='PRINTING') (by_machine:False)
Feb 24 09:26:47.713932 ultimakersystem-xxx PrinterService[1611]: ERR - controller:906 - Halting ALL procedures
Feb 24 09:26:47.713932 ultimakersystem-xxx PrinterService[1611]: INF - printFileStep:44 - Print procedure aborted
Feb 24 09:26:47.713932 ultimakersystem-xxx PrinterService[1611]: INF - controller:616 - Setting paused state to: False
Feb 24 09:26:47.713932 ultimakersystem-xxx PrinterService[1611]: INF - charonFileHandler:147 - File handler aborted.
Feb 24 09:26:47.713932 ultimakersystem-xxx PrinterService[1611]: INF - timeEstimator:119 - Warning print was aborted!

 

 

[Onno 6]

Hi Walter,

 

Thanks for bringing this to our attention.

 

I can confirm that the behavior of the /print_job/state REST API endpoint has regressed with our 8.x firmware release. My apologies for the inconvenience this must have caused!

 

I've just pushed a fix for this to our internal systems, but I can't make any promises as to public availability of this fix yet. I'll keep you posted if I can share more.

 

For now, I can also confirm that the problem appears to be submitting a request to pause the printer, while the printer is currently executing a "resume from pause" command. If you would be able to add a check for that to your script, that should provide you with a workaround. (As far as I can see, asking the printer to pause while it's currently resuming, previously just caused your request to be ignored by the printer. The ER999 you get now is the regression. So adding the check would probably be a good idea anyway.)

 

 

Edited February 27, 2023 by Onno
Add more info about the workaround

[walterww 2]

Thank you very much!

 

[quote]So adding the check would probably be a good idea anyway.[/quote]

Yes, I will do that!