Marlin: Issues when switching tools (RCBugFix)

[Alex9779]

I am testing dual extrusion with RCBugFix and with the new Tx S1 commands and while a simple switch seems to work in the whole process of multiple commands there are still issues.

The sequence I run is:

G28
M218 T1 X29.5 Y-18.1 ; set offset
G1 Z50 F3000
G1 X150 Y100 ; middle of the bed
T1 ; T1 moves to X150 Y100
T0 ; T0 moces to X150 Y100
T1 S1 ; head stays, coordinates show X179 Y81
T0 ; T0 moves to X179 Y81

; and now start strange things
T1 ; T1 moves to X150 Y100 (!) and then to X179 Y81

[thinkyhead]

Still staring at gcode_T to try to see why it does two moves. It only has code to perform one move after changing the position. So, it's strange.

[Alex9779]

I can make a video if you don't believe me and I just run the commands I posted above...
I searched too and have no idea why that happens...
Must be connected to be do-not-move commands somehow...

[lavato]

Just a thought: In #3899 T1 also moves by ~30mm (179-150 =-29) . (offset between hotends ?)

[Alex9779]

Anything I can do, test, try to help solving this?

[Alex9779]

Ok I did some further tests with the RCBUgFix of half an hour ago.
I uploaded the new firmware and loaded failsafe defaults.
Then I ran the code and all was good.
I tried to switch tools with and without moving the head and all was good.

Then I levelled the bed, I use mesh/manual bed levelling and then the strange things started.
To be able to better observe when running a complete gcode file with the code I posted above I inserted G4 S5command to wait between the switches and this behaved different than running the code without the pauses.
With pauses the first switch to T1didn't move the head but the coordinates stayed at X150 Y100, the switch back to T0 moves the head and the coordinates remained at X150 Y100, the head looks like that T0 is not at X179 Y81.
Switching to T1 S1 does not move the head and the coordinates change to X179 Y81.
Switching to T0 moved the head, coordinates are X179 Y81 but because the head moves this are not the actual coordinates of T0.

Running there script without the pauses does move the tools correct except the strange move in the last line when switching to T1 again the head moves to X150 Y100 first and instantly to X179 Y81.

[Alex9779]

Ok I made seom videos and the behaviour really worries me.
I made two test files:
file 1:

G28
M218 T1 X29.5 Y-18.1 ; set offset
G1 Z3 F3000
G1 X150 Y100 ; middle of the bed
T1 ; T1 moves to X150 Y100
T0 ; T0 moces to X150 Y100
T1 S1 ; head stays, coordinates show X179 Y81
T0 ; T0 moves to X179 Y81

; and now start strange things
T1 ; T1 moves to X150 Y100 (!) and then to X179 Y81

and file 2:

G28
M218 T1 X29.5 Y-18.1 ; set offset
G1 Z3 F3000
G1 X150 Y100 ; middle of the bed
G4 S2
T1 ; T1 moves to X150 Y100
G4 S2
T0 ; T0 moces to X150 Y100
G4 S2
T1 S1 ; head stays, coordinates show X179 Y81
G4 S2
T0 ; T0 moves to X179 Y81
G4 S2
; and now start strange things
T1 ; T1 moves to X150 Y100 (!) and then to X179 Y81

And I did the following:

1. I loaded failsafe defaults, stored memory, powered down the box then switched on and ran each file.
   File 1: https://youtu.be/VaXWmThGgho
   File 2: https://youtu.be/5xSltapXBlw
2. I levelled the bed and stored memory.
   File 1: https://youtu.be/ByabBhphWr4
   File 2: https://youtu.be/DLbla4QnJIE
3. I powered down the box then switched on again.
   File 1: https://youtu.be/XABfKn1KC2I
   File 2: https://youtu.be/LBQm6YXyo9I

The only one running fine is the first file right with an EEPROM with failsafe defaults. The second file behaves not correct.
Second try after I levelled the bed shows also the same misbehaviour with both files, different than the misbehaviour of test one of the second file.
The third try after a restart shows another changed behaviour, with file 1 you can see the additional move on the last command, the second file shows the same behaviour as in try 2.

So the file with the pauses is always misbehaving, maybe I get something wrong with the pause commands, maybe the are not usable or I am getting something wrong?

At least the first should do the rights things as this is nothing special but it only does with default values in the EEPROM, bed levelling seems to have an influence and rebooting after bed levelling changes the behaviour again...

[Alex9779]

Sorry something got mixed up, I accidentally switched some links, I corrected the order in my previous post...

[thinkyhead]

I've added more logging for gcode_T in #4308 (https://github.com/thinkyhead/Marlin/tree/rc_debug_gcode_t) so please test! Be sure to enable DEBUG_LEVELING_FEATURE and use M111 S32 before testing. Then post the log here. Hopefully it will reveal … something!

