Marlin: [2.0.x] Filament Runout Sensor sporadic false positive when using FILAMENT_RUNOUT_DISTANCE_MM > 0

[ghost]

Description

I have a Filament Runout Sensor that has been running fine when I did not specify FILAMENT_RUNOUT_DISTANCE_MM.

As it is more convenient to let the filament be used by another 50mm on my printer, making it easier to catch the filament as it is retracted out of the bowden, I configured FILAMENT_RUNOUT_DISTANCE_MM to 50mm.

I tested this by cutting the filament and waiting, and everthing works as expected.

But now I have spontaneous false runout detections every couple of hours.

I shorted the microswitch with a wire (which rules out a faulty switch), I added two small capacitors across the wire near the plug into the controller and checked every eventuality that might point to a fail in the electronics. Seems there might be big noise on the wire, but remember: Debouncing worked fine until I specified FILAMENT_RUNOUT_DISTANCE_MM > 0.

I looked at the code and I can see that specifiying FILAMENT_RUNOUT_DISTANCE_MM > 0 effectively bypasses any debouncing.

Expected behavior: Specifying FILAMENT_RUNOUT_DISTANCE_MM >0 should debounce

Actual behavior: Specifying FILAMENT_RUNOUT_DISTANCE_MM >0 turns off any debouncing.

Additional Information

The code in /src/feature/runout.h is where debounce is done, if FILAMENT_RUNOUT_DISTANCE_MM is not specified.

[gloomyandy]

So are you saying that even with a wire shorting the switch and capacitors in place you still get false triggers? What happens if you just have a very short wire shorting the pins close to the board?

That sounds like you must have a big problem with noise. I'd consider using some sort of shielded cable, or perhaps twisted pairs. Although software filtering might help if you have that much noise there is a good chance you will still get false triggers.

[ghost]

So are you saying that even with a wire shorting the switch and capacitors in place you still get false triggers? What happens if you just have a very short wire shorting the pins close to the board?

Yes. Short wire? Oh, good idea - I will check that. Obviously, it will take a few hours to be conclusive evidence - if with a short wire, no false triggers, then it would still be nice to debounce in software. As I said, there are no false triggers when FILAMENT_RUNOUT_DISTANCE_MM is not specified.
I am modifying the code right now to change that behaviour and will see how that works out.

[ghost]

I can see in the code that the steps_since_detection[extruder] are set back to 0 if the sensor is closed, so effectively the distance needed equates to a debounce. Needs further testing on my part, methinks.

[ghost]

Further testing is complete. There is NO noise on the pin. Something else is happening and whilst I myself am also looking for the reason, I will put out my intermediate findings here.

I configured the FILAMENT_RUNOUT_DISTANCE_MM to 50.

In runout.h (/src/feature) I defined

#define FILAMENT_RUNOUT_SENSOR_DEBUG

and added another debug output to serial out down in the response type for the sensor like so:

      static inline void filament_present(const uint8_t extruder) {
        #ifdef FILAMENT_RUNOUT_SENSOR_DEBUG
          static uint16_t r = 0;
          if ((r++ % 4000) == 0) {
        SERIAL_PROTOCOLPGM("filament present on extruder ");
            SERIAL_PROTOCOL(extruder);
            SERIAL_EOL();
          }
    #endif
        steps_since_detection[extruder] = 0;
      }

      static inline void run() {
        #ifdef FILAMENT_RUNOUT_SENSOR_DEBUG
          static uint16_t r = 0;
          if ((r++ % 4000) == 0) {
            SERIAL_PROTOCOLPGM("mm since filament detection: ");
            LOOP_L_N(i, NUM_RUNOUT_SENSORS) {
              if (i > 0) SERIAL_PROTOCOLPGM(", ");
              SERIAL_PROTOCOL(get_mm_since_runout(i));
            }
            SERIAL_EOL();
          }
        #endif
      }

Note: The second debug output was there already. I just added the first one but it wasn't really needed to see the following problem:

In the following output, you see happy printing going on, with no sensor triggering, when suddenly out of the blue, M600 is enqueued (near the bottom):

Log Output

