[SBC mode] Random errors in macros with 3.5.2

crpalmer

My PrusaSlicer start gcode is:

M83          ; Relative Extruder mode
M98 P"/sys/prepare-to-print.g" H{is_extruder_used[0] ? first_layer_temperature[0] : 0} B{is_extruder_used[0] ? first_layer_bed_temperature[0] : 0}
T{initial_tool}

and the macro prepare-to-print.g is:

if exists(param.H) == false or exists(param.B) == false
  echo "Missing required parameter (H and B)"
  M99

var bed_temp = param.B
var probing_temp = min(var.bed_temp, 60)

;echo "Hotend temperatures: ", param.H
;echo "Probing temperature: ", var.probing_temp
;echo "Bed temperature: ", var.bed_temp

M220 S100     ; clear any speed changes
M290 R0 S0    ; clear any baby stepping
M106 S0       ; disable fans

M568 A1 P0 R{param.H} S{param.H}
M190 R{var.probing_temp+10}    ; Wait to get up (or down!) to the right temperature

M561
M98 P"/sys/homexy-if-needed.g"
M401
G28 Z
G32
G32
G28 Z
G29 S1

M98 P"/sys/retractprobe-forced.g"

if var.probing_temp < var.bed_temp
   M140 S{var.bed_temp+10}

M116

Since upgrading to 3.5.2 on one printer and a new deployment of 3.5.2 on another printer, I'm sporatically seeing errors on both printers when this macro is invoked while starting a print. Both printers are running Duet 3 Mini 5+ control boards.

The most common error I get is:

Error: in file prepare-to-print.g line 31: unknown variable 'probing_temp'

where probing_temp is used extensively thoughout the macro and line 31 (I assume really line 30 but reported as 31) is always executed and therefore if it was an error in the macro then it should always report the error. I just recently also saw this warning:

Warning: Macro file has been started on channel File but none was requested

Possibly related to these errors I am getting situations where clicking Pause Print in the web interface hangs and does nothing (a page reload shows the print still running) and when I received the warning, my filament sensor didn't trigger which makes we think that the warning / error is causing RRF to think that the print is not running even though the print is running.

Note that on the machine I upgraded to 3.5.2, the prepare-to-print macro has been running for a long time without any changes without ever reporting an error until version 3.5.2.

Am I doing something incorrect in how I use macros inside of macros? Is something that I'm doing venturing into undefined behaviour? Note that the macro prepare-to-print will invoke the macro homexy-if-needed which will invoke the macro homexy. Prepare-to-print also invokes the macro retractprobe-forced which will invoke the macro retract-probe.

(edit to add that I looked at the 3.5.3-rc.1 changelog and git diff 3.5.2 3.5.3-rc.1 and nothing appears to be related to me)

dc42

@crpalmer are you running in standalone or SBC mode?

crpalmer

@dc42 sbc for both machines.

chrishamm

@crpalmer I ran your macro from a print file 10 times in a row with v3.5.2 and it completed every time as expected. Can you please share a print file and files /sys/homexy-if-needed.g and /sys/retractprobe-forced.g as well?

crpalmer

@chrishamm / @dc42 The two machines I am running 3.5.2 configs are:

https://github.com/crpalmer/3d-printing/tree/master/veho
https://github.com/crpalmer/3d-printing/tree/master/ender5

