[bug] Error: in job file (channel File2) variable already exists

timschneider

The following minimal working example will oscillating cause the following error:

Error: in job file (channel File2) line 5: variable 'global.TestVar1' already exists

content of 0:/gcodes/job-variable.gcode

if exists(global.TestVar1)
  echo global.TestVar1
  set global.TestVar1 = true
else
  global TestVar1 = true


echo global.TestVar1

G4 S1

M112

How to reproduce:

Start the print job with M32 "0:/gcodes/job-variable.gcode"
wait for the emergency stop
press reset button
Start the print job again M32 "0:/gcodes/job-variable.gcode"
wait for the emergency stop
press reset button
see the error in the console, if not, repeat the job file.

Further Informations:

Duet3HC in SBC setup

M115
FIRMWARE_NAME: RepRapFirmware for Duet 3 MB6HC FIRMWARE_VERSION: 3.5.0-rc.2 ELECTRONICS: Duet 3 MB6HC v1.02 or later FIRMWARE_DATE: 2023-12-14 10:32:22

M122
=== Diagnostics ===
RepRapFirmware for Duet 3 MB6HC version 3.5.0-rc.2 (2023-12-14 10:32:22) running on Duet 3 MB6HC v1.02 or later (SBC mode)
Board ID: 08DJM-9P63L-DJ3T8-6JKD4-3SJ6K-9A77A
Used output buffers: 1 of 40 (17 max)
=== RTOS ===
Static ram: 154844
Dynamic ram: 87568 of which 4776 recycled
Never used RAM 95948, free system stack 204 words
Tasks: SBC(2,ready,0.9%,404) HEAT(3,nWait,0.0%,326) Move(4,nWait,0.0%,339) CanReceiv(6,nWait,0.0%,942) CanSender(5,nWait,0.0%,334) CanClock(7,delaying,0.0%,343) TMC(4,nWait,7.7%,61) MAIN(2,running,91.0%,103) IDLE(0,ready,0.4%,30), total 100.0%
Owned mutexes: HTTP(MAIN)
=== Platform ===
Last reset 00:03:01 ago, cause: software
Last software reset at 2024-01-16 09:19, reason: User, Platform spinning, available RAM 95948, slot 2
Software reset code 0x6000 HFSR 0x00000000 CFSR 0x00000000 ICSR 0x00400000 BFAR 0x00000000 SP 0x00000000 Task SBC Freestk 0 n/a
Error status: 0x00
MCU temperature: min 32.7, current 32.8, max 34.5
Supply voltage: min 24.0, current 24.1, max 24.2, under voltage events: 0, over voltage events: 0, power good: yes
12V rail voltage: min 11.8, current 12.3, max 12.8, under voltage events: 0
Heap OK, handles allocated/used 99/4, heap memory allocated/used/recyclable 2048/104/0, gc cycles 0
Events: 0 queued, 0 completed
Driver 0: standstill, SG min n/a, mspos 264, reads 27143, writes 22 timeouts 0
Driver 1: standstill, SG min n/a, mspos 424, reads 27143, writes 22 timeouts 0
Driver 2: standstill, SG min n/a, mspos 168, reads 27144, writes 21 timeouts 0
Driver 3: standstill, SG min n/a, mspos 1016, reads 27144, writes 21 timeouts 0
Driver 4: standstill, SG min n/a, mspos 264, reads 27144, writes 21 timeouts 0
Driver 5: standstill, SG min n/a, mspos 84, reads 27146, writes 19 timeouts 0
Date/time: 2024-01-16 09:22:35
Slowest loop: 1.99ms; fastest: 0.07ms
=== Storage ===
Free file entries: 20
SD card 0 not detected, interface speed: 37.5MBytes/sec
SD card longest read time 0.0ms, write time 0.0ms, max retries 0
=== Move ===
DMs created 125, segments created 0, maxWait 0ms, bed compensation in use: none, height map offset 0.000, max steps late 0, ebfmin 0.00, ebfmax 0.00
no step interrupt scheduled
Moves shaped first try 0, on retry 0, too short 0, wrong shape 0, maybepossible 0
=== DDARing 0 ===
Scheduled moves 0, completed 0, hiccups 0, stepErrors 0, LaErrors 0, Underruns [0, 0, 0], CDDA state -1
=== DDARing 1 ===
Scheduled moves 0, completed 0, hiccups 0, stepErrors 0, LaErrors 0, Underruns [0, 0, 0], CDDA state -1
=== Heat ===
Bed heaters 0 -1 -1 -1 -1 -1 -1 -1 -1 -1 -1 -1, chamber heaters -1 -1 -1 -1, ordering errs 0
=== GCodes ===
Movement locks held by null, null
HTTP* is doing "M122" in state(s) 0
Telnet is idle in state(s) 0
File is idle in state(s) 0
USB is idle in state(s) 0
Aux is idle in state(s) 0
Trigger* is idle in state(s) 0
Queue is idle in state(s) 0
LCD is idle in state(s) 0
SBC is idle in state(s) 0
Daemon* is doing "G4 P100" in state(s) 0 0, running macro
Aux2 is idle in state(s) 0
Autopause is idle in state(s) 0
File2 is idle in state(s) 0
Queue2 is idle in state(s) 0
Q0 segments left 0, axes/extruders owned 0x0000000
Code queue 0 is empty
Q1 segments left 0, axes/extruders owned 0x0000000
Code queue 1 is empty
=== Filament sensors ===
check 0 clear 1602563
Extruder 0: pos 2473.24, errs: frame 0 parity 0 ovrun 0 pol 0 ovdue 0
=== CAN ===
Messages queued 1600, received 0, lost 0, errs 853123, boc 0
Longest wait 0ms for reply type 0, peak Tx sync delay 0, free buffers 50 (min 50), ts 907/0/0
Tx timeouts 0,0,906,0,0,692 last cancelled message type 30 dest 127
=== SBC interface ===
Transfer state: 5, failed transfers: 0, checksum errors: 0
RX/TX seq numbers: 7174/7174
SPI underruns 0, overruns 0
State: 5, disconnects: 0, timeouts: 0 total, 0 by SBC, IAP RAM available 0x258a4
Buffer RX/TX: 0/0-0, open files: 0
=== Duet Control Server ===
Duet Control Server version 3.5.0-rc.2 (2023-12-18 12:42:49)
Failed to deserialize the following properties:
- MoveSegmentation -> Int32 from 2.0
Daemon:
>> Doing macro daemon.g, started by system
Code buffer space: 4096
Configured SPI speed: 8000000Hz, TfrRdy pin glitches: 0
Full transfers per second: 41.05, max time between full transfers: 74.2ms, max pin wait times: 97.5ms/1.4ms
Codes per second: 1.54
Maximum length of RX/TX data transfers: 4420/1080