2018-11-13 18:21:31,575 - Send: N47131 G0 F6000 X99.529 Y118.164*125
2018-11-13 18:21:31,678 - Recv: ok
2018-11-13 18:21:31,682 - Send: N47132 G0 X98.408 Y116.364*17
2018-11-13 18:21:31,790 - Recv: ok
2018-11-13 18:21:31,794 - Send: N47133 G0 X97.836 Y115.149*16
2018-11-13 18:21:31,804 - Recv: ok
2018-11-13 18:21:31,807 - Send: N47134 G0 X97.082 Y113.087*21
2018-11-13 18:21:31,858 - Recv:  T:189.57 /190.00 B:60.01 /60.00 @:66 B@:40
2018-11-13 18:21:31,871 - Recv: ok
2018-11-13 18:21:31,875 - Send: N47135 G0 X97.219 Y113.058*22
2018-11-13 18:21:31,976 - Recv: ok
2018-11-13 18:21:31,980 - Send: N47136 G1 F1200 E2526.90277*57
2018-11-13 18:21:31,999 - Recv: ok
2018-11-13 18:21:32,003 - Send: N47137 G1 F3000 X96.16 Y111.999 E2526.95009*55
2018-11-13 18:21:32,033 - Recv: ok
2018-11-13 18:21:32,041 - Send: N47138 G0 F6000 X96.16 Y112.525*73
2018-11-13 18:21:32,175 - Recv: ok
2018-11-13 18:21:32,179 - Send: N47139 G1 F3000 X96.931 Y111.753 E2526.98457*15
2018-11-13 18:21:32,251 - Recv: mm since filament detection: 0.00
2018-11-13 18:21:32,253 - Recv: filament present on extruder ^@
2018-11-13 18:21:32,258 - Recv: ok
2018-11-13 18:21:32,261 - Send: N47140 G1 X97.001 Y111.683*28
2018-11-13 18:21:32,457 - Recv: ok
2018-11-13 18:21:32,461 - Send: N47141 G0 F6000 X99.608 Y111.339*121
2018-11-13 18:21:32,474 - Recv: ok
2018-11-13 18:21:32,479 - Send: N47142 G1 F3000 X102.288 Y108.659 E2527.10433*54
2018-11-13 18:21:32,554 - Recv: ok
2018-11-13 18:21:32,556 - Send: N47143 G1 X102.358 Y108.589*44
2018-11-13 18:21:32,701 - Recv: ok
2018-11-13 18:21:32,706 - Send: N47144 G0 F6000 X99.608 Y108.659*119
2018-11-13 18:21:32,853 - Recv: ok
2018-11-13 18:21:32,857 - Send: N47145 G1 F3000 X102.288 Y111.339 E2527.22408*51
2018-11-13 18:21:32,918 - Recv: ok
2018-11-13 18:21:32,921 - Send: N47146 G1 X102.358 Y111.409*40
2018-11-13 18:21:32,932 - Recv: ok
2018-11-13 18:21:32,934 - Send: N47147 G1 F1200 E2523.22408*61
2018-11-13 18:21:32,992 - Recv: ok
2018-11-13 18:21:32,995 - Send: N47148 G0 F6000 X102.358 Y111.2*72
2018-11-13 18:21:33,010 - Recv: ok
2018-11-13 18:21:33,013 - Send: N47149 G0 X96.76 Y108.725*32
2018-11-13 18:21:33,061 - Recv: ok
2018-11-13 18:21:33,064 - Send: N47150 G0 X96.797 Y108.216*21
2018-11-13 18:21:33,128 - Recv: ok
2018-11-13 18:21:33,131 - Send: N47151 G0 X96.932 Y108.246*16
2018-11-13 18:21:33,286 - Recv: ok
2018-11-13 18:21:33,290 - Send: N47152 G1 F1200 E2527.23448*56
2018-11-13 18:21:33,399 - Recv: ok
2018-11-13 18:21:33,403 - Send: N47153 G1 F3000 X96.16 Y107.473 E2527.26899*51
2018-11-13 18:21:33,429 - Recv: ok
2018-11-13 18:21:33,433 - Send: N47154 G0 F6000 X96.16 Y107.999*76
2018-11-13 18:21:33,487 - Recv: ok
2018-11-13 18:21:33,490 - Send: N47155 G1 F3000 X97.219 Y106.94 E2527.31632*60
2018-11-13 18:21:33,501 - Recv: ok
2018-11-13 18:21:33,504 - Send: N47156 G1 X97.289 Y106.87*45
2018-11-13 18:21:33,574 - Recv: ok
2018-11-13 18:21:33,577 - Send: N47157 G1 F1200 E2523.31632*53
2018-11-13 18:21:33,593 - Recv: mm since filament detection: 0.00
2018-11-13 18:21:33,596 - Recv: filament present on extruder ^@
2018-11-13 18:21:33,739 - Recv: ok
2018-11-13 18:21:33,743 - Send: N47158 G0 F6000 X97.102 Y106.829*126
2018-11-13 18:21:33,796 - Recv: ok
2018-11-13 18:21:33,800 - Send: N47159 G0 X98.037 Y104.361*18
2018-11-13 18:21:33,823 - Recv: ok
2018-11-13 18:21:33,826 - Send: N47160 G0 X98.487 Y103.545*16
2018-11-13 18:21:33,857 - Recv:  T:189.55 /190.00 B:60.00 /60.00 @:66 B@:43
2018-11-13 18:21:33,986 - Recv: ok
2018-11-13 18:21:33,991 - Send: N47161 G0 X99.538 Y101.824*29
2018-11-13 18:21:34,149 - Recv: ok
2018-11-13 18:21:34,154 - Send: N47162 G0 X99.647 Y101.91*35
2018-11-13 18:21:34,203 - Recv: echo:enqueueing "M600"
2018-11-13 18:21:35,159 - Recv: ok
2018-11-13 18:21:35,167 - Send: N47163 G1 F1200 E2527.32671*50
2018-11-13 18:21:35,878 - Recv:  T:189.66 /190.00 B:60.00 /60.00 @:65 B@:42
2018-11-13 18:21:37,179 - Recv: echo:busy: processing
2018-11-13 18:21:37,890 - Recv:  T:190.00 /190.00 B:60.00 /60.00 @:59 B@:42
2018-11-13 18:21:39,193 - Recv: echo:busy: processing
2018-11-13 18:21:39,900 - Recv:  T:190.36 /190.00 B:60.00 /60.00 @:53 B@:42
2018-11-13 18:21:41,204 - Recv: echo:busy: processing
2018-11-13 18:21:41,913 - Recv:  T:190.59 /190.00 B:60.00 /60.00 @:49 B@:42
2018-11-13 18:21:43,215 - Recv: echo:busy: processing
2018-11-13 18:21:43,926 - Recv:  T:191.05 /190.00 B:60.00 /60.00 @:40 B@:41
2018-11-13 18:21:45,228 - Recv: echo:busy: processing
2018-11-13 18:21:45,937 - Recv:  T:191.05 /190.00 B:60.00 /60.00 @:39 B@:41
2018-11-13 18:21:47,241 - Recv: echo:busy: processing
2018-11-13 18:21:47,950 - Recv:  T:190.59 /190.00 B:60.00 /60.00 @:46 B@:41
2018-11-13 18:21:49,253 - Recv: echo:busy: processing
2018-11-13 18:21:49,965 - Recv:  T:190.20 /190.00 B:59.99 /60.00 @:51 B@:46
2018-11-13 18:21:51,267 - Recv: echo:busy: processing

