TTF fails with MQTT installed

[eyal0]

As a test, I disabled all my other plugins, and TimeToFilament started working correctly. Re-enabling one at a time, this appears to be some kind of conflict with the OctoPrint-MQTT plugin. With that disabled, the print time and filament time works correctly (first screenshot below). When I re-enable the MQTT plugin, the times are way off again (second screenshot).

MQTT plugin DISABLED:

MQTT plugin ENABLED (incorrect print and filament times):

The plugin_PrintTimeGenius_engine.log contents are identical in both cases.

Not sure if you're familiar with MQTT, but that plugin just monitors OctoPrint events and publishes them over the network for monitoring purposes. It should be pretty much a read-only plugin, so I'm not sure why it would have this kind of interaction with TimeToFilament...

Originally posted by @greendog99 in https://github.com/eyal0/OctoPrint-TimeToFilament/issues/1#issuecomment-636500298

[eyal0]

I installed MQTT and configured a the IP address because the configuration page says that MQTT will do nothing without it. I used this IP address: test.mosquitto.org (notice the intentional misspelling). It had no affect on TimeToFilament operation for me.

Maybe we can try enabling debug logging TimeToFilament? If you can send me some debug logs, both with and without MQTT enabled, maybe that'll shed some light on it.

Also, perhaps try using the same MQTT IP address and I used above? It could be that my MQTT in Octoprint is misconfigured so it's not doing whatever it is that causes MQTT to interact poorly with TTF.

[greendog99]

Even after enabling DEBUG logging for TimeToFilament I get no log file at all for that plugin. I restarted OctoPrint and re-loaded and started printing for my file... still no log file.

Here is the PrintTimeGenius log file. It does show a TypeError: unsupported operand type(s) for +: 'int' and 'NoneType' during compensate_analysis but I don't think that's affecting anything. https://gist.github.com/greendog99/4901ba084306de230b74a6a85ea46644

I'll build a new OctoPrint and see if I can reproduce this from scratch...

[greendog99]

I've been able to make this fail without having the MQTT plugin installed, so we can ignore that as the potential cause.

The first time I press "Print" in the OctoPrint UI, the times are correct. If I press "Cancel", and then later press "Print" again, the times are wrong.

I tested this by building a brand new OctoPi 0.17.0 server, installing only the PrintTimeGenius and TimeToFilament plugins. I added my custom TimeToFilament regexp (^M0) and loaded my gcode, and performed the above steps (print, cancel, print).

To double-check, I deleted my ^M0 regexp and changed my gcode to use M600 instead, and saw the same problem. Since I was using print and cancel a lot when enabling and disabling plugins, I must have been running into this as a side-effect this when disabling and re-enabling the mqtt plugin.

Here's a sample. After restarting OctoPrint, I loaded my gcode and pressed print:

The times above are correct. I pressed "Cancel", waited a few seconds, and pressed "Print" again, and saw this:

Hopefully this will help track down the bug. Let me know what else I can do to help troubleshoot!

[eyal0]

Please make sure that you have downloaded the latest TTF. I built a new one with the logging. Also, I think that there are multiple "TimeToFilament" named logging things. I'm not sure which one you need so please just enable both.

I do have some caching that might be causing this trouble. I think that the logs will give us a clue.

Logs are only created while printing, once every 10 seconds.

[greendog99]

OK, installed latest TTF and turned on all the DEBUG logging I could find for both plugins.

TTF log: https://gist.github.com/greendog99/f232a723a2a0c963c2e272a76124f094 PTG log: https://gist.github.com/greendog99/0dd02efadf9ba9bb024c51ae990102da

Loaded gcode file @ 19:26:22 Pressed "Print" @ 19:26:37. Correct times displayed in UI. Pressed "Cancel" after ~1 minute. Pressed "Print" @ 19:28:22. Incorrect times displayed in UI. Pressed "Cancel" after ~1 minute.

I noticed that when I press "Print" the second time, the "Print Time Left" almost exactly matches the original "Filament change in" time (see screenshots in comment above). This makes me think that when the print is canceled, one of the plugins is updating the list of "times remaining" as though the filament change happened and the print was now half finished. I.e. the analysis is only run when the file is first loaded, then some array gets updated, and when the print is started the second time, the wrong data is used (instead of the original calculations). Not sure if this is related to the potential caching issue you mentioned.

[eyal0]

Okay, that was interesting. I definitely see how the time left dropped way down the second time around! Something is wrong there.

[eyal0]

I found a pretty dumb bug of mine in PrintTimeGenius. I don't know if this is the same issue as what you're having but lets give it a shot, yeah?

Install this form the Octoprint settings plugin manager (there's a place where you can put a URL). No need to uninstall the old PTG.

https://github.com/eyal0/OctoPrint-PrintTimeGenius/archive/time_to_filament.zip

After you install, I think that you'll have to restart Octoprint. Then please do the same test as you did last time, with the print, cancel after a minute, then print again. Let me know how that works, thanks!

[greendog99]

That seems to have fixed it!

[eyal0]

Fantastic! I'll push a new version of PTG and you can upgrade to that one if you like. It'll be v2.2.4.