chrishamm

@timschneider TBH I would expect to see an error there. The G-code channels File and File2 process the same file concurrently so if one channel attempts to create a global variable that the other just created, that error should pop up. I think you'd see the same error in standalone mode as well.

To avoid it you can simply check state.thisInput and execute that conditional block only if it's executed by File and not by File2.

timschneider

@chrishamm what does it mean?
I just started the print job once, why is this job executed in two different channels? and the problem is only there after an M112 and only in the exists function.

if I extent the example to the following, the error is gone

if exists(global.TestVar1)
  echo global.TestVar1
  set global.TestVar1 = true
else
  echo global.TestVar1
  global TestVar1 = true


echo global.TestVar1

G4 S1

M112

Output

16.1.2024, 09:39:40 	Emergency stop, attemping to reconnect...
16.1.2024, 09:39:38 	true
16.1.2024, 09:39:38 	Error: in job file (channel File2) line 5: in GCode file line 0: unknown variable 'TestVar1'
16.1.2024, 09:39:38 	Error: in job file (channel File) line 5: in GCode file line 0: unknown variable 'TestVar1'
16.1.2024, 09:39:38 	M32 "0:/gcodes/job-variable.gcode"
File 0:/gcodes/job-variable.gcode selected for printing

chrishamm

@timschneider The second File channel is needed in 3.5 to support async moves (running 2 jobs concurrently that may synchronize at given times). I don't think using M112 and then starting a print prior to resetting the machine should be possible. @dc42 and I need to look into that.

timschneider

@chrishamm
ok thank you, I found the following

https://docs.duet3d.com/en/User_manual/RepRapFirmware/Multiple_motion_systems#how-the-queue-works

where it reads:

The File and File2 channels are logically a single channel. When you start a GCode job, the job file is opened by both of them. If the job contains no commands to use the second motion system then File2 will quickly reach the end of file or the M0 command, and wait for File to catch up. The point of having two channels that are logically a single channel is so that one can get well ahead of the other. Whereas if you send commands for both motion systems through one of the other channels, then the most that one channel can get ahead of the other is limited by the length of the movement queue.

so that makes it clear why the file is executed by both channels.

Don't get me wrong,

@chrishamm said in [bug] Error: in job file (channel File2) variable already exists:

I don't think using M112 and then starting a print prior to resetting the machine should be possible.