---

Normally you would see increasing mm values until 50.0 before the M600 is enqueued - here is what that would look like:

Log Output

2018-11-13 16:15:42,572 - Send: N4221 G1 F900 X119.12 Y123.872 E257.00562*62
2018-11-13 16:15:43,190 - Recv: mm since filament detection: 3.52
2018-11-13 16:15:43,727 - Recv: mm since filament detection: 3.79
2018-11-13 16:15:44,297 - Recv:  T:200.00 /200.00 B:65.00 /65.00 @:56 B@:48
2018-11-13 16:15:44,357 - Recv: mm since filament detection: 4.33
2018-11-13 16:15:44,463 - Recv: ok
2018-11-13 16:15:44,468 - Send: N4222 G0 F1800 X119.524 Y123.597*112
2018-11-13 16:15:44,822 - Recv: ok
2018-11-13 16:15:44,828 - Send: N4223 G1 F900 X96.401 Y100.474 E258.6697*7
2018-11-13 16:15:45,017 - Recv: mm since filament detection: 4.87
2018-11-13 16:15:45,555 - Recv: mm since filament detection: 5.14
2018-11-13 16:15:45,766 - Recv: mm since filament detection: 5.41
2018-11-13 16:15:46,299 - Recv:  T:200.00 /200.00 B:65.00 /65.00 @:56 B@:48
2018-11-13 16:15:46,397 - Recv: mm since filament detection: 5.96
2018-11-13 16:15:46,651 - Recv: ok
etc
etc until 50.0 mm and then M600...

