homing regression between 1.0.4 and current development branch

[arekm]

Just switched from 1.0.4 to development firmware (via website generator) and printing on my X3D XL CoreXY printer fails immediately with log below. 1.0.4 worked just fine.

bisect led me to this commit:

commit be51311d095859b7d44a64df4d8b3c0c752a5681
Author: repetier <darko371@googlemail.com>
Date:   Fri Jan 22 14:33:56 2021 +0100

    Improved safe homing procedure

Reverting it makes problem go away.

08:54:17.324 : N2 M530 S1 L366*58
08:54:17.324 : N3 M531 CFFFP_2_1_Tubus_5cm_ESP32-CAM*85
08:54:17.324 : N4 M117 ETE 5h 19m 07s*56
08:54:17.324 : N5 G21*31
08:54:17.324 : N6 G90*22
08:54:17.324 : N7 M82*30
08:54:17.324 : N8 G28 Z0*81
08:54:17.335 : N9 G28 X0 Y0*27
08:54:17.337 : N10 G1 Z15 S100*37
08:54:17.340 : N11 G32 S2*105
08:54:17.368 : N12 G92 E0*116
08:54:17.368 : N13 G1 F200 E3*24
08:54:17.369 : N14 G92 E0*114
08:54:17.369 : N15 M117 Printing...*47
08:54:18.630 : RequestStop:
08:54:18.657 : fatal:Homing failed! - Printer stopped and heaters disabled due to this error. Fix error and restart with M999.
08:54:18.660 : fatal:Homing failed! - Printer stopped and heaters disabled due to this error. Fix error and restart with M999.
08:54:18.660 : N16 G28 Z0*110
08:54:18.668 : fatal:Homing failed! - Printer stopped and heaters disabled due to this error. Fix error and restart with M999.
08:54:18.671 : N17 M104 S0 T0*23
08:54:18.680 : fatal:Homing failed! - Printer stopped and heaters disabled due to this error. Fix error and restart with M999.
08:54:18.688 : fatal:Homing failed! - Printer stopped and heaters disabled due to this error. Fix error and restart with M999.
08:54:18.701 : fatal:Homing failed! - Printer stopped and heaters disabled due to this error. Fix error and restart with M999.
08:54:18.702 : N18 M140 S0*92
08:54:18.702 : N19 M530 S0*94
08:54:18.709 : fatal:Homing failed! - Printer stopped and heaters disabled due to this error. Fix error and restart with M999.
08:54:18.717 : Error:Checksum required when switching back to ASCII protocol.
08:54:18.717 : Resend:15
08:54:18.741 : Resend: N15 M117 Printing...*47
08:54:18.741 : Resend: N16 G28 Z0*110
08:54:18.741 : Resend: N17 M104 S0 T0*23
08:54:18.741 : Resend: N18 M140 S0*92
08:54:18.741 : Resend: N19 M530 S0*94
08:54:18.754 : fatal:Homing failed! - Printer stopped and heaters disabled due to this error. Fix error and restart with M999.
08:54:18.766 : fatal:Homing failed! - Printer stopped and heaters disabled due to this error. Fix error and restart with M999.
08:54:18.775 : fatal:Homing failed! - Printer stopped and heaters disabled due to this error. Fix error and restart with M999.
08:54:18.788 : fatal:Homing failed! - Printer stopped and heaters disabled due to this error. Fix error and restart with M999.
08:54:18.795 : fatal:Homing failed! - Printer stopped and heaters disabled due to this error. Fix error and restart with M999.

[repetier]

Thanks for the feedback. I assume you mean it happens with 1.0.5dev and the safe homing update introduced it.

Not sure it is really an error or configuration issue, but I have no core printer for testing.

If you change SAFE_HOMING to 0 you get old behaviour.

The big question is, if you just miss the condition required for safe homing so it triggers the error. First it would be better to just test one axis to see which of the 3 axes is causing it. G28 X0 G28 Y0 G28 Z0

The requirement is that the back move is long enough so that the end stop signal disappears. Then retest must trigger it again. Especially with mechanical end stops you need a few mm to untrigger and a too low distance can introduce that even if it worked before. WIth the error that before it would end in a bit different position.

For testing it is good to have the back move 20mm so it is easy visible if it trigger on first move, back move or retest move.

Also for core printers the x and y end stop must be untriggered at end of homing, so M119 should not show one of them as high. Reason is both move x and y motor.

[arekm]