[Alex9779]

I uploaded the new firmware to the machine, I did NOT load failsafe defaults this time, I just run file 1 with am M111 S255 at the very beginning.
So current state of the machine is as it was after test 3 yesterday, that is the machine is leveled with MBL, values saved to EEPROM and I booted it before the test.
Here is the log:

Toolchange Log

Changing monitoring state from 'Operational' to 'Printing'
Send: N0 M110 N0*125
Recv: ok
Send: N1 M111 S255*98
Recv: echo:DEBUG:ECHO,INFO,ERRORS,DRYRUN,COMMUNICATION,LEVELING
Recv: ok
Send: N2 G28*17
Recv: echo:N2 G28*17
Recv: >>> gcode_G28
Recv: current_position=(0.00, 0.00, 0.00) : setup_for_endstop_or_probe_move
Recv: > endstops.enable(true)
Recv: Raise Z (before homing) to 4.00
Recv: >>> homeaxis(1)
Recv: current_position=(0.00, 0.00, 4.00) : sync_plan_position
Recv: echo:busy: processing
Recv: current_position=(0.00, 0.00, 4.00) : sync_plan_position
Recv: current_position=(0.00, 0.00, 4.00) : > TRIGGER ENDSTOP
Recv: >>> set_axis_is_at_home(1)
Recv: For 89 axis:
Recv:  home_offset = 0.00
Recv:  position_shift = 0.00
Recv:  sw_endstop_min = 0.00
Recv:  sw_endstop_max = 240.00
Recv: > home_offset[89] = 0.00
Recv: current_position=(0.00, 0.00, 4.00) :
Recv: <<< set_axis_is_at_home(1)
Recv: current_position=(0.00, 0.00, 4.00) : sync_plan_position
Recv: current_position=(0.00, 0.00, 4.00) : > AFTER set_axis_is_at_home
Recv: <<< homeaxis(1)
Recv: current_position=(0.00, 0.00, 4.00) : > homeY
Recv: >>> homeaxis(0)
Recv: current_position=(0.00, 0.00, 4.00) : sync_plan_position
Recv: echo:busy: processing
Recv: echo:busy: processing
Recv: current_position=(0.00, 0.00, 4.00) : sync_plan_position
Recv: current_position=(0.00, 0.00, 4.00) : > TRIGGER ENDSTOP
Recv: >>> set_axis_is_at_home(0)
Recv: For 88 axis:
Recv:  home_offset = 0.00
Recv:  position_shift = 0.00
Recv:  sw_endstop_min = -29.50
Recv:  sw_endstop_max = 300.00
Recv: > home_offset[88] = 0.00
Recv: current_position=(-29.50, 0.00, 4.00) :
Recv: <<< set_axis_is_at_home(0)
Recv: current_position=(-29.50, 0.00, 4.00) : sync_plan_position
Recv: current_position=(-29.50, 0.00, 4.00) : > AFTER set_axis_is_at_home
Recv: <<< homeaxis(0)
Recv: current_position=(-29.50, 0.00, 4.00) : > homeX
Recv: > Z_SAFE_HOMING >>>
Recv: current_position=(-29.50, 0.00, 4.00) : sync_plan_position
Recv: current_position=(-29.50, 0.00, 4.00) : > Z_SAFE_HOMING > home_all_axis
Recv: destination=(0.00, 0.00, 4.00) : > Z_SAFE_HOMING > home_all_axis
Recv: >>> homeaxis(2)
Recv: current_position=(0.00, 0.00, 0.00) : sync_plan_position
Recv: echo:busy: processing
Recv: current_position=(0.00, 0.00, 0.00) : sync_plan_position
Recv: echo:busy: processing
Recv: echo:busy: processing
Recv: current_position=(0.00, 0.00, 0.00) : > TRIGGER ENDSTOP
Recv: >>> set_axis_is_at_home(2)
Recv: For 90 axis:
Recv:  home_offset = 0.00
Recv:  position_shift = 0.00
Recv:  sw_endstop_min = 0.00
Recv:  sw_endstop_max = 300.00
Recv: > home_offset[90] = 0.00
Recv: current_position=(0.00, 0.00, 0.00) :
Recv: <<< set_axis_is_at_home(2)
Recv: current_position=(0.00, 0.00, 0.00) : sync_plan_position
Recv: current_position=(0.00, 0.00, 0.00) : > AFTER set_axis_is_at_home
Recv: <<< homeaxis(2)
Recv: <<< Z_SAFE_HOMING
Recv: current_position=(0.00, 0.00, 0.00) : > (home_all_axis || homeZ) > final
Recv: current_position=(0.00, 0.00, 0.00) : sync_plan_position
Recv: > endstops.not_homing()
Recv: current_position=(0.00, 0.00, 4.00) : sync_plan_position
Recv: current_position=(0.00, 0.00, 0.00) : clean_up_after_endstop_or_probe_move
Recv: <<< gcode_G28
Recv: X:0.00 Y:0.00 Z:0.00 E:0.00 Count X: 0 Y:0 Z:6400
Recv: ok
Send: N3 M218 T1 X29.5 Y-18.1*68
Recv: echo:N3 M218 T1 X29.5 Y-18.1*68
Recv: echo:Hotend offsets: 0.00,0.00 29.50,-18.10
Recv: ok
Send: N4 G1 Z3 F3000*0
Recv: echo:N4 G1 Z3 F3000*0
Recv: ok
Send: N5 G1 X150 Y100*41
Recv: echo:N5 G1 X150 Y100*41
Recv: ok
Send: N6 T1*61
Recv: echo:N6 T1*61
Recv: >>> gcode_T
Recv: current_position=(150.00, 100.00, 3.00) : BEFORE
Recv: Z before MBL: 3.00 after: 3.00
Recv: Offset Tool XY by { 29.50, 29.50 }
Recv: For 88 axis:
Recv:  home_offset = 0.00
Recv:  position_shift = 29.50
Recv:  sw_endstop_min = 0.00
Recv:  sw_endstop_max = 329.50
Recv: For 89 axis:
Recv:  home_offset = 0.00
Recv:  position_shift = -18.10
Recv:  sw_endstop_min = -18.10
Recv:  sw_endstop_max = 221.90
Recv: current_position=(179.50, 81.90, 3.00) : Sync After Toolchange
Recv: current_position=(179.50, 81.90, 3.00) : sync_plan_position
Recv: destination=(150.00, 100.00, 3.00) : Move back
Recv: echo:busy: processing
Recv: echo:busy: processing
Recv: current_position=(150.00, 100.00, 3.00) : AFTER
Recv: <<< gcode_T
Recv: echo:Active Extruder: 1
Recv: ok
Send: N7 M105*32
Recv: echo:N7 M105*32
[...]
Send: N8 T0*50
Recv: echo:N8 T0*50
Recv: >>> gcode_T
Recv: current_position=(150.00, 100.00, 3.00) : BEFORE
Recv: Z before MBL: 3.00 after: 3.00
Recv: Offset Tool XY by { -29.50, -29.50 }
Recv: For 88 axis:
Recv:  home_offset = 0.00
Recv:  position_shift = 0.00
Recv:  sw_endstop_min = -29.50
Recv:  sw_endstop_max = 300.00
Recv: For 89 axis:
Recv:  home_offset = 0.00
Recv:  position_shift = 0.00
Recv:  sw_endstop_min = 0.00
Recv:  sw_endstop_max = 240.00
Recv: current_position=(120.50, 118.10, 3.00) : Sync After Toolchange
Recv: current_position=(120.50, 118.10, 3.00) : sync_plan_position
Recv: destination=(150.00, 100.00, 3.00) : Move back
Recv: current_position=(150.00, 100.00, 3.00) : AFTER
Recv: <<< gcode_T
Recv: echo:Active Extruder: 0
Recv: ok
Send: N9 T1 S1*112
Recv: echo:N9 T1 S1*112
Recv: >>> gcode_T
Recv: current_position=(150.00, 100.00, 3.00) : BEFORE
Recv: Z before MBL: 3.00 after: 3.00
Recv: Offset Tool XY by { 29.50, 29.50 }
Recv: For 88 axis:
Recv:  home_offset = 0.00
Recv:  position_shift = 29.50
Recv:  sw_endstop_min = 0.00
Recv:  sw_endstop_max = 329.50
Recv: For 89 axis:
Recv:  home_offset = 0.00
Recv:  position_shift = -18.10
Recv:  sw_endstop_min = -18.10
Recv:  sw_endstop_max = 221.90
Recv: current_position=(179.50, 81.90, 3.00) : Sync After Toolchange
Recv: current_position=(179.50, 81.90, 3.00) : sync_plan_position
Recv: current_position=(179.50, 81.90, 3.00) : AFTER
Recv: <<< gcode_T
Recv: echo:Active Extruder: 1
Recv: ok
Send: N10 T0*11
Recv: echo:N10 T0*11
Recv: >>> gcode_T
Recv: current_position=(179.50, 81.90, 3.00) : BEFORE
Recv: Z before MBL: 3.00 after: 3.00
Recv: Offset Tool XY by { -29.50, -29.50 }
Recv: For 88 axis:
Recv:  home_offset = 0.00
Recv:  position_shift = 0.00
Recv:  sw_endstop_min = -29.50
Recv:  sw_endstop_max = 300.00
Recv: For 89 axis:
Recv:  home_offset = 0.00
Recv:  position_shift = 0.00
Recv:  sw_endstop_min = 0.00
Recv:  sw_endstop_max = 240.00
Recv: current_position=(150.00, 100.00, 3.00) : Sync After Toolchange
Recv: current_position=(150.00, 100.00, 3.00) : sync_plan_position
Recv: destination=(179.50, 81.90, 3.00) : Move back
Recv: current_position=(179.50, 81.90, 3.00) : AFTER
Recv: <<< gcode_T
Recv: echo:Active Extruder: 0
Recv: ok
Send: N11 T1*11
Recv: echo:N11 T1*11
Recv: >>> gcode_T
Recv: current_position=(179.50, 81.90, 3.00) : BEFORE
Recv: Z before MBL: 3.00 after: 3.00
Recv: Offset Tool XY by { 29.50, 29.50 }
Recv: For 88 axis:
Recv:  home_offset = 0.00
Recv:  position_shift = 29.50
Recv:  sw_endstop_min = 0.00
Recv:  sw_endstop_max = 329.50
Recv: For 89 axis:
Recv:  home_offset = 0.00
Recv:  position_shift = -18.10
Recv:  sw_endstop_min = -18.10
Recv:  sw_endstop_max = 221.90
Recv: current_position=(209.00, 63.80, 3.00) : Sync After Toolchange
Recv: current_position=(209.00, 63.80, 3.00) : sync_plan_position
Recv: destination=(179.50, 81.90, 3.00) : Move back
Recv: current_position=(179.50, 81.90, 3.00) : AFTER
Recv: <<< gcode_T
Recv: echo:Active Extruder: 1
Recv: ok
Changing monitoring state from 'Printing' to 'Operational'