---

I found that the only plausible (I think, I hope) place that would have enqueued the M600 is also in runout.h:

    static void run() {
      if (enabled && !filament_ran_out && (IS_SD_PRINTING() || print_job_timer.isRunning())) {
        response.run();
        sensor.run();
        if (response.has_runout()) {
          filament_ran_out = true;
          #if ENABLED(EXTENSIBLE_UI)
            UI::onFilamentRunout();
          #endif
          enqueue_and_echo_commands_P(PSTR(FILAMENT_RUNOUT_SCRIPT));
          planner.synchronize();
        }
      }
    }
};

I will put some debug statements in there and start a test print again. It will take maybe an hours worth of printing and then it will happen again. We will see.

* additional fact (reminder): Using the normal response type (debounced instead of distance) makes the problem go away - response.run() and sensor.run() are my potential culprits*

I will reopen this in case anyone else can see where the problem lies.

[thinkyhead]

Better for your testing: SERIAL_PROTOCOL(int(extruder));

[thinkyhead]

Try the modified filament runout code, with debugging enabled, in this branch: https://github.com/thinkyhead/Marlin/archive/bf2_runout_rejigger.zip

I didn't find any obvious flaw in the design, but maybe the rearranged code and modified debugging will help to show what's going on more clearly.

[ghost]

@thinkyhead: yup, I can see you have changed the logic in the runout.h to a mm countdown. Ok, I'll test that (runout.h, runout.cpp) and if it fails as well, I will continue debugging with that.

[ghost]

@thinkyhead: Ok, your new runout.h and runout.cpp is up and running, the test print object is progressing and it will take a few hours to see if a false runout will occur. Just now I have tested a real runout and that performed ok.

[thinkyhead]

I'm just glad to hear it's compiling and running. Took me a while to clear up all the typos.

[InsanityAutomation]

I did see a few blips on a NO sensor which was unplugged at the time where serial log reported distance since triggering at 0.1 then back to 0.0 so I had written it off as noise. I plan to look at filtering options for runout as there are also plenty of shaky sensors that blink occasionally out there.

[ghost]

Ok, while the print is running, i can see some occurences of (Recv: ok removed):

Send: N31230 G1 X103.199 Y103.613 E1925.67572*90
Recv: Remaining mm: 49.98
Send: N31231 G1 X102.81 Y104.051 E1925.69423*110
Send: N31232 G1 X102.451 Y104.516 E1925.71279*82

as well as (probably a retract)

Send: N31178 G1 X103.796 Y102.502 E1924.17122*89
Send: N31179 G1 X103.339 Y102.908 E1924.19053*86
Recv: Remaining mm: 54.00
Send: N31180 G1 X102.908 Y103.339 E1924.20979*91
Send: N31181 G1 X102.502 Y103.796 E1924.22911*81

This is the same sort of thing that was happening with the previous code. If, by any chance, the arithmetic in runout_mm_countdown[e] -= (TEST(b->direction_bits, E_AXIS) ? -steps : steps) * planner.steps_to_mm[E_AXIS_N(e)]; results beyond the threshold, it will trigger even without the sensor being active. That was the direction my testing of the old code was going.

IMHO if the sensor is inactive, the runout_mm_countdown should not be updated at all - because has_run_out() seems to be called before a filament_present() sets the countdown back to the threshold. Or has_run_out() needs to qualify its final decision by doing a safety check on the sensor status.

[thinkyhead]

If runout.enabled is false, all endstop logic is bypassed. Plus, runout.reset is called whenever the enabled state is altered. So you should see absolutely no debug output when the sensor is disabled by M412 S0.

The calculation you point out must be doing something odd, because it shouldn't be able to go over 50. Can you drop the G-code file you're printing into your next reply? (It will need to be put into a ZIP archive or renamed with a .txt extension.)

When runout.enabled is true… the runout.run method calls response.run immediately before it calls sensor.run. When using the simple debounce, response.run will decrement the countdown, and then sensor.run will immediately set it to 0 if the sensor detects filament. These both occur before has_run_out is called.

