[BUG] IGNORES first instance of matched pause regex "^M601"

[puterboy]

I modeled new routines "TIme to Next Pause" and "Time of Next Pause" on the corresponding functions for filament changes. The change was trivial, merely replacing "^M600" with "^M601" and changing the relevant description text.

However, TImeToFilament seems to ignore the first pause (displaying nothing). If there are more than one pauses, then after the first pause is resumed, TimeToFilament identifies and displays subsequent pause times correctly.

In contrast, for "Time to Next Filament Change", all filament changes are identified correctly.

Grepping through the gcode, there are indeed the right number and placement of "M601" commands.

Scratching my head at why TimeToFilament is ignoring the first pause while working ok with the first filament change code despite the fact that the configuration difference is so trivial.

The relevant portion of my config.yaml now looks like:

TimeToFilament:
    displayLines:
    - description: Time to Next Layer
      enabled: true
      format: Next layer in <b>${formatDuration(this.progress.printTimeLeft - this.plugins.TimeToFilament["^;LAYER_CHANGE"].timeLeft)}</b>
      regex: ^;LAYER_CHANGE
    - description: Time to Next Filament Change
      enabled: true
      format: Filament change in <b>${formatDuration(this.progress.printTimeLeft -
        this.plugins.TimeToFilament["^M600"].timeLeft)}</b>
      regex: ^M600
    - description: Time of Next Filament Change
      enabled: true
      format: Filament change at <b>${new Date(Date.now() + (this.progress.printTimeLeft
        - this.plugins.TimeToFilament["^M600"].timeLeft)*1000).toLocaleTimeString([],
        {hour12:false})}</b>
      regex: ^M600
    - description: Time to Next Pause
      enabled: true
      format: Pause in <b>${formatDuration(this.progress.printTimeLeft - this.plugins.TimeToFilament["^M601"].timeLeft)}</b>
      regex: ^M601
    - description: Time of Next Pause
      enabled: true
      format: Pause at <b>${new Date(Date.now() + (this.progress.printTimeLeft - this.plugins.TimeToFilament["^M601"].timeLeft)*1000).toLocaleTimeString([],
        {hour12:false})}</b>
      regex: ^M601

[puterboy]

Weird... and now without changing anything it seems to be working.... So strange...

[eyal0]

So can we close this issue?

[puterboy]

Let me play around a bit more to make sure it's truly resolved :)

[eyal0]

It might be that you found a real bug. The code is caching the results in order to save time. That is, it remembers where it started searching last time and continues from there, that way it doesn't have to start over and waste a bunch of time on parts of the file that were already read.

The caching is complex because the cache needs to be cleared whenever switching to a new file. And also, we can't start scanning the file before the file is completely loaded. So there are some corner cases there that were difficult to deal with. If there's a bug in the code for the first M600/M601, it might be on the first file printed after rebooting OctoPrint, or maybe on the first time printing a file after upload, or maybe when cancelling a print in the middle and then starting a new one. These are the kind of scenarios that I would test given what you have found.

[puterboy]

Those "corner cases" pretty much represent what I was doing -- since I was simply testing out the module since I don't have any models that I need to print now that have pauses. So, I was definitely canceling/restarting/rebooting etc. Unfortunately, I am not able to use my printer for a bit so may be a while before I can test.

But is there no way to wait for file to be fully loaded before searching? Or alternatively, is there no way to re-search if it turns out that the length of the file has changed since last loop. Perhaps stat the file to get the length? Or see if file timestamp has changed?

[puterboy]

To clarify, you would only check the timestamp or file length if there was no "next" event of any of the given types in the cache. Then, if the timestamp or file length changed, you would continue searching from the last point to the end of file. In case it's an issue of the file itself changing (i.e. brand new file), perhaps you could look at the create time.

[eyal0]

It's been so long since I worked on the plugin that I don't even remember what corner cases I hit! But I recall that there was some weirdness around loading one file and then another, to keep the cache coherent.

Here: https://github.com/eyal0/OctoPrint-TimeToFilament/blob/master/octoprint_TimeToFilament/__init__.py#L99

We need to check if there is a cache and also if the data in the cache represents the current file or a different one. I think that I did it right but perhaps not!

[eyal0]

Looking at the code, the corner cases are around quitting a file and starting a new one and around doing a search that is not past the end of the file but is past the last M600.

The caching is there so that we don't need to redo the search if the next M600 is already past the current file position. So if file position is 100 and the M600 is at position 1000 then when we get to file position 200, we don't do another search because we already know that the next one is at position 1000.

If you can find a use case that breaks consistently, I can try to investigate. I use a virtual printer for testing so that I don't need to use an actual printer. (I don't even have a printer anymore.)

[puterboy]

My issue has been when I add a case to also check for M601. Is it possible that it finds M600 and doesn't look further for the M601 -- i.e., do you look for matches against all the cases?

As an aside, I seem to recall when I looked at the logs (which unfortunately I accidentally erased), it seemed that when it couldn't find the M601, it was first looking for M600 then M601 (on the first pause). But when it started working, the order had flipped but since it worked, I didn't have anything to investigate further and I had lost the old logs to confirm if something changed.

Also, as a further aside, the logging by default is very verbose, Would it make sense to only log that level of detail when in 'debug' mode?

[eyal0]

I could change this from info to debug, yeah: https://github.com/eyal0/OctoPrint-TimeToFilament/blob/master/octoprint_TimeToFilament/__init__.py#L144

The order of the regex search will vary because we only search for the ones that we need to search for. If our cached M600 result is still in the future then we don't need to search for it. But if it's in the past then we need a new one. Likewise for the other ones. We don't loop over each regex and then loop over each line. We loop over each line and then apply the regex to the line. This is because jumping around in the file is slower than jumping around between regexs.

To maintain which regexs need to be processed and which not, we use a set. https://github.com/eyal0/OctoPrint-TimeToFilament/blob/master/octoprint_TimeToFilament/__init__.py#L108 The set is not ordered and the order might change each time (this is a security feature). But it shouldn't affect correctness of the code. If you see that it is, I want to know about it!