I'v noticed this error while working on the automatic filament calibration and sometimes I had to use the e-stop. Then the "Reset Machine" button appears. After resetting the machine, starting the print job again, and the error appeared.

So maybe there is an sync error between the RRF and DSF in connection to the current available variables. If I execute an echo, to force a sync with RRF, the exists function and global function work as expected.

So it is

M112 and then resetting the machine prior to starting a print

timschneider

This post is deleted!

timschneider

@chrishamm so I just checked it in standalone mode, first on Duet2, but there is not second queue so I went to an duet3 6XD.

The gcode was just fine on an duet2 with

M115
FIRMWARE_NAME: RepRapFirmware for Duet 2 WiFi/Ethernet FIRMWARE_VERSION: 3.5.0-rc.2 ELECTRONICS: Duet WiFi 1.02 or later + DueX5v0.11 FIRMWARE_DATE: 2023-12-14 10:30:41

I had to adopt the gcode for the 6XD, so maybe that is the bug in the first place.
The error of the original gcode

M32 "0:/gcodes/job-variable.gcode"
File 0:/gcodes/job-variable.gcode selected for printing
Error:  line 1 column 4: meta command: unknown value 'exists'
Cancelled printing file 0:/gcodes/job-variable.gcode, print time was 0h 0m

so I changed the gcode to the following:

if {exists(global.TestVar1)}
  echo global.TestVar1
  set global.TestVar1 = true
else
  global TestVar1 = true


echo global.TestVar1

G4 S1

M112

but with this gcode I was not able to reproduce the error in standalone mode

Error: in job file (channel File2) line 5: variable 'global.TestVar1' already exists

M122

M122
=== Diagnostics ===
RepRapFirmware for Duet 3 MB6XD version 3.5.0-rc.2 (2023-12-14 10:33:00) running on Duet 3 MB6XD v1.01 or later (standalone mode)
Board ID: 0JD2M-999AL-D2PS0-6J9F6-3SD6L-KPJM0
Used output buffers: 3 of 40 (18 max)
=== RTOS ===
Static ram: 153284
Dynamic ram: 116748 of which 0 recycled
Never used RAM 75960, free system stack 196 words
Tasks: NETWORK(1,ready,33.8%,182) ETHERNET(5,nWait,0.1%,321) HEAT(3,nWait,0.0%,369) Move(4,nWait,0.0%,340) CanReceiv(6,nWait,0.0%,942) CanSender(5,nWait,0.0%,334) CanClock(7,delaying,0.0%,343) MAIN(1,running,63.2%,128) IDLE(0,ready,2.9%,30), total 100.0%
Owned mutexes:
=== Platform ===
Last reset 00:04:45 ago, cause: software
Last software reset at 2024-01-16 10:56, reason: User, Gcodes spinning, available RAM 73040, slot 1
Software reset code 0x0003 HFSR 0x00000000 CFSR 0x00000000 ICSR 0x00400000 BFAR 0x00000000 SP 0x00000000 Task MAIN Freestk 0 n/a
Error status: 0x00
MCU temperature: min 23.1, current 23.9, max 25.0
Supply voltage: min 23.7, current 23.8, max 23.8, under voltage events: 0, over voltage events: 0, power good: yes
12V rail voltage: min 12.1, current 12.2, max 12.2, under voltage events: 0
Heap OK, handles allocated/used 0/0, heap memory allocated/used/recyclable 0/0/0, gc cycles 0
Events: 0 queued, 0 completed
Driver 0: ok
Driver 1: ok
Driver 2: ok
Driver 3: ok
Driver 4: ok
Driver 5: ok
Date/time: 2024-01-16 11:01:38
Slowest loop: 6.31ms; fastest: 0.07ms
=== Storage ===
Free file entries: 20
SD card 0 detected, interface speed: 25.0MBytes/sec
SD card longest read time 3.3ms, write time 0.0ms, max retries 0
=== Move ===
DMs created 125, segments created 0, maxWait 0ms, bed compensation in use: none, height map offset 0.000, max steps late 0, ebfmin 0.00, ebfmax 0.00
no step interrupt scheduled
Moves shaped first try 0, on retry 0, too short 0, wrong shape 0, maybepossible 0
=== DDARing 0 ===
Scheduled moves 0, completed 0, hiccups 0, stepErrors 0, LaErrors 0, Underruns [0, 0, 0], CDDA state -1
=== DDARing 1 ===
Scheduled moves 0, completed 0, hiccups 0, stepErrors 0, LaErrors 0, Underruns [0, 0, 0], CDDA state -1
=== Heat ===
Bed heaters -1 -1 -1 -1 -1 -1 -1 -1 -1 -1 -1 -1, chamber heaters -1 -1 -1 -1, ordering errs 0
=== GCodes ===
Movement locks held by null, null
HTTP is idle in state(s) 0
Telnet is idle in state(s) 0
File is idle in state(s) 0
USB is idle in state(s) 0
Aux is idle in state(s) 0
Trigger is idle in state(s) 0
Queue is idle in state(s) 0
LCD is idle in state(s) 0
SBC is idle in state(s) 0
Daemon is idle in state(s) 0
Aux2 is idle in state(s) 0
Autopause is idle in state(s) 0
File2 is idle in state(s) 0
Queue2 is idle in state(s) 0
Q0 segments left 0, axes/extruders owned 0x0000000
Code queue 0 is empty
Q1 segments left 0, axes/extruders owned 0x0000000
Code queue 1 is empty
=== CAN ===
Messages queued 1434, received 0, lost 0, errs 1352416, boc 0
Longest wait 0ms for reply type 0, peak Tx sync delay 0, free buffers 50 (min 49), ts 1427/0/0
Tx timeouts 0,0,1426,6,0,0 last cancelled message type 30 dest 127
=== Network ===
Slowest loop: 6.24ms; fastest: 0.03ms
Responder states: MQTT(0) HTTP(0) HTTP(0) HTTP(0) HTTP(0) HTTP(0) HTTP(0) FTP(0) Telnet(0) Telnet(0)
HTTP sessions: 1 of 8
= Ethernet =
Interface state: active
Error counts: 0 0 0 0 0 0
Socket states: 5 2 2 2 2 0 0 0
=== Multicast handler ===
Responder is inactive, messages received 0, responses 0