With the delayed response type, the ordering is the same as described, so response.run in that case does nothing (except print the debug info), and then sensor.run immediately calls filament_present (if it is detected as present) which resets the runout_mm_countdown value (for the active extruder) back to runout_threshold_mm.

So there is one potential flaw in the logic, which is if there is a very long E movement (50mm or more), and then the filament sensor gives a false signal at the exact moment that sensor.run is called, so that it fails to reset runout_mm_countdown, then it could be seen as a false runout. But the potential for that is infinitesimally small.

In your output log did you see any Filament OUT or Filament OK messages? Did you see any instances where Remaining mm: went anywhere close to 0?

[ghost]

Ok, the object has printed ok. Your new code looks good - unless someone specifies 1mm as the runout distance (see previous comment).
Do you want me to continue the testing on the old code to find the error?

[thinkyhead]

I think it's a good sign that the modified code is working well. Maybe there was a hole in the old logic. I may give it more analysis. I'm not too fond of the methodology as it stands, so I'm sure I'll continue to mess with it to get rid of the "count first, reset later" behavior. I am curious how the runout_mm_countdown ends up going over 50. That is unusual.

I'll merge what I have now, and later today I'll mess with it some more. Then I'll post again here when I have something new to test.

Thanks for checking it out, and please let me know if you see any false runouts again.

[ghost]

Oh, and I agree with your above comments.

So there is one potential flaw in the logic, which is if there is a very long E movement (50mm or more), and then the filament sensor gives a false signal at the exact moment that sensor.run is called, so that it fails to reset runout_mm_countdown, then it could be seen as a false runout. But the potential for that is infinitesimally small.

I agree, such a long extrusion would be quite strange.

The calculation you point out must be doing something odd, because it shouldn't be able to go over 50.

Well if the countdown is sitting at 50 and the (TEST(b->direction_bits, E_AXIS) ? -steps : steps) * planner.steps_to_mm[E_AXIS_N(e)]; is negative, there is a window where the countdown is above 50 and not yet reset back to 50 by the sensor run.

Here is the gcode zip file:
CFFFP_power-socket-cover.zip

[InsanityAutomation]

Long Bowden tubes would have a load command over 50.

[ghost]

@InsanityAutomation: Yup, so does mine.

@thinkyhead : I notice that the call to runout.block_complete(current_block); in stepper.cpp comes into this asynchronously? Perhaps I will put a debug output into block_complete to see if we get a lot of increments/decrements BEFORE the countdown gets reset.

[thinkyhead]

@InsanityAutomation — Even so, the false positive signal would have to occur during the tiny interval between the move completing and the next reset of the countdown, which happens microseconds later. While a false positive is possible during that time, the chance is exceedingly small.

[thinkyhead]

Well if the countdown is sitting at 50 and…

Oh right, retraction…

[marcio-ao]

Is it possible that the counter value is getting corrupted because it is incremented during an ISR, but is reset to zero during the idle loop? It is possible that if the stars align just right, the ISR fires while the counter is being cleared in the idle loop, the ISR increments a partially cleared value, and all hell breaks loose. Maybe there needs to be a "noInterrupts()" and "interrupts()" in the "filament_present()" method whenever the counter value is cleared. For good measure, maybe "noInterrupts()" and "interrupts()" should be called in "has_run_out()" which is checking the value, also to prevent the ISR from modifying the value while it is being read.

The joys of concurrent programming...

[ghost]

Is it possible that the counter value is getting corrupted because it is incremented during an ISR,...

Then the new code should also fail.

I'm on the second test print of the obeject now (thankfully, I can make use of them) and have not had a fail yet.

Just the observed deviations from the 50mm - which are slightly worrying, but the behaviour is now better by far.

I wonder what part of the old code, which is really not so very different, was causing this.

• Counting Down vs. Counting Up : that can't be it
• The arithmetic has changed, no longer accumulating 32-Bit signed integer steps then dividing by steps per mm, but rather using float and multiplying by mm per step. Hmmmm.

I am in favor of a merge

[marcio-ao]

I'm not too fond of the methodology as it stands, so I'm sure I'll continue to mess with it to get rid of the "count first, reset later" behavior.

I wasn't fond of this either. But I couldn't see any way to get more accurate real-time information out of the stepper ISR without the potential of introducing timing issues.