For whatever reason, it happens much more frequently on "ender5" (don't be confused by the name, all that is left of the original ender-5 is the frame). It doesn't happen all the time and I'm starting to wonder if it happens more frequently when it has been running for awhile (perhaps some kind of subtle memory corruption?). It did happen again yesterday:

9/10/2024, 6:27:28 AM	Error: in file prepare-to-print.g line 32: unknown variable 'probing_temp'
9/10/2024, 6:27:28 AM	Error: in file prepare-to-print.g line 34: unknown variable 'probing_temp'
9/10/2024, 6:27:12 AM	Warning: Macro file has been started on channel File but none was requested

and like before after the print finished (including M2 in the end.gcode) the machine thought that the print was still running and it was impossible to cancel the print. I end up just doing an Emergency Stop when this happens.

chrishamm

@crpalmer Can you please upload a demo G-code job as well? Then I could prepare a bench setup and attempt to reproduce it.

crpalmer

@chrishamm Here's a gcode file that I was running at around the time I last saw the error. I can't be sure it's the one I was running but the exact object probably doesn't matter given that the error happens before the print itself starts.

YACS - PLA - 0.6mm.gcode

crpalmer

@chrishamm I was just browsing the "random restarts on mini" thread and wondered if my problems could be related. However, both of my machines are running Duet 3 Mini 5+ (Ethernet not WiFi).

Both machines have CAN boards attached. The one that encounters this error more frequently is using a EXP3HC and the other a TOOL1LC.

chrishamm

@crpalmer I think I've got a bug fix ready which will be part of v3.5.3.

crpalmer

@chrishamm Thank you but unfortunately I think that's not the (entire?) fix. Was it this commit that you were hoping fixed the problem?

I find that the error occurs more frequently on one of my machines so I upgraded it to 3.5.3 to test. I just had the error occur when starting a print. FYI:

I have 3 machines that were running 3.5.2 and I'm seeing errors with very different frequencies on these machines. The one I upgraded to 3.5.3 has the error occur 10% of the time. That machine has a EXP3HC board that runs a Y motor an U motor and an extruder. The second machine runs a toolboard and I see the error here less frequently (I don't have a percentage estimate but definitely less frequently). The last machine has yet to report an error and it doesn't use any CAN expansion boards.

I don't see anything interesting in the differences in the SBC. All three machines are running Raspberry PI 4 boards (the two that have had the errors are Rev 1.5 and the one that hasn't is 1.4). The most machine that most commonly has errors and the one that has never had an error are running Raspbian 10 and the one other is Raspbian 12.

9/21/2024, 4:12:58 PM	Error: in file prepare-to-print.g line 32: unknown variable 'probing_temp'
9/21/2024, 4:12:58 PM	Error: in file prepare-to-print.g line 34: unknown variable 'probing_temp'
9/21/2024, 4:12:43 PM	Warning: Macro file has been started on channel File but none was requested

chrishamm

@crpalmer That was only one of the commits for the full fix, there was at least one more in DSF, too. So far I've been unable to reproduce that issue again since I made those changes. If you can come up with a simpler and reliable way to reproduce this problem, I can have a look at it again. Unfortunately, I can't reproduce your full setup here and AFAIK we haven't got similar reports from other customers either.

crpalmer

@chrishamm This problem is most definitely not fixed. Yesterday I had the error occur twice. FWIW, random and explained behaviour by the software used to control industrial machines is something that I think should still be investigated -- even if it's difficult.

Whenever I get the random error message, I click "Emergency Stop" in the interface and restart the job. I do so just to be on the safe side and since I know I'll have to click emergency stop eventually anyway because the print never terminates, and the interface fails to let me cancel it.

Yesterday, the error occurred in 2 prints jobs in a row (with an emergency stop in between). Memory corruption, while still a possibility, sounds very unlikely.

I did try to find a reproducible example by having macros running macros running macros, but I was not able to reproduce anything that doesn't involve actually running print jobs. One difference in my tests and the actual print jobs is that some macro invocations are generated by M401 / M402 gcodes. I see in the RRF code that when system macros are run, it takes not of that (runningSystemMacro). Is there any difference there that could be part of the problem?

chrishamm

@crpalmer I suspect something closes one of your macro files prematurely - that might explain those error messages. I need to have a look at this again provided I can reproduce it somehow.

Meanwhile you could enable debug logging by changing the log level in /opt/dsf/conf/config.json from info to debug and share the corresponding journal when it happens again. If it is what I think it is, it might be possible to reduce the frequency of this issue by reducing the number of nested macros.

I've also logged this issue here: https://github.com/Duet3D/DuetSoftwareFramework/issues/205 Note that I'm not available next week but I'm happy to have a look at this again when I'm back.

chrishamm created this issue in Duet3D/DuetSoftwareFramework

closed [Bug]: Macro files on certain systems remain open leading to stack corruption #205

crpalmer

@chrishamm Thanks.

I changed the log level to debug and reboot the PI to be sure everything was restarted. I see debug messages from the DuetControlServer and DuetWebServer in /var/log/syslog. If the error happens again (I fear the debug logging is going to change the timing that causes this to happen) should I attach the output of running "grep -i duet /var/log/syslog" to the github bug report?

(Let me know next week when you're back)

crpalmer

@chrishamm I have a syslog that has the same gcode run twice in a row, once with no errors and then once with the errors. Hopefully the syslog is the "journal" that you were referring to. Either way, it's good to know that the error still occurs with the debug logging enabled.