3.5.0b1+ don't wait for commands to finish before moving on

gloomyandy

@Exerqtor If it is easy for you to do could you disable the Daemon.g stuff and run the print again.I suspect that it has nothing to do with the problem, but it cuts down the complexity for trying to reproduce things.

Exerqtor

@gloomyandy
I can disable the loop inside of it by setting the global to false?

It's nothing mission critical going on in it anyways, so I can just remove daemon.g entierly just for the sake of experimenting.

I'm not at home now though so I can't test it STAT, but I'll do it once I get home.

Exerqtor

@gloomyandy said in 3.5.0b1+ don't wait for commands to finish before moving on:

@Exerqtor If it is easy for you to do could you disable the Daemon.g stuff and run the print again.I suspect that it has nothing to do with the problem, but it cuts down the complexity for trying to reproduce things.

This is what spews out with global.RunDaemon=false / daemon.g disabled:

7.1.2023, 15:26:49	M292 S10
Error: M292: no active message box
7.1.2023, 15:26:46	print_tram.g start
print_tram.g end
start.g end
7.1.2023, 15:26:27	print_tram.g start
print_tram.g end
start.g end
print_start.g start
Error: No P or R parameter
print_purge.g start
Error: in file macro line 41 column 52: meta command: unknown variable 'x_origin'
Cancelled printing file 0:/gcodes/Shape-Box_0.2mm_ABS_0.4n_5m.gcode, print time was 0h 0m
7.1.2023, 15:26:26	M32 "0:/gcodes/Shape-Box_0.2mm_ABS_0.4n_5m.gcode"
File 0:/gcodes/Shape-Box_0.2mm_ABS_0.4n_5m.gcode selected for printing
 start.g start
 start.g start

And with daemon.g removed from 0:/sys/:

7.1.2023, 15:31:25	M292 S13
Error: M292: no active message box
7.1.2023, 15:31:21	print_tram.g start
print_tram.g end
start.g end
7.1.2023, 15:31:02	print_tram.g start
print_tram.g end
start.g end
print_start.g start
Error: No P or R parameter
print_purge.g start
Error: in file macro line 41 column 52: meta command: unknown variable 'x_origin'
Cancelled printing file 0:/gcodes/Shape-Box_0.2mm_ABS_0.4n_5m.gcode, print time was 0h 0m
7.1.2023, 15:31:01	M32 "0:/gcodes/Shape-Box_0.2mm_ABS_0.4n_5m.gcode"
File 0:/gcodes/Shape-Box_0.2mm_ABS_0.4n_5m.gcode selected for printing
 start.g start
 start.g start

The "Error: in file macro line 41 column 52: meta command: unknown variable 'x_origin'" stems from print_purge.g, most likely because the global variables that gets parsed with the sliced print data for the max/min print coordinates haven't really been run yet since there obviously part of the start gcode from the slicer. But when everything has stopped moving (homing moves stoped) and i check out the object model browser the coordinates have been parsed correctly.

So something is getting ahead of itself for some reason, almost like DWC reads thru the whole damn thing before RRF has actually had a chance to execute the commands "irl". But if it was a DWC problem the issue shouldn't manifest if i start a print from PD? Or is DWC handeling stuff in the background no matter whats being done?

dc42

@Exerqtor what I suspect is happening is that some commands - in particular, echo commands - are being executed by both file readers instead of by just one. It's normal for the second file reader to get ahead because in a "normal" print, the second motion system isn't used so the second file reader has nothing to do.

Apart from echo commands, which other commands are getting executed earlier than you expect?

Exerqtor

@dc42
Ok, what order things get displayed really don't bother me as long as it works irl.

Uhm where should I start, nothing get's executed as I expect it to at this point 😂.

I "want/think" this should happen:

1 start.g gets called because i initialize a print.
2 start.g executes the codes in order from "line 1" downwards, with the first "visual" thing being that the the active bed temp changes to 65°C and starts heating up.
3 Then continuing downwards, changing the toolhead lights, promting the Print Started. Preheating and Homing message for 10seconds (while in the background continuing to execute the code) until it gets to M190 S65 where it waits for the bed to reach 65°C.
4 When the bed has reached 65°C it homes all the axis BEFORE, continuing to execute print_tram.g.
5 print_tram.g does it's thing, and that's the end of start.g, so now it moves on the execute the actual sliced/job file.
6 Runs the code in the sliced/job file from "line 1" downwards:

M107
M190 S110 ; set bed temperature and wait for it to be reached
G10 S255 P0 ; set temperature
;TYPE:Custom
; Start G-code: START
; Inform of first layer height
set global.first_layer_height = 0.2
; Define print area
set global.paMinX = 162.5
set global.paMaxX = 187.5
set global.paMinY = 162.5
set global.paMaxY = 187.5
; Set temps & the initial extruder
set global.bed_temp = 110
set global.hotend_temp = 255
set global.initial_extruder = 0
M83                                                                            ; use relative distances for extrusion

7 After executing M83 it moves on to calling print_start.g.
8 print_start.g goes from "line 1" downwards, with first visual change being active bed temp changing to 110°C and it's starts heating up.
9 The toolhead lights changes back to "heating-colors" and then M116 H0 S5 get's executed, and everythings waits for the bed to reach 105°C before continuing.
10 Bed temp has reached 105°C and print_probe.g gets called (for the sake of not writing a whole novel that does it things and we return to the next line of print_start.g).
11 Changes bed compensation taper in the background, then we see T0 active and standby temps change to 255°C and starts heating up.
12 The toolhead lights changes back to "heating-colors" again, and it executes M116 H1, so we wait for T0 to reach 255°C.
13 T0 reaches 255°C, the chamber lights turn on, bed drops a tiny bit and print_purge.g gets called.
14 print_purge.g does it's thing and lays down the purge lines and the toolhead lights changes to "printing-colors".
15 global.RunDaemon changes to false ("turning off" daemon.g ) finishing of print_start.g.
16 We return to the sliced/job file and so on and so forth....

dc42

@Exerqtor thanks. What actually happens too soon, other than spurious output from echo commands? Do you see any motion before the bed has finished heating to 65C, or any other motion that happens too early ?

Exerqtor

EDIT
Cleaned up the post.

@dc42
It doesn't wait for the bed to reach 65°C even! 😂😂
What happens is:

1) start.g gets called because i initialize a print.
2 Active bed temp changes to 65°C and Print Started. Preheating and Homing message gets displayed.
3 Immediately while the message is displayed the active and standby hotend temps to 80°C and starts to home the axis.
4 The same millisecond the axis start to home it displays the "Response too long, see Console Close" prompt.
5 It turns ONLY the hotend standby temp too 150°C while the homing sequence finish up.
6 I get the M291 S1 R"Bed tramming" P"Bed allready trammed" T4 from print_tram.g DESPITE global.bed_trammed being false when i started the print.
7 Then nothing more happens, both bed & hotend heaters gets turned off all movement stops, like the machine is in "limbo" (if I look at the DWC temp chart it's no visible changes in temps).
8 Switching over to DWC console this is what I see:

7.1.2023, 18:42:16	print_tram.g start
print_tram.g end
start.g end
7.1.2023, 18:41:57	print_tram.g start
print_tram.g end
start.g end
Start G-code: START
print_start.g start
Error: No P or R parameter
print_purge.g start
Error: in file macro line 41 column 52: meta command: unknown variable 'x_origin'
Cancelled printing file 0:/gcodes/Shape-Box_0.2mm_ABS_0.4n_5m.gcode, print time was 0h 0m
7.1.2023, 18:41:56	M32 "0:/gcodes/Shape-Box_0.2mm_ABS_0.4n_5m.gcode"
File 0:/gcodes/Shape-Box_0.2mm_ABS_0.4n_5m.gcode selected for printing
 start.g start
 start.g start

This all happens so fast that either the bed OR hotend (E3D Revo 24v, so it's quite responsive) have any visible change in the temp chart.

The 80°C hotend temp part is something I'm going to remove, but it's a good thing that I forgot to remove that step since it highlights the fact that only the standby temp gets upped to 150°C when G10 P0 S150 R150 is executed.

Exerqtor

I must also add that:

When I check the object model browser after what happens above. All the globals have been parsed with the values from the sliced/job file like intended. AND global.bed_trammed has changed from false to true despite the no tramming has been performed.

For referance this is how bed.g looks, and it works just like intended when i run it:

; bed.g  v2.1
; Called as response to G32
; Used to tram the bed

;---/
; -/--/--/--/--/--/--/--/--/--/--/--/--/--/--/--/--
; THIS MACRO ONLY WORKS WITH RRF 3.5.0b1 AND LATER!!
;--/--/--/--/--/--/--/--/--/--/--/--/--/--/--/--/--
;-/

; ====================---------------------------------------------------------
; Question code
; ====================

; Ask to make sure you want to tram the bed or not
if !exists(global.bed_trammed)
  echo "global.bed_trammed missing, aborting!
  abort
elif global.bed_trammed
  M291 S3 R"Bed tramming" P"The bed is allready trammed, want to tram it again?"
else
  M291 S3 R"Bed tramming" P"Are you sure you want to tram the bed?"

; ====================---------------------------------------------------------
; Prep phase
; ====================

; LED status
if exists(global.sb_leds)
  set global.sb_leds = "homing"

; Report whats going on
M291 R"Bed tramming" P"Please wait..." T0                                      ; Tramming bed message

M561                                                                           ; Clear any bed transform
M290 R0 S0                                                                     ; Reset baby stepping
M84 E0                                                                         ; Disable extruder stepper

; Lower Z currents
if fileexists("/sys/lib/current/z_current_low.g")
  M98 P"/sys/lib/current/z_current_low.g"                                      ; Set low Z currents
else
  M913 Z60                                                                     ; Set Z motors to 60% of their max current

; ====================---------------------------------------------------------
; Lower Z axis
; ====================

; Lower Z relative to current position if needed
if !move.axes[2].homed                                                         ; If Z ain't homed
  G91                                                                          ; Relative positioning
  G1 Z{global.Nozzle_CL} F9000 H1                                              ; Lower Z(bed) relative to current position	
  G90                                                                          ; Absolute positioning

elif move.axes[2].userPosition < {global.Nozzle_CL}                            ; If Z is homed and less than global.Nozzle_CL
  G1 Z{global.Nozzle_CL} F9000                                                 ; Move to Z global.Nozzle_CL

; ====================---------------------------------------------------------
; Homing check
; ====================

; Make sure all axes are homed, and home Z again anyways
if !move.axes[0].homed || !move.axes[1].homed                                  ; If X & Y axes aren't homed
  ; Home X & Y axis
  M98 P"/sys/homex.g" Z A                                                      ; Home X axis, pass param.Z since we allready lowered Z & A to indicate this is part of a homing sequence
  M98 P"/sys/homey.g" Z C                                                      ; Home Y axis, pass param.Z since we allready lowered Z & C since XY currents/speeds are also ok

; ====================
; Home Z axis
; ====================

M98 P"/sys/homez.g" Z A                                                        ; Home Z axis, pass param.Z since we allready lowered Z & A to indicate this is part of a homing sequence

; ====================---------------------------------------------------------
; Tramming code
; ====================

; LED status
if exists(global.sb_leds)
  set global.sb_leds = "tramming"

; Coarse tramming pass
M558 K0 H10 F300 A1                                                            ; Increase the depth range, gets the bed mostly trammed immediately
M98 P"/sys/bed_probe_points.g"                                                 ; Probe the bed

; Fine tramming pass
while true
  ; Probe near lead screws -
  M558 K0 H2 F300:180 A3                                                       ; Reduce depth range, probe slower for better repeatability 
  M98 P"/sys/bed_probe_points.g"                                               ; Probe the bed

  ; Check results - exit loop if results are good
  if move.calibration.initial.deviation < 0.02                                 ; If probing result is less than 0.02mm
    set global.bed_trammed = true                                              ; Set global state
    break                                                                      ; Stop probing

  ; Check pass limit - abort if pass limit reached
  if iterations = 5                                                            ; If probed more than 5 times
    M291 P"Bed tramming aborted!" R"Pass Limit Reached!"                       ; Abort probing, something wrong
    set global.bed_trammed = false                                             ; Set global state
    abort "Bed tramming aborted! - Pass Limit Reached!"                        ; Abort probing, something wrong

; ====================---------------------------------------------------------
; Finish up
; ====================

; Uncomment the following lines to lower Z(bed) after probing
G90                                                                            ; Absolute positioning
G1 Z{global.Nozzle_CL} F2400                                                   ; Move to Z global.Nozzle_CL


; Home Z one last time now that the bed is trammed
M98 P"/sys/lib/goto/bed_center.g"                                              ; Move to bed center
G30 K0 Z-99999                                                                 ; Probe the center of the bed
M400                                                                           ; Wait for moves to finish


; Full currents
if fileexists("/sys/lib/current/xy_current_high.g")
  M98 P"/sys/lib/current/xy_current_high.g"                                    ; Set high XY currents
else
  M913 X100 Y100                                                               ; Set X Y motors to var.100% of their max current
if fileexists("/sys/lib/current/z_current_high.g")
  M98 P"/sys/lib/current/z_current_high.g"                                     ; Set high Z currents
else
  M913 Z100                                                                    ; Set Z motors to var.100% of their max current

; Uncomment the following lines to lower Z(bed) after probing
G90                                                                            ; Absolute positioning
G1 Z5 F2400                                                                    ; Move to Z 10

M291 R"Bed tramming" P"Done" T5                                                ; Bed tramming done message

; If using Voron TAP, report that probing is completed
if exists(global.TAPPING)
  set global.TAPPING = false
  M402 P0                                                                      ; Return the hotend to the temperature it had before probing

; LED status
if exists(global.sb_leds)
  set global.sb_leds = "ready"

As you can see it's more or less functionally the same as print_tram.g, except some question and homing steps in bed.g. But the check to see if the bed is allready trammed works like intended and is carried out in the same manner in print_tram.g.

Exerqtor

Anyone else with 3.5.0b1+ thats willing to try recreating this issue?

Shouldn't be anything super exotic that needs to be changed to try this out on other machines 😅

I've looked to the code so many times now I'm sure I wouldn't find a fault if it jumped at me lol

dc42

@Exerqtor what's happening is that there are now two GCode File channels used to process print files, one for each motion system. Normally, only the first one of them executes commands. The other typically reaches end of file or the M0 command if there is one, and waits for the first to catch up.

What I hadn't allowed for is that both File channels will execute GCode meta commands such as echo, and set. This is why you are seeing some echo commands being executed ahead of time, and why global.bed_trammed is being set to true.

I propose to change the behaviour as follows, which I hope will resolve this for you:

Only execute echo, global and set global commands commands from the File channel that is currently selected.
~~When either channel reaches a command that involves waiting for temperatures to be reached, add a sync point there so that both File channels wait~~. no, that would not be appropriate e.g. when changing tools and waiting for a hot end to heat.

Exerqtor

@dc42
Uuuhm oook, how do i know what file channel is in use? Sounds easier/less issue proned (for me) to just don't use start.gand scrap it to be honest.

dc42

@Exerqtor my aim is that you won't need to modify start.g; but if you do, the modification needed should be simple.

Exerqtor

@dc42
Ah I missunderstood what you meant! Do what you feel is the best way of solving/moving around it, I haven't got a good enough understanding of how it all ties together to weigh in on it

T3P3Tony

@Exerqtor can you confirm if the issue with start.g other than the one with M190 you reported here: https://forum.duet3d.com/post/308884 are resolved?

Exerqtor

@T3P3Tony
I've ditched using start.g totally because it made more problems for me than it solved.

If my recollection serves me right though, i'm pretty sure the changes David did in b2 solved this perticular issue.

I'll remove this thread as a question so it won't remain as "unsolved" at least.