[thinkyhead]

Your pointing out that MBL was involved led me to a happenstance discovery. The function that handles splitting up lines when mesh leveling is enabled was failing to account for the position_shift introduced recently to deal with the use of G92 and other functions that forcibly set the current_position. The gcode_T function for changing tools was doing all the right things, but MBL wasn't. So what happens is that after a tool-change the nozzle offset ends up being applied only to longer moves that cross mesh boundaries. If you do short moves, you might not see the effect. Not until you cross a grid line.

I think I might have fixed the issue with #4310. Please test https://github.com/thinkyhead/Marlin/tree/rc_mbl_position_shift when you have a chance. This should also have the updated logging in it.

[thinkyhead]

@Alex9779 Ok, should be in better shape. Watching the compiler…

[Alex9779]

Waiting for a working version to test...

[thinkyhead]

Sorry, had to run before Travis caught my bugs.
It's patched now, compiles, and should be testable.

[Alex9779]

I had not time to test over the weekend, now everything is merged into RCBugFix.
Going to test asap...

[Alex9779]

Ok I did some tests and some results are still strange but I think I know why.
The problem is that my files end with T1 selected so a new G28homes with T1 selected. This seems to produce issues.
So the question is, is it ok and intended that homing is dependent on which tool is selected?
I can remember this was always the case because some time ago I used this but is that correct?
Depending on what a user has in his end script he could finish a print with T1selected and then a new print starts with a G28but homing with the wrong hotend.
I tried it also with homing from the LCD, same effect. If T1was selected T1is still selected after homing but homing is done for T0because after homing T0is at 0,0.
After that the coordinate systems are all weird...

