Plugin not reporting time/layers as expected

[raichea]

Just installed this plugin as I've recently started playing with multicolour prints. PrintTimeGenius has installed OK, it seems but TimeToFilament throws the error in the subject. Here's the relevant part of the log:

1-02-02 17:49:57,221 - octoprint.printer.standard - INFO - Using print time estimator provided by PrintTimeGenius 2021-02-02 17:49:57,724 - octoprint_TimeToFilament - ERROR - Failed: AttributeError("'TimeToFilamentPlugin' object has no attribute '_printer'",)

Versions installed: PrintTimeGenius - v2.2.7, TimeToFilament - v1.2.1

[eyal0]

I've seen that before but usually it goes away. Does this error cause TimeToFilament to stop working?

[raichea]

As far as I can tell - there's no sign of layer info or time to change in the status panel.

[raichea]

A friend of mine who has this working has seen a similar message in his log.

I presume you're trapping the M600 message. Assuming so, where do you do this - in the input stream from the file or the output stream to the printer? If the former, I think that's the cause of my problem. My printer (Anycubic Mega S) doesn't support M600, I believe, so I'm currently trapping the M600 and injecting gcode with Octoprint to allow me to change the filament.

[raichea]

I've now found the plugin log and just loading a file into Octoprint (ie not printing), I get several lines like this:

2021-02-02 23:34:04,946 sending: {"^M600": {"timeLeft": null, "groups": [], "group": "M600", "groupdict": {}, "matchPos": 412768, "searchPos": 0}}

