Daemon.g logging incorrect file position.

tdowns7

I'm trying to log the file position from the daemon to see how temperature and humidity in the print chamber change throughout the print. However, I've noticed that when I log the object model property "job.filePosition" from the daemon it doesn't appear to be the correct file position.

Here's a gcode file that I've been using to test this.

M929 P"0:/gcodes/Logs/Print Logs/DaemonLogTest.csv" S3

M118 P1 S{"Line 3, File Position," ^ job.filePosition} L3
G4 S5
M118 P1 S{"Line 5, File Position," ^ job.filePosition} L3

M118 P1 S{"Line 7, File Position," ^ job.filePosition} L3
G4 S5
M118 P1 S{"Line 9, File Position," ^ job.filePosition} L3

M118 P1 S{"Line 11, File Position," ^ job.filePosition} L3
G4 S5
M118 P1 S{"Line 13, File Position," ^ job.filePosition} L3

M118 P1 S{"Line 15, File Position," ^ job.filePosition} L3
G4 S5
M118 P1 S{"Line 17, File Position," ^ job.filePosition} L3

M929 S0

My daemon.g file(global.daemonLoopTime=10):

while true
	; Log sensor data if a file is being printed and the enable variable is set to true.
	if job.file.fileName != null && global.daemonLogEnable == true
		M118 L2 S{",Chamber Temp, " ^ sensors.analog[global.chmbr_temp].lastReading ^ ",File Position," ^ job.filePosition ^ " "}
		M118 L2 S{",Chamber Humidity, " ^ sensors.analog[global.chmbr_humid].lastReading ^ ",File Position," ^ job.filePosition ^ " "}
	else
		; don't log
	G4 S{global.daemonLoopTime} ; Pause every X seconds

And the resulting log file.

2023-08-28 10:10:47 [info] Event logging started at level debug
2023-08-28 10:10:47 [info] Running: Duet 3 MB6HC v1.01: 3.4.5 (2022-11-30 19:35:23)
2023-08-28 10:10:47 [debug] Line 3, File Position,56
2023-08-28 10:10:52 [debug] Line 5, File Position,120
2023-08-28 10:10:52 [debug] Line 7, File Position,179
2023-08-28 10:10:55 [info] ,Chamber Temp, 2000.00,File Position,36 
2023-08-28 10:10:55 [info] ,Chamber Humidity, 2000.00,File Position,165 
2023-08-28 10:10:57 [debug] Line 9, File Position,243
2023-08-28 10:10:57 [debug] Line 11, File Position,302
2023-08-28 10:11:02 [debug] Line 13, File Position,367
2023-08-28 10:11:02 [debug] Line 15, File Position,427
2023-08-28 10:11:05 [info] ,Chamber Temp, 2000.00,File Position,285 
2023-08-28 10:11:05 [info] ,Chamber Humidity, 2000.00,File Position,414 
2023-08-28 10:11:07 [debug] Line 17, File Position,492
2023-08-28 10:11:07 [info] Event logging stopped

Firmware: RepRapFirmware for Duet 3 MB6HC 3.4.5 (2022-11-30)

chrishamm

@tdowns7 Why do you think it is wrong? The current file position may be way ahead of the current move being done because RRF needs to calculate the moves in advance.

tdowns7

@chrishamm Going off the timestamps, it looks like the daemon log commands are executed between Line 7 and 9 of the job file. But the byte positions logged by the daemon are before Line 7.

2023-08-28 10:10:52 [debug] Line 7, File Position,179
2023-08-28 10:10:55 [info] ,Chamber Temp, 2000.00,File Position,36 
2023-08-28 10:10:55 [info] ,Chamber Humidity, 2000.00,File Position,165 
2023-08-28 10:10:57 [debug] Line 9, File Position,243

I'm assuming that the daemon runs during the dwell command in this case. So I'd expect that the byte positions logged by the daemon would be between 179 and 243.

M118 P1 S{"Line 7, File Position," ^ job.filePosition} L3; File Position = 179
G4 S5
M118 P1 S{"Line 9, File Position," ^ job.filePosition} L3; File Position = 243

chrishamm

@tdowns7 Thanks, can you confirm the problem persists with RRF 3.4.6?

tdowns7

@chrishamm Yes, this did persist when I updated to RRF3.4.6

2023-08-28 16:11:10 [info] Event logging started at level debug
2023-08-28 16:11:10 [info] Running: Duet 3 MB6HC v1.01: 3.4.6 (2023-07-21 14:11:38)
2023-08-28 16:11:10 [debug] Line 3, File Position,57
2023-08-28 16:11:15 [debug] Line 5, File Position,121
2023-08-28 16:11:15 [debug] Line 7, File Position,181
2023-08-28 16:11:18 [info] ,Chamber Temp, 2000.00,File Position,38 
2023-08-28 16:11:18 [info] ,Chamber Humidity, 2000.00,File Position,167 
2023-08-28 16:11:20 [debug] Line 9, File Position,245
2023-08-28 16:11:20 [debug] Line 11, File Position,305
2023-08-28 16:11:25 [debug] Line 13, File Position,370
2023-08-28 16:11:25 [debug] Line 15, File Position,431
2023-08-28 16:11:28 [info] ,Chamber Temp, 2000.00,File Position,289 
2023-08-28 16:11:28 [info] ,Chamber Humidity, 2000.00,File Position,418 
2023-08-28 16:11:30 [debug] Line 17, File Position,496
2023-08-28 16:11:30 [info] Event logging stopped

chrishamm

@tdowns7 I can reproduce this problem, we're looking into it.

chrishamm

@tdowns7 I could identify the cause of this bug and I've got a fix ready. It will be included in the upcoming v3.5-rc.1 and in v3.4.7, although I can't say yet when we will release the latter.

tdowns7

@chrishamm , Thanks for the quick follow up, appreciate it! Linking the github issue for those who may want to track.