Was testing Firmware from development branch (as of commit fa9198d96049ede3c94a680b9946fef38227c626).

G28 Z0 and it fails immediately. G28 [XY]0 work fine.

Note that with this printer Z max endstop is active in default position (bed is "lying" on thet endstop). Now G28 Z0 causes bed to move up a few mm (not enough to deactivate Z max endstop I think; didn't measure) and "homing failed" is reported.

If I move Z axis, so endstop is no longer active and then issue "G28 Z0" then homing succeeds.

Note that Z max endstop is the only Z endstop on this printer.

Didn't test with SAFE_HOMING 0 but it is the same as reverting commit be51311d095859b7d44a64df4d8b3c0c752a5681 which I tested (it works fine then).

[repetier]

Ok so z homing with Z_HOME_DIR 1 is the case. That is the same code as for my cartesians with z min homing, just testing opposite direction. Looking into code in Printer.cpp line 2159 i see no obvious reasion. Here code for analysis/discussion:

bool Printer::homeZAxis() { // Cartesian homing
#if defined(SENSORLESS_HOMING) && TMC2130_ON_Z
    while (!Printer::tmc_driver_z->stst())
        ; // Wait for motor stand-still
    uint32_t coolstep_speed = Printer::tmc_driver_z->coolstep_min_speed();
    uint32_t stealth_max_sp = Printer::tmc_driver_z->stealth_max_speed();
    bool stealth_state = Printer::tmc_driver_z->stealthChop();
    tmcPrepareHoming(Printer::tmc_driver_z, TMC2130_TCOOLTHRS_Z);
#endif
    long steps;
    if ((MIN_HARDWARE_ENDSTOP_Z && Z_MIN_PIN > -1 && Z_HOME_DIR == -1) || (MAX_HARDWARE_ENDSTOP_Z && Z_MAX_PIN > -1 && Z_HOME_DIR == 1)) {
        offsetZ2 = 0;
#if Z_HOME_DIR < 0 && Z_PROBE_PIN == Z_MIN_PIN && FEATURE_Z_PROBE
        if (!Printer::startProbing(true)) {
            return false;
        }
#endif
        coordinateOffset[Z_AXIS] = 0; // G92 Z offset
        UI_STATUS_UPD_F(Com::translatedF(UI_TEXT_HOME_Z_ID));
        steps = (zMaxSteps - zMinSteps) * Z_HOME_DIR;
        currentPositionSteps[Z_AXIS] = -steps;
        setHoming(true);
#if defined(Z_PROBE_DELAY) && Z_PROBE_DELAY > 0 && Z_MIN_PIN == Z_PROBE_PIN && Z_HOME_DIR == -1
        HAL::delayMilliseconds(Z_PROBE_DELAY);
#endif
#if NONLINEAR_SYSTEM
        transformCartesianStepsToDeltaSteps(currentPositionSteps, currentNonlinearPositionSteps);
#endif
        PrintLine::moveRelativeDistanceInSteps(0, 0, (5 * steps) / 4, 0, homingFeedrate[Z_AXIS], true, true);
        currentPositionSteps[Z_AXIS] = (Z_HOME_DIR == -1) ? zMinSteps : zMaxSteps;
#if NONLINEAR_SYSTEM
        transformCartesianStepsToDeltaSteps(currentPositionSteps, currentNonlinearPositionSteps);
#endif
#if SAFE_HOMING
        if (Z_HOME_DIR < 0) {
            if (!Endstops::zMin()) {
                return false;
            }
        } else {
            if (!Endstops::zMax()) {
                return false;
            }
        }
#endif
        PrintLine::moveRelativeDistanceInSteps(0, 0, axisStepsPerMM[Z_AXIS] * -ENDSTOP_Z_BACK_MOVE * Z_HOME_DIR, 0, homingFeedrate[Z_AXIS] / ENDSTOP_Z_RETEST_REDUCTION_FACTOR, true, false);
#if SAFE_HOMING
        Endstops::update();
        Endstops::update();
        if (Z_HOME_DIR < 0) {
            if (Endstops::zMin()) {
                return false;
            }
        } else {
            if (Endstops::zMax()) {
                return false;
            }
        }
#endif
#if defined(ZHOME_WAIT_UNSWING) && ZHOME_WAIT_UNSWING > 0
        HAL::delayMilliseconds(ZHOME_WAIT_UNSWING);
#endif
#if defined(Z_PROBE_DELAY) && Z_PROBE_DELAY > 0 && Z_MIN_PIN == Z_PROBE_PIN && Z_HOME_DIR == -1
        HAL::delayMilliseconds(Z_PROBE_DELAY);
#endif
#if Z_HOME_DIR < 0 && Z_PROBE_PIN == Z_MIN_PIN && FEATURE_Z_PROBE
#ifdef Z_PROBE_RUN_AFTER_EVERY_PROBE
        GCode::executeFString(PSTR(Z_PROBE_RUN_AFTER_EVERY_PROBE));
#endif
#endif
        PrintLine::moveRelativeDistanceInSteps(0, 0, axisStepsPerMM[Z_AXIS] * 2 * ENDSTOP_Z_BACK_MOVE * Z_HOME_DIR, 0, homingFeedrate[Z_AXIS] / ENDSTOP_Z_RETEST_REDUCTION_FACTOR, true, true);
#if SAFE_HOMING
        if (Z_HOME_DIR < 0) {
            if (!Endstops::zMin()) {
                return false;
            }
        } else {
            if (!Endstops::zMax()) {
                return false;
            }
        }
#endif

#if Z_HOME_DIR < 0 && Z_PROBE_PIN == Z_MIN_PIN && FEATURE_Z_PROBE
        Printer::finishProbing();
#endif
        setHoming(false);
        int32_t zCorrection = 0;
#if Z_HOME_DIR < 0 && MIN_HARDWARE_ENDSTOP_Z && FEATURE_Z_PROBE && Z_PROBE_PIN == Z_MIN_PIN
        // Fix error from z probe testing
        zCorrection -= axisStepsPerMM[Z_AXIS] * EEPROM::zProbeHeight();
        // Correct from bed rotation
        //updateCurrentPosition(true);
        //float xt,yt,zt;
        //transformToPrinter(currentPosition[X_AXIS],currentPosition[Y_AXIS],0,xt,yt,zt);
        //zCorrection -= zt;
#endif
#if defined(ENDSTOP_Z_BACK_ON_HOME)
        // If we want to go up a bit more for some reason
        if (ENDSTOP_Z_BACK_ON_HOME > 0) {
            zCorrection -= axisStepsPerMM[Z_AXIS] * ENDSTOP_Z_BACK_ON_HOME * Z_HOME_DIR;
        }
#endif
#if Z_HOME_DIR < 0
        // Fix bed coating
#if Z_PROBE_Z_OFFSET_MODE == 0 // Only if measure through coating e.g. inductive
        zCorrection += axisStepsPerMM[Z_AXIS] * zBedOffset;
#endif
#endif
        //Com::printFLN(PSTR("Z-Correction-Steps:"),zCorrection); // TEST
        PrintLine::moveRelativeDistanceInSteps(0, 0, zCorrection, 0, homingFeedrate[Z_AXIS], true, false);
        currentPositionSteps[Z_AXIS] = ((Z_HOME_DIR == -1) ? zMinSteps : zMaxSteps - zBedOffset * axisStepsPerMM[Z_AXIS]);
#if NUM_EXTRUDER > 0
#if (EXTRUDER_IS_Z_PROBE == 0 || Z_HOME_DIR > 0)
        // currentPositionSteps[Z_AXIS] -= Extruder::current->zOffset;
        Printer::offsetZ = -Extruder::current->zOffset * Printer::invAxisStepsPerMM[Z_AXIS];
#endif
#endif
#if DISTORTION_CORRECTION && Z_HOME_DIR < 0 && Z_PROBE_PIN == Z_MIN_PIN && FEATURE_Z_PROBE
        // Special case where z probe is z min end stop and distortion correction is enabled
        if (Printer::distortion.isEnabled()) {
            Printer::zCorrectionStepsIncluded = Printer::distortion.correct(Printer::currentPositionSteps[X_AXIS], currentPositionSteps[Y_AXIS], currentPositionSteps[Z_AXIS]);
            currentPositionSteps[Z_AXIS] += Printer::zCorrectionStepsIncluded;
        }
#endif
        updateCurrentPosition(true);
#if Z_HOME_DIR < 0 && Z_PROBE_PIN == Z_MIN_PIN && FEATURE_Z_PROBE
        // If we have software leveling enabled and are not at 0,0 z position is not zero, but we measured
        // for z = 0, so we need to correct for rotation.
        currentPositionSteps[Z_AXIS] -= (axisStepsPerMM[Z_AXIS] * currentPosition[Z_AXIS] - zMinSteps);
        currentPosition[Z_AXIS] = zMin;
#endif
#if NONLINEAR_SYSTEM
        transformCartesianStepsToDeltaSteps(currentPositionSteps, currentNonlinearPositionSteps);
#endif
        setZHomed(true);
#if FEATURE_BABYSTEPPING
        Printer::zBabysteps = 0;
#endif
    }
#if defined(SENSORLESS_HOMING) && TMC2130_ON_Z
    while (!Printer::tmc_driver_z->stst())
        ; // Wait for motor stand-still
    Printer::tmc_driver_z->coolstep_min_speed(coolstep_speed);
    Printer::tmc_driver_z->stealth_max_speed(stealth_max_sp);
    Printer::tmc_driver_z->stealthChop(stealth_state);
#endif
    return true;
}

From your description it breaks in the first occurence of

#if SAFE_HOMING
        if (Z_HOME_DIR < 0) {
            if (!Endstops::zMin()) {
                return false;
            }
        } else {
            if (!Endstops::zMax()) {
                return false;
            }
        }
#endif

As a proof you could modify them all like this to see where it really bails out:

#if SAFE_HOMING
        if (Z_HOME_DIR < 0) {
            if (!Endstops::zMin()) {
                return false;
            }
        } else {
            if (!Endstops::zMax()) {
Com::printFLN(PSTR("First Z Endstop Test Failed!")); // Change message for other parts analog
                return false;
            }
        }
#endif

Before this code there is a move to move towards end stop until it is hit. So the condition should be z max enabled. What troubles me is that when you start from below it triggers and is triggered and if you start triggered it says untriggered. So why would that happen. What kind of endstop are you using?

Also for testing can you try z homing with M111 S70 before. This enables endstop debugging so firmware reports any change. Can crash if messages come too fast so nothing for real printing, just to find such problems. So test would be

M111 S70
M119 ; See start condition
G28 Z0

Endstop status can only change if update() for them is called. At least for linear systems this is updated in stepper interrupt, so with bad timing and a swinging signal (switching high/low randomly) this may cause wrong signals. Might happen on some endstops at the edge between hit/not hit. In such cases you would just disable safe homing as it would not work reliably in that case.

[arekm]

It turns out that this was a configuration problem. And you indicated that already "The requirement is that the back move is long enough so that the end stop signal disappears. " which I didn't notice that it is part of configuration.

#define ENDSTOP_Z_BACK_MOVE 2

wasn't enough to untrigger Z max (mechanical) endstop. Previously that didn't matter (weird but that's the case) for this printer operation but with safe homing it matters.

With

#define ENDSTOP_Z_BACK_MOVE 5

z max untriggers and homing succeeds.

With bad config:

10:33:06.557 : N15 M111 S70*98
10:33:06.560 : DebugLevel:70
10:33:33.343 : N16 M119*29
10:33:33.351 : endstops hit: x_min:L y_min:L z_max:H Z-probe state:L
10:34:06.948 : N17 G28 Z0*111
10:34:08.211 : z problem z max 2
10:34:08.213 : RequestStop:
10:34:08.262 : fatal:Homing failed! - Printer stopped and heaters disabled due to this error. Fix error and restart with M999.

#endif
        PrintLine::moveRelativeDistanceInSteps(0, 0, axisStepsPerMM[Z_AXIS] * -ENDSTOP_Z_BACK_MOVE * Z_HOME_DIR, 0, homingFeedrate[Z_AXIS] / ENDSTOP_Z_RETEST_REDUCTION_FACTOR, true, false);
#if SAFE_HOMING
        Endstops::update();
        Endstops::update();
        if (Z_HOME_DIR < 0) {
            if (Endstops::zMin()) {
              Com::printFLN(PSTR("z problem z min 2"));
                return false;
            }
        } else {
            if (Endstops::zMax()) {
              Com::printFLN(PSTR("z problem z max 2"));
                return false;
            }
        }
#endif
#if defined(ZHOME_WAIT_UNSWING) && ZHOME_WAIT_UNSWING > 0
        HAL::delayMilliseconds(ZHOME_WAIT_UNSWING);

Maybe it could report, just like it does in some other part of code, when such scenario happens?

Com::printFLN(PSTR("Back move did not untrigger endstops!"), (float)ENDSTOP_Z_BACK_MOVE);

Closing as this is not a bug but user/me fault.