occasionally, however, some of the data looks promising (well, at least there's a time there):

2021-02-02 23:40:19,725 sending: {"^M600": {"timeLeft": 3815.876102052472, "groups": [], "group": "M600", "groupdict": {}, "matchPos": 412768, "searchPos": 0}}

again, several lines like this appear in the log. In neither case, does anything about layers or time to change filament appear in the control area of the UI.

This suggests the plugin is seeing the M600 in the input stream but something is stopping it sending data to the UI.

[eyal0]

I'm not trapping M600. The only way to do that would be as the command is sent. But I need to know about it before it is sent, so that I can measure how long it is until it is sent.

Instead, TimeToFilament scans through the file in the forward direction looking for an M600. It then asks OctoPrint to predict how much time left there is between the M600 and the end of the print. We already know the time between now and the end of the print so a little subtraction yields the time until the M600. From your log above, it seems that the time from the M600 until the end of the print was 3815 seconds.

Why it reported null the first time? I dunno. It shouldn't be able to do that. Maybe the file was mid-analysis and there was no timeLeft to report?

Null is not expected. I can check the code to see how the null might have been generated and also add something to handle it better, if it isn't already handled well.

For your friend for whom it works, it works correctly? The reported value is non-zero and it's reasonable?

What's the pattern on that timeLeft? Is it null a few times and then a proper value the rest of the time? Or does it switch back and forth?

[raichea]

I didn't know whether OctoPrint was preprocessing the whole file or injecting code on the fly, but with the log output, it was obviously seeing the M600, so I figured out you were seeing it in the input - I shouldn't have said 'trapping'.

Ok, I've dug around some more. I've got two very similar files. Each has a single M600 command embedded in it by Cura:

M600 E30.00 L300.00 X0.00 Y0.00 ; Generated by FilamentChange plugin

If I load the first file and start printing it, I get this line posted to the log approximately every 10s:

2021-02-03 08:55:51,771 sending: {"^M600": {"timeLeft": 3815.876102052472, "groups": [], "group": "M600", "groupdict": {}, "matchPos": 412768, "searchPos": 0}}

In the UI, I see the following line (but not the Layer x line shown in the readme):

Filament change in 00:00:00

... the time never changes from 00:00:00 . After the M600 has been processed, the Filament change line disappears from the UI.

Loading and printing the second file posts this line to the log, again every 10s:

2021-02-03 08:57:35,271 sending: {"^M600": {"timeLeft": null, "groups": [], "group": "M600", "groupdict": {}, "matchPos": 174746, "searchPos": 0}}

...and neither the Filament change nor the Layer x lines appear in the UI. Why this should behave differently to the first file, I have no idea.

I haven't mentioned this previously but in case it's relevant (can't see why it would be for this plugin), I'm not running Octoprint on a Raspberry Pi.

[raichea]

To answer your question, my friend reports that it works well... rather than having to check his print every so often, your plugin tells him when he needs to change the filament.

I tried running the files on my RPi and got similar(actually worse) results. The two, same test files both didn't display anything new (no layer, no filament change lines in the UI). I assume this eliminates the RPi as being involved.

Interestingly, I learned that my friend's slicer (PrusaSlicer to a Prusa Mk3 ) injects a simple M600 with no additional parameters. To test this on my setup, I edited the two .gcode files to eliminate the extra data from the M600 line and now both files show the filament change line (but not the layer one) but the time is stuck at 00:00:00.

As the regex is ^M600, the additional parameters should affect things, but they obviously do.

(I changed the title of this issue as the original error message was a red herring).

[raichea]

I wondered if there might be a problem with Windows vs Linux line-endings but it seems not, having tried both and observed the same behaviour.

I tried a .gcode file from my friend that works on his printer. I got the same result as with my files - no layer info, and filament change time = 00:00:00. I did something I hadn't tried before, which was to allow the print to go beyond the filament change before cancelling it. I then tried starting the print job again (with the same file) and suddenly, the time to change field was apparently working correctly (can't be 100% certain as I'm testing with Octoprint's virtual printer) - it certainly seemed correct and counted down up to the change point as expected.

I'm still not seeing the layer information, however.

At this point, I can print any file (even with M600 with parameters) and the Filament Change line appears to work correctly quite often - IF I print using the print button in the file list below the status panel, the FC time is displayed. Unfortunately, this isn't always the case - sometimes it's back to 00:00:00 until I take a file past M600 again. If I hit Load in the file list and then Print from the status panel, I get 00:00:00 again. Most puzzling... my guess is that something isn't being initialised properly.

[eyal0]

I also use the virtual printer for my testing and I haven't seen a problem.

There is some code where TimeToFilament is trying to figure out if the currently printing file is different from the file that was printing the last time that it was checked (which is twice per second). If the file is the same as last time, it caches the results and re-uses them when possible. But if the file is different, then it clears the cache and starts over.

Maybe there's some bug around that code? Could you supply to me whatever I would need in order to reproduce the issue the same as you, including files and also a precise procedure? If I'm able to reproduce it, maybe I can fix it!

[raichea]

I'm not doing anything special. Just using Cura to inject a Change Filament M600 at a specific layer. Octoprint is trapping the M600 and also generating a pause on an M600. Using almost vanilla scripts from the Octoprint docs to move the head so I can change filament and resume.

I've attached a small .gcode file (had to type it as .txt to get it to upload) that has the Filament Change and demonstrates the problem for me. My friend has now also seen the 00:00:00 response and the lack of layer information using his own files.

Filament change-AI3M_IR_Bezel.gcode.txt

[eyal0]

I am still unable to see the same bug as you. I don't know why. I'm sure that it's real because it is affecting others, too. But I can't figure out how to make it happen on my computer. Someone with programming ability that sees the bug will need to work on it. I can assist.

You are not seeing layer information because the layer information in your file is not in the format expected. Please open the advanced settings of the plugin and observe that layers should match this regular expression: ^; layer (\d+). But in you file, that does not appear. I guess that Cura uses capital letters. If you find a better regex and you submit a PR, I will accept it and publish a new version of this plugin.

[raichea]

I realised the regex was not matching so I tried "^;LAYER:(\d+)" and also "^;LAYER:\d+", both of which should match. but they didn't work either. I tried changing it in both the regex box and then in the expression below. Neither worked.

It's really weird. I uninstalled and reinstalled and then nothing worked again. Sometime later, the line stuck at 00:00:00 started appearing again. It just has the feel of an initialisation problem to me.

[eyal0]

You need to change it both in the regex and the format. Notice that in the format every backslash is doubled.

There is sample text at the bottom of the advanced settings. You can paste your gcode into there and use the settings dialog as a testing grounds.

[raichea]

Ah! Thank you. I'd noticed the double '\' in the format but then completely forgot about it when I edited.

GOOD NEWS!

With the '\\' fixed, the layer line is now being displayed and the time to filament change is also working as expected! There's presumably some unexpected interaction between the two of them - if the layer regex doesn't find a match then the filament change field is somehow messed up. I also (after brushing up my regex!) figured out why you need the () around (\d+).

Apologies for using your time up but perhaps I can make some suggestions as a result of my experience?

1) Because I was most interested in the time to change filament, I ignored the layer information apart from noting that it was missing. If you can make the two fields fully independent it would mean no-one else will have the problem I had. 2) Please consider putting that useful information about how to edit the regex (inc. the \\!) in the readme for the project. I also hadn't realised the link between the sample output line for each field and the sample gcode box - I realised the JSON was changing with the sample text but didn't notice the effect on the output lines. 3) I assumed the layer information (eg Layer 23 in 03:06:58) was also "time to start layer 23" (like time to change filament) but quickly realised it's actually time to completion of layer 23. I've therefore changed the format to: Layer 23 complete in 03:06:58, which you might consider making the default.

Thanks once again for this useful plugin and my appreciation for your support. I hope you find my suggestions useful.

[eyal0]

Ah, that's a great find. So you're telling me that the failure of the regex format in one of them is leading to a different one to fail? Huh. Well, that's something that I can certainly test! I'll follow all the suggestions above.

[raichea]

Just to be clear, the TimetoFilament line failed to work correctly without me making any changes to the default regex. When I edited the regex so that it found the layer tag in my gcode, the TimetoFilament line worked correctly.

Note that I changed all the relevant entries for the layer tag, even for the third line that I wasn't using, so I don't know whether it's related to just one or the other or both layer lines not finding a valid layer tag.