IMHO homing should be done with T0, if an other tool is selected this should be reset...

[Alex9779]

A maybe different thing I found is that travel moves across the centre Y line (Y100) and X150 line stop at that line... This was gone with RC6, think it was before too and is now back... Is that connected to MBL and the mesh boundaries?

[Alex9779]

Shall I open a new issue with the problems regarding homing?
But this one should still be open because I really like to have an opinion why the file with the inserted pauses does behave different...

[thinkyhead]

travel moves across the centre Y line

I did muck around with the mesh bed leveling "split on boundaries" code, but I took care to try to preserve the existing behavior. If the current RCBugFix code doesn't have the issue fixed, then we can try reverting these adjustments and see if it fixes the issue.

[Alex9779]

Did a single nozzle print today with RCBugFix of yesterday. Worked without issues.
Maybe I try dual tomorrow, the tests switching tools were successful so I'll give it a shot soon...

[thinkyhead]

Did a single nozzle print today

Mesh bed leveling enabled? 🎩

[Alex9779]

For sure!
Didn't have a look at the travel issue so...

[thinkyhead]

Crossing my fingers that all the movement and coordinate oddities will be worked out very shortly. I know I say this a lot, but I think we _might_ be able to do the RC7 release _this very weekend_.

[jbrazio]

@Alex9779 was your print successful, can we close this issue ?

[Alex9779]

Didn't try yet, sorry... I am having some motion system issues, I think a bearing is damaged... Will take a few days to replace...

[Alex9779]

Currently no time and I don't feel like testing... Think it works but I am going back to RC6 for some time, I have to print...

[thinkyhead]

😿