chrishamm

@timschneider Note that the Duet 2 does not support multiple motion systems due to the lack of RAM. I will look into the error once again even though I still think it shouldn't be possible to start a print if the machine is halted.

timschneider

@chrishamm ok thank you! But again, this is after a restart, after the machine was haltet - so in a normal operating state - not while the machine is haltet.

And the test was carried out on the duet3 6XD in standalone mode due to the missing support for multiple motion systems on the duet2 as you mentioned.

chrishamm

@timschneider Ok, I just tried to reproduce it and I can confirm what I said before: This is actually expected behaviour. If you put conditional G-code into a job file, that conditional G-code is always executed on the two File channels on the Duet 3, and the order doesn't necessarily need to be the same. That's why this error can be provoked. I'm pretty sure RRF behaves in the same way in standalone mode as well even if you couldn't reproduce the issue. That's why it is a good idea to check state.thisInput if you must put conditional G-code directly in a job file.

If you put that conditional G-code in a macro file and the corresponding motion system of the input is not used (as is the case with File2 by default), that macro is only executed on File and not File2 (see here for further info).

Besides, it isn't possible to start prints again in halted mode, so that's OK as well.

timschneider

@chrishamm thank you for checking it that fast, and I respectfully see your response, but the underlaying bug in it is not addressed.
There is some initialize/reset bug in the dsf which is causing all kind of trouble, but this is a minimal working example on how to reproduce it very easy. You will come back to that bug later on, even if you do not see the bug now.

In sbc mode, channel 0 and 2 are sometimes mixed up, which will lead to unexpected behaviour of the machine - even after a fresh hard reboot.

the following execution order is not possible with normal behaviour.

another example

g-code used to produce it

content of 0:/gcodes/job-variable.gcode

echo {state.thisInput}

if {state.thisInput == 2}
  if {exists(global.TestVar1)}
    echo "before set: " ^ { global.TestVar1 }
    set global.TestVar1 = true
  else
    global TestVar1 = true


  echo global.TestVar1

G4 S5

if {state.thisInput == 2}
  M999
  ;M112

content of 0:/sys/stop.g

; stop.g
; called when M0 (Stop) is run (e.g. when a print from SD card is cancelled)
;

echo "0:/sys/stop.g"
;M98 P"0:/sys/meltingplot/print_end"

if conditional gcode in job files is not supported, the machine should output an error message.

chrishamm

@timschneider Thanks, now I see what you mean. It looks like there is indeed an issue with evaluation requests which I will look into next. I highly doubt it is related to resetting/E-STOP, though.

chrishamm

@timschneider This bug is now fixed upstream.

PS: The extra curly braces around your expressions aren't needed.

timschneider

@chrishamm Thank you for your work and the fast fix! I'll try it as soon as the fix is available in the beta channel.

timschneider

@chrishamm I can confirm, that I'm unable to reproduce the above error - so it should be fixed