So there is one potential flaw in the logic, which is if there is a very long E movement (50mm or more)..

It certainly is a flaw with the current algorithm that FILAMENT_RUNOUT_DISTANCE_MM must be longer than any possible retractions, with possibly a margin of safety beyond that. The current scheme is admittedly crude and I welcome any improvements to it :)

[ghost]

Maybe need just a safety net by doing a final check of the filament sensor before invoking the runout script - as a failsafe so to speak and thereby acknowledging that one small flaw in the algorithm?

[marcio-ao]

Is it possible that the counter value is getting corrupted because it is incremented during an ISR,...
Then the new code should also fail.

@FanDjango: Just a wild guess, but it is possible that tge incrementing/clearing of an int32 is sufficiently different from the incrementing/clearing of an IEEE float to account for why it failed with one vs the other.

I would say that if the current code works, then we should run with it. Adding "noInterrupts()" and "interrupts()" could possibly affect the timing in the ISR, so probably best not to add those unless it is absolutely necessary.

[marcio-ao]

Maybe need just a safety net by doing a final check of the filament sensor before invoking the runout script - as a failsafe so to speak and thereby acknowledging that one small flaw in the algorithm?

That final check may work for an endstop style sensor, but it would not work for an encoder-disc type sensor, which only triggers filament presence every once in a while.

[ghost]

Just a wild guess, but it is possible that tge incrementing/clearing of an int32 is sufficiently different from the incrementing/clearing of an IEEE float to account for why it failed with one vs the other.

Possibly getting into an architecture dependant bug here - same behaviour on (all) 32bit platforms?

If the old code produces the error, I think I will prefer to (try) to isolate the problem there - in the new code it doesn't seem to happen anymore up to now. I'll have a go at it tomorrow.

Don't really want to keep you guys busy on this one thing only.

[thinkyhead]

One thing that occurred to me was that a single noisy filament sensor signal is enough to trigger a runout if the distance accumulator happens to be past the limit at that exact moment. So it would seem to be a good idea to include the debounce in all cases, even with the distance counter, to ensure that the runout is genuine.

This could be accomplished at a lower level by making filament sensors part of the endstops suite, so they would not show up as triggered unless they passed the same threshold to which endstops are beholden.

Anyway, one thing I did change to prevent block_complete from being called at an inopportune moment was this:

  // Give the response a chance to update its counter.
  static inline void run() {
    if (enabled && !filament_ran_out && (IS_SD_PRINTING() || print_job_timer.isRunning())) {
+     #if FILAMENT_RUNOUT_DISTANCE_MM > 0
+       cli(); // Prevent RunoutResponseDelayed::block_completed from accumulating here
+     #endif
      response.run();
      sensor.run();
+     const bool ran_out = response.has_run_out();
+     #if FILAMENT_RUNOUT_DISTANCE_MM > 0
+       sei();
+     #endif
+     if (ran_out) {
        filament_ran_out = true;
        #if ENABLED(EXTENSIBLE_UI)
          UI::onFilamentRunout();
        #endif
        enqueue_and_echo_commands_P(PSTR(FILAMENT_RUNOUT_SCRIPT));
        planner.synchronize();
      }
    }
  }

[marcio-ao]

So it would seem to be a good idea to include the debounce in all cases, even with the distance counter, to ensure that the runout is genuine.

I guess I would have to see your proposal to see if it works with the encoder disc sensor. One thing to know about the encoder disc sensor is that it is not a run-out sensor, it is a filament presence sensor that issues a signal few mms if filament is moving. This is reason I changed the names of some of the classes to "FilamentPresenceSensor", because that is what the motion sensor is.

The behavior of an endstop and an encoder disc are quite different. An endstop switch will show filament presence most of the times, with a few false negatives. The encoder disc will for the majority of the time show a not-present signal (i.e. no change on the inputs) with a change indicating filament motion every few millimeters. Therefore, in the case of the encoder disc, it is important not to suppress any signals. Any changes should be interpreted as filament being present. Only if filament is extruded for FILAMENT_RUNOUT_DISTANCE_MM without any pulses should a run-out be triggered. This is the logic I have implemented. This logic should also work for endstops, because FILAMENT_RUNOUT_DISTANCE_MM is essentially a really long debounce period.

[thinkyhead]

Exhibit A — The current logic.

Simple Switch with Debounce:

• main loop calls runout.run() to:
  
  
  
  • count-down the debounce threshold (response.run)
  
  
  • reset the debounce if filament is present (sensor.run)
  
  
  • fire runout action if the debounce goes to 0 (response.has_run_out)
  
  

Simple Switch with Distance Counter:

• stepper calls, whenever, block_completed to accumulate distance
• main loop calls runout.run() to:
  
  
  
  • cli()
  
  
  • (do nothing on response.run)
  
  
  • reset the distance accumulator if filament is present (sensor.run)
  
  
  • sei()
  
  
  • fire runout action if the accumulator was below 0 (response.has_run_out)
  
  

Encoder Wheel with Distance Counter:

• stepper calls, whenever, block_completed => runout.filament_present to reset the accumulator
• main loop calls runout.run() to:
  
  
  
  • (do nothing on response.run)
  
  
  • poll the encoder bits (sensor.run) but don't respond to them
  
  
  • fire runout action if the accumulator is below 0 (response.has_run_out)
  
  

[marcio-ao]

Encoder Wheel with Debounce

This is not a valid choice. You may have missed the fact that in my original PR, this combination was not allowed. The encoder wheel has to be used with the distance counter, otherwise it would trigger anytime the wheel was between poles, which is pretty much always.

[thinkyhead]

Oh yeah, I see it's ensured in the config.

[marcio-ao]

Encoder Wheel with Distance Counter:
if block_completed happened here, accumulator reset would be trumped

Yes, this is a known flaw with the algorithm. The stepper ISR currently does not give me real-time updates about where the extruder is at during a move, it can either tell me "I am about to move x mm", or "I have just moved x mm". However, the encoder wheel will change state sometime in between "I am about to move x mm" and "I have just moved x mm". This means the count may be inaccurate for up to the distance of a single move.

For a sufficient high value of FILAMENT_RUNOUT_DISTANCE_MM, this should not present a problem.

[thinkyhead]

Yeah, the one rare case, as cited above, was following a filament load move which had a false runout trigger at just the wrong moment, while the sensor was enabled.

One way around would be to ignore E moves that occur without XY moves, which would tend to only trigger the filament runout action during actual printing.

I notice that since we're only checking the active extruder's distance in has_run_out, the EXTRUDERS-sized array can be replaced with a single value without affecting anything.

[marcio-ao]

I notice that since we're only checking the active extruder's distance in has_run_out, the EXTRUDERS-sized array can be replaced with a single value without affecting anything.

Nope. Originally I had implemented it that way, but on some dual prints, such as a dual color moai, there isn't enough filament extruded of one color per layer to detect a runout of that particular color (i.e. the amount extruded per layer < FILAMENT_RUNOUT_DISTANCE_MM). Hence, it is necessary to keep track of how much has been extruded without filament motion on that particular extruder across multiple nozzle changes.

[marcio-ao]

Yeah, the one rare case, as cited above, was following a filament load move which had a false runout trigger at just the wrong moment, while the sensor was enabled.

Yes, we have run into the problem.

One way around would be to ignore E moves that occur without XY moves, which would tend to only trigger the filament runout action during actual printing.

I like that solution. It makes sense to me.

[thinkyhead]

Originally I had implemented it that way, but on some dual prints, such as a dual color moai, there isn't enough filament extruded of one color per layer to detect a runout of that particular color

I see. So as the extruders switch from one to the other, the distance is still being tracked for the one that ran out, until eventually it extrudes enough to finally trigger the action.

[marcio-ao]

I see. So as the extruders switch from one to the other, the distance is still being tracked for the one that ran out, until eventually it extrudes enough to finally trigger the action.

Yup. And we use 3 mm filament, which makes the problem worse. It's surprising how much you can print with just a short length of that stuff.

[thinkyhead]

I almost miss using 3mm. I've still got a roll, and a machine that could use it, if only it was reassembled…

[ghost]

