Upon print completion, 'job' event not sent from plugin to cloud?

[dnewman-polar3d]

This is with the gpx plugin as well.

Print finished; status 7 sent. Then back to status 0. However, cloud doesn't appear to have seen a 'job' command indicating completion of the print job. As such, the print job was left in the printer's queue.

[dnewman-polar3d]

Ahhh, job event seems to be sent. But state was 'canceled' although the job completed normally... I enabled additional logging and caught this,

info - OP000108: job from 66.159.242.14 socket id /#TZK14l6NfAjEheIRAAA-:
{
    "state": "canceled",
    "serialNumber": "OP000108",
    "jobId": "OP000108-165410"
}

[dnewman-polar3d]

2017-06-25 21:14:09,332 - octoprint.plugins.polarcloud - DEBUG - on_event: 'ZChange'
2017-06-25 21:14:09,960 - octoprint.plugins.polarcloud - DEBUG - _upload_snapshot
2017-06-25 21:14:09,961 - octoprint.plugins.polarcloud - DEBUG - upload_type printing
2017-06-25 21:14:10,312 - octoprint.plugins.polarcloud - DEBUG - on_event: 'ZChange'
2017-06-25 21:14:10,381 - octoprint.plugins.polarcloud - DEBUG - on_event: 'ZChange'
2017-06-25 21:14:10,909 - octoprint.plugins.polarcloud - DEBUG - on_event: 'ZChange'
2017-06-25 21:14:10,927 - octoprint.plugins.polarcloud - DEBUG - on_event: 'ZChange'
2017-06-25 21:14:11,944 - octoprint.plugins.polarcloud - DEBUG - on_event: 'ZChange'
2017-06-25 21:14:12,012 - octoprint.plugins.polarcloud - DEBUG - on_event: 'ZChange'
2017-06-25 21:14:13,009 - octoprint.plugins.polarcloud - DEBUG - 204: 
2017-06-25 21:14:13,012 - octoprint.plugins.polarcloud - DEBUG - Image captured from http://127.0.0.1:8080/?action=snapshot
2017-06-25 21:14:13,013 - octoprint.plugins.polarcloud - DEBUG - {'bed': {'actual': 60.0, 'target': 60.0, 'offset': 0}, 'tool0': {'actual': 211.0, 'target': 210.0, 'offset': 0}}
2017-06-25 21:14:13,014 - octoprint.plugins.polarcloud - DEBUG - get_current_data() is {'progress': {'completion': 99.97944378525781, 'printTimeLeftOrigin': 'estimate', 'printTime': 1290, 'printTimeLeft': 77, 'filepos': 384233L}, 'state': {'text': 'Printing', 'flags': {'operational': True, 'paused': False, 'printing': True, 'sdReady': True, 'error': False, 'ready': False, 'closedOrError': False}}, 'offsets': {}, 'job': {'estimatedPrintTime': 964, 'filament': {'tool1': {'volume': 0.0, 'length': 0}, 'tool0': {'volume': 5.953072641626595, 'length': 2475}}, 'averagePrintTime': 1654.4841010570526, 'file': {'origin': 'local', 'path': u'polarcloud/current-print.gcode', 'date': 1498423961, 'name': u'current-print.gcode', 'size': 384312L}, 'lastPrintTime': 1654.4841010570526}, 'currentZ': 8.0}
2017-06-25 21:14:13,015 - octoprint.plugins.polarcloud - DEBUG - emit status: {'status': '3', 'printSeconds': 1290, 'bed': 60.0, 'protocol': '2', 'file': '', 'targetBed': 60.0, 'estimatedTime': 964, 'config': '', 'serialNumber': 'OP000108', 'sliceDetails': '', 'jobId': u'OP000108-165410', 'targetTool0': 210.0, 'fileSize': 384312L, 'startTime': '2017-06-25T20:52:43.014806', 'progressDetail': 'Printing Job:  Percent Complete: 100.0%', 'progress': 'Printing', 'tool0': 211.0, 'bytesRead': 384233L, 'filamentUsed': None, 'securityCode': ''}
2017-06-25 21:14:22,264 - octoprint.util.comm - INFO - Finished in 1300.844 s.
2017-06-25 21:14:22,271 - octoprint.plugins.polarcloud - DEBUG - on_event: 'PrintDone'
2017-06-25 21:14:22,319 - octoprint.plugins.polarcloud - DEBUG - on_event: 'MetadataStatisticsUpdated'
2017-06-25 21:14:22,321 - octoprint.plugins.polarcloud - DEBUG - on_event: 'PrinterStateChanged'
2017-06-25 21:14:22,322 - octoprint.plugins.polarcloud - DEBUG - job
2017-06-25 21:14:22,612 - octoprint.plugins.polarcloud - DEBUG - {'bed': {'actual': 60.0, 'target': 0.0, 'offset': 0}, 'tool0': {'actual': 209.0, 'target': 0.0, 'offset': 0}}
2017-06-25 21:14:22,614 - octoprint.plugins.polarcloud - DEBUG - emit status: {'status': '7', 'printSeconds': '0', 'bed': 60.0, 'protocol': '2', 'file': '', 'targetBed': 0.0, 'estimatedTime': '0', 'config': '', 'serialNumber': 'OP000108', 'sliceDetails': '', 'jobId': '0', 'targetTool0': 0.0, 'fileSize': '0', 'startTime': '0', 'progressDetail': '', 'progress': '', 'tool0': 209.0, 'bytesRead': '0', 'filamentUsed': '0', 'securityCode': ''}
2017-06-25 21:14:36,986 - octoprint.plugins.polarcloud - DEBUG - _upload_snapshot
2017-06-25 21:14:36,987 - octoprint.plugins.polarcloud - DEBUG - upload_type idle
2017-06-25 21:14:39,879 - octoprint.plugins.polarcloud - DEBUG - 204: 
2017-06-25 21:14:39,880 - octoprint.plugins.polarcloud - DEBUG - Image captured from http://127.0.0.1:8080/?action=snapshot
2017-06-25 21:14:39,881 - octoprint.plugins.polarcloud - DEBUG - {'bed': {'actual': 59.0, 'target': 0.0, 'offset': 0}, 'tool0': {'actual': 199.0, 'target': 0.0, 'offset': 0}}
2017-06-25 21:14:39,882 - octoprint.plugins.polarcloud - DEBUG - emit status: {'status': '7', 'printSeconds': '0', 'bed': 59.0, 'protocol': '2', 'file': '', 'targetBed': 0.0, 'estimatedTime': '0', 'config': '', 'serialNumber': 'OP000108', 'sliceDetails': '', 'jobId': '0', 'targetTool0': 0.0, 'fileSize': '0', 'startTime': '0', 'progressDetail': '', 'progress': '', 'tool0': 199.0, 'bytesRead': '0', 'filamentUsed': '0', 'securityCode': ''}

[dnewman-polar3d]

Okay, had a print finish and no 'job' event was sent to the cloud. So the print job was left in the queue. I searched the Octoprint log file for 'emitting job' and found no corresponding entry.

Interestingly, I decided to check and make sure that debug logging was enabled for the plugin. It was but I decided to uncheck/check the box and click save. I then found this logged

2017-06-28 19:05:39,833 - octoprint.plugins.polarcloud - DEBUG - emitting job due to event: SettingsUpdated

which sent to the cloud

info - OP000108: job from 66.159.242.14 socket id /#t1cJWp4Aeb5-Hm4DAAcU:
{
    "state": "canceled",
    "serialNumber": "OP000108",
    "jobId": "OP000108-165488"
}

So not one but two issues perhaps?

1. job event with state completed not sent,
2. job events sent when they shouldn't be.

[dnewman-polar3d]

Here's why the completed print isn't logged

2017-06-28 20:14:57,691 - octoprint.plugins.polarcloud - DEBUG - on_event: 'PrintDone'
2017-06-28 20:14:57,692 - octoprint.plugins.polarcloud - DEBUG - *** _job_pending = True
2017-06-28 20:14:57,693 - octoprint.plugins.polarcloud - DEBUG - *** _printer.is_printing() = True
2017-06-28 20:14:57,693 - octoprint.plugins.polarcloud - DEBUG - *** _printer.is_paused() = False
2017-06-28 20:14:57,694 - octoprint.plugins.polarcloud - DEBUG - *** _pstate = 7

As self._printer.is_printing() is still true, the code to invoke _job() isn't called

if self._job_pending and not self._printer.is_printing() and not self._printer.is_paused() and self._pstate != self.PSTATE_PREPARING:
    self._job_pending = False
    self._logger.debug("emitting job due to event: {}".format(event))
    self._job(self._job_id, "completed" if event == Events.PRINT_DONE else "canceled")

[markwal]

@dnewman-polar3d Ah. That makes sense then. Do I want to wait until after the timelapse has been uploaded before saying job complete? Or just after printing is complete?

[dnewman-polar3d]

There's no "right" answer here. From past experience,

1. Some people complain when they can see the printer is done printing but it reports "finishing print" for 5+ minutes as it prepares a timelapse. Some/many of those people power cycle the printer to get it back in a "ready" state. Sigh. I see that behavior in our logs pretty regularly with the same printers.
2. We tried reporting it done when the print is finished and then had people complain that they didn't see the timelapse in the cloud right away. Sigh.
3. And on RPi 2's running raspbian we've found that slicing & preparing timelapse's concurrently can stress out the RAM and CPU. (RPi 3's running OpenWRT handle this very well, OTOH.)

If we're willing to cater to faster hardware (e.g., RPi 3's and faster), then I'd report the print done when it is physically done. Just be sure to "nice 19" (or whatever) the timelapse preparation.

[markwal]

Tricky. OK, in master now, it reports completion properly. In the timelapse branch it reports completion before timelapse creation. I'll need to look at that part of it closer.

[dnewman-polar3d]

Primary issue does appear to be resolved.