You were faster, I was going to suggest the following to avoid the arithmetic in the ISR (need to test it first, but a prior test-print is running right now):

  // RunoutResponseDelayed triggers a runout event only if the length
  // of filament specified by FILAMENT_RUNOUT_DISTANCE_MM has been fed
  // during a runout condition.
  class RunoutResponseDelayed {
    private:
      static float runout_steps_countdown[EXTRUDERS];

    public:
      static float runout_threshold_mm;

      static void reset() {
        LOOP_L_N(i, EXTRUDERS) filament_present(i);
      }

      static inline void run() {
        #ifdef FILAMENT_RUNOUT_SENSOR_DEBUG
          static millis_t t = 0;
          const millis_t ms = millis();
          if (ELAPSED(ms, t)) {
            t = millis() + 1000UL;
            LOOP_L_N(i, EXTRUDERS) {
              serialprintPGM(i ? PSTR(", ") : PSTR("Remaining mm: "));
              SERIAL_PROTOCOL(runout_steps_countdown[i] * planner.steps_to_mm[E_AXIS_N(i)]);
            }
            SERIAL_EOL();
          }
        #endif
      }

      static inline bool has_run_out() {
        return runout_steps_countdown[active_extruder] < 0;
      }

      static inline void filament_present(const uint8_t extruder) {
        runout_steps_countdown[extruder] = runout_threshold_mm / planner.steps_to_mm[E_AXIS_N(extruder)];
      }

      static inline void block_complete(const block_t* const b) {
        const uint8_t e = b->extruder;
        const int32_t steps = b->steps[E_AXIS];
        runout_steps_countdown[e] -= (TEST(b->direction_bits, E_AXIS) ? -steps : steps);
      }
  };

in runout.h

and

  float RunoutResponseDelayed::runout_threshold_mm = FILAMENT_RUNOUT_DISTANCE_MM,
               RunoutResponseDelayed::runout_steps_countdown[EXTRUDERS];

in runout.cpp

[ghost]

Gotcha, caught the error in the OLD version of the code.
Using some more debugging output in function has_runout:

2018-11-14 23:13:19,334 - Send: N62227 G0 F6000 X125.609 Y103.441*65
2018-11-14 23:13:19,342 - Recv: mm since filament detection: 0.00
2018-11-14 23:13:19,447 - Recv: ok
2018-11-14 23:13:19,451 - Send: N62228 G1 F3000 X124.607 Y104.443 E3081.53219*61
2018-11-14 23:13:19,608 - Recv: ok
2018-11-14 23:13:19,613 - Send: N62229 G0 F6000 X124.477 Y104.112*65
2018-11-14 23:13:19,679 - Recv: ok
2018-11-14 23:13:19,683 - Send: N62230 G1 F3000 X126.304 Y105.939 E3081.61383*50
2018-11-14 23:13:19,710 - Recv: ok
2018-11-14 23:13:19,714 - Send: N62231 G1 X126.374 Y106.009*38
2018-11-14 23:13:19,807 - Recv: ok
2018-11-14 23:13:19,810 - Send: N62232 G0 F6000 X126.207 Y105.105*79
2018-11-14 23:13:19,980 - Recv: has_runout:
2018-11-14 23:13:19,982 - Recv: steps since detection: 16773216
2018-11-14 23:13:19,984 - Recv: planner settings axis steps per mm: 1000.00
2018-11-14 23:13:19,986 - Recv: mm since filament detection: 16773.22
2018-11-14 23:13:19,988 - Recv: echo:enqueueing "M600"
2018-11-14 23:13:21,134 - Recv:  T:190.03 /190.00 B:60.00 /60.00 @:64 B@:44

16773216 is 00FFF060x so nothing suspicious there, but it sort of confirms the concurreny suspicion that @marcio-ao mentioned - especially as the error occurs at entirely different times on the same print object, seemingly at random.

Now moving to the new code as committed by @thinkyhead and 3 or 4 of the same test prints. If they remain good as the first two already done, I think this can be closed. I will report tomorrow.

[ghost]

Been printing all day - no more false positives. @FanDjango is happy and thanks to you all.

[ghost]

I am sorry to say that this issue needs to be reopened: Until 2.0.x from 2018/11/24 problem was not occuring.
BUT with 2.0.x from 2018/11/15 issue occurs more or less immediately on print start and repeatedly with seconds after successful resume. Looks like there is a regression here.
Sadly, I don't have time this week to check on a day by day basis which commit in that time period is at fault. I can do this next week. Meanwhile I am back on 2.0.x 2018/11/24

[ghost]

Ok, I found the problem: The value of FIL_RUNOUT_INVERTING is now inverted due to this commit. I used to use false, I now had to set it to true. I think this corresponds better to the actual situation in my printer: The switch pulls down to GND.