Print resume fails after long pause

TK3d

My selfmade Printer works well for normal prints. I have an Rotary Filament Sensor, which check´s the filament feedrate.

If, for any reason, the Printer goes in "Pause Mode", the resuming of the print works if the pause is not too long. Everytime i tried it, waiting at my printer, it works.

But if i recognize it much later (e.g. after a filament jam), the extruder has cooled down. Then i solve the problem and press Preheat. The Extruder heats up (Everything normal at this point). But If i press "Resume", the printer tries to work off the commands an feeds the filament  !! X-Times !! faster than normal. Extruder can´t follow this extreme speed. Everytime I try to resume, at this point, it fails because of the very, very high Speed the Printer can not follow. After a few seconds the Rotary Filament Sensor triggers a jam. I have to cancel the print.

It is a Mystery for me. I think it is a Problem specially with my DUE Configuration.

I think it´s a bug for DUE Printers. Are there any hints? Thanks....!

Printer Config:

- Repetier Server 0.92.3 (control´s everything) with TouchDisplay

- Repetier Firmware 1.03

- Rotary Filament Sensor

Bei meinem selbstgebauten Drucker, habe ich ein Problem mit dem Fortsetzen von Drucken nach einer Pause Situation. Immer wenn ich das live am Drucker teste funktioniert das weiterdrucken problemlos. Habe alle Auslöser getestet. Es ist egal ob ich am Display Pause drücke oder ob der Filament Sensor einen Jam erkennt (z.b. wenn ich das Filament festhalte) oder ich die Pause im Code ergänze.

Nur wenn ich nicht in der Nähe des Druckers bin und dann erst nach Stunden feststelle, daß der Drucker in Pause gegangen ist (Weil z.B. ein Jam aufgetreten ist) habe ich Probleme. Nach dieser Zeit ist der Extruder bereits abgekühlt. Ich kann dann alles in Ordung bringen und Preheat drücken. Das funktioniert auch, aber wenn ich dann "Resume" drücke versucht der Drucker die Kommandos in extremer Geschwindigkeit abzuarbeiten. Weder der Extruder noch die Schrittmotoren können dieser Geschwindigkeit folgen. Es rattert nur. Der Filamentsensor erkennt dann nach 2-3 Sekunden einen Jam. Egal wie oft ich das versuche passiert immer das selben. Ich bin gezwungen den Druck abzubrechen. Nach dem Abbruch funktioniert wieder alles normal.

Ich kann mir nur denken, daß es ein Arduino DUE spezifisches Problem ist. Ich komme nur selbst nicht drauf was das Problem ist. Ich vermute jedoch den Fehler eher in der Server Software. Leider kann ich es nicht nur über den Drucker testen. Ich habe nur noch den Server mit Touchdisplay angeschlossen. Der Drucker hat kein eigenes Display mehr.

Hat irgendjemand einen Tipp? Vielen Dank...!!

Repetier

The cooldown comes from firmware or server. Both can have a timeout to disable heaters on long pause. Preheating should not be required - with rescue system we store last temperatures as well and restore them.

To debug the problem you need to enable logging so we can see what exactly gets send on resume. I do not really expect different commands if you resume after a minute or an hour. There is no such thing in server. What might be is that a timeout in firmware has an unexpected effect. 

TK3d

I tried to generate two files with a fail and a good result. But I can not figure out what the error causes. I try to make better files which show the problem clearer..... .

TK3d

Now I generate two Demo Files, which are showing the different behaviors.

I sliced a 20mm CalCube with Slic3r and Repetier Host an added an "@pause" Request at Height 0,45mm and preheated the Printer.
- The File marked as Good startet printing and entered the Pause Mode at Layerchange. After a short time I tapped at the Resume Button at the Touchdisplay and the Print finishes succesfully. Then I started the second try with the same prepares.

- The File marked as File did the same till Pause Mode. I waited much longer ca. 1/2h. The Printer waits at Pause Position and the extruder has cooled down. After Preheating the extruder I tap the resume button. The move to Printposition fails (the Head moves not a bit) and the Extruder tries to push the filament at very high speed. The Flow can´t be so high, so the Printer detects correctly a jam. I tried to start the print for 3 times, then I stopped the print.

I am confused. Please help. I think it is a important feature. Especially for long prints.

TK3d

I can not upload the two files. Here is the zipped File with the two logs

TK3d

Sorry, I tried to upload the files several times. I seems to work, but after "Save Draft" the files are lost. I generated a download link ( I don´t think its a good idea to post the whole two files in Text).

https://gofile.io/?c=4s2Byy

Repetier

Don't see a temperature problem in failed log. I see it disables extruder after 10 minutes and then it enables it and waits for target temperature and continues. What I find irritating is this

<  8:51:48.612: @snapshot 1

>  8:51:48.615: ok 2289

>  8:51:48.615: ok 2290

>  8:51:48.615: ok 2291

<  8:51:48.616: N133370 G1 F7800

<  8:51:48.616: @excludeTimeOff

<  8:51:48.616: @excludeTimeOn

<  8:51:48.616: @snapshot 1

<  8:51:48.616: N133371 G1 F7800

<  8:51:48.616: @excludeTimeOff

<  8:51:48.616: @excludeTimeOn

<  8:51:48.616: @snapshot 0

<  8:51:48.617: N133372 G1 F7800

<  8:51:48.617: @excludeTimeOff

<  8:51:48.617: @excludeTimeOn

<  8:51:48.617: @snapshot 1

>  8:51:48.619: ok 2292

>  8:51:48.619: ok 2293

>  8:51:48.619: ok 2294

<  8:51:48.620: N133373 G1 F7800

<  8:51:48.620: @excludeTimeOff

<  8:51:48.620: @excludeTimeOn

<  8:51:48.620: @snapshot 1

<  8:51:48.620: N133374 G1 F7800

<  8:51:48.620: @excludeTimeOff

<  8:51:48.620: @excludeTimeOn

<  8:51:48.620: @snapshot 1

<  8:51:48.620: N133375 G1 F7800

<  8:51:48.620: @excludeTimeOff

<  8:51:48.620: @excludeTimeOn

<  8:51:48.620: @snapshot 1

Seems like you have 2 webcams for which you both make a video. What is your setting there that it tries to make so much snapshots suddenly? Also do you have really several G1 F7800 in a row in your gcode? These just confuse me and do not look correct. Maybe when I see your settings I can reproduce and or see why it happens. Also please check where all the identical lines come from, that is not a typical content of gcode. Repetition does not change anything. 
Anyhow the many snapshots surely might add some delay in operation at that frequency. Is that the problem?

TK3d

You are right, there was an not available webcam 2 in the config. I was not aware of this. Removed it from Server Config. I try tomorrow if it changes something in the behavior.
Second, i checked the Gcode, there is nowhere "G1 F7800". Also in the eventbased Server Settings. Don´t know from where it comes.... Thanks so far....

Repetier

Ok, maybe G1 F7800 comes from the snapshot restoring old speed also this is only required after moves but does not explain the repetitions. But maybe it is as you said the second webcam that fails from not being there so it repeats over and over since it never finished so still flagged to make the snapshot.

TK3d

Tested with following changes:

- deleted the second Webcam (-> No change in behavior)

- changed to absolut extrusion (thought this could be the reason, because (I think) Repetierserver sends a G92 Exxx Command after Pause. I think this could end the relative extrusion). But the Problem is the same.

What stands out for me in the Log File is, that after pause. The Printer should extrude 25mm in a time period of approx 2 seconds. Before the pause 3-4mm per 2 seconds is normal. I am clueless again

The logfile is available at https://gofile.io/?c=1M1HmO

Repetier

Why should it extrude 25mm in 2 seconds. Here a reduced part of the log

< 19:36:55.506: N135683 G1 X125.254 Y122.526 E14.39532

....

> 20:02:27.822: T:233.00 /230 B:65.10 /65 B@:0 @:76

< 20:02:27.944: N135846 M513 ; Setze das Jam Detect Signal zurück

< 20:02:27.944: N135847 G90

< 20:02:27.944: N135848 G1 X125.482 Y122.136 F7200

< 20:02:27.944: N135849 G1 Z0.300 F2400

< 20:02:27.945: N135850 G92 E14.3953

< 20:02:27.945: N135851 G1 F7800

...

< 20:02:28.165: @snapshot 0

< 20:02:28.166: N135925 G1 F7800

< 20:02:28.166: @excludeTimeOff

< 20:02:28.166: @excludeTimeOn

< 20:02:28.166: @snapshot 0

< 20:02:28.166: N135926 G1 F7800

< 20:02:28.166: @excludeTimeOff

< 20:02:28.166: @excludeTimeOn

< 20:02:28.166: @snapshot 0

> 20:02:28.169: ok 4846

> 20:02:28.169: ok 4847

> 20:02:28.169: ok 4848

< 20:02:28.169: N135927 G1 F7800

< 20:02:28.169: @excludeTimeOff

< 20:02:28.169: N135928 G1 Z0.450 F7800.000

> 20:02:28.173: ok 4849

> 20:02:28.173: ok 4850

> 20:02:28.173: ok 4851

< 20:02:28.173: N135929 M104 S215 ; set temperature

< 20:02:28.175: N135930 M140 S60 ; set bed temperature

> 20:02:28.177: ok 4852

> 20:02:28.177: ok 4853

> 20:02:28.177: ok 4854

< 20:02:28.177: N135931 G1 X127.023 Y108.665

< 20:02:28.178: N135932 G1 F1200

< 20:02:28.178: N135933 G1 X126.353 Y109.335 E14.42044

You see last E before pause is 14.3953 then after continue you have heatup and again lots of webcam snapshots, this time only for first webcam but still lots of it so still wondering how it happens. Must be pause related. Do you have set it per time? Then it might have added them during pause one per minute or whatever you had and that gets executed with continue. Would make sense also not good. Will check and add a test for pause to not add snapshots then.

Then you see the rest of continue were G92 sets E to 14.3953 correctly and next extrusion is 14.42 from print so from the commands being send that would be ok. No extra 25mm and that is also not to expect or I missed a part in your problem description.

So can you please tell more precise what you expect and what happens in the error case as the gcode send doe snot show anything unusual.

TK3d

You can see a totaly different Extrusion Speed in the Log if you compare before and after pause.

Printing before pause e.g.:

Time: 19:36:06.357 E4.897
Time: 19:36:08.869 E7.698
Difference  about 1,8mm per second

Printing after pause e.g.:
Time: 20:02:28.178 E14.420
Time: 20:02:29.353 E41.146
That Difference is about 22,27mm per second !!!!

I think it is not an Repetier Server Issue. It should be an Firmware Issue, I think after every "OK" from the printer, the server sends a new command. The OK´s are to fast (I think).

Repetier

< 20:02:28.178: N135932 G1 F1200

< 20:02:28.178: N135933 G1 X126.353 Y109.335 E14.42044
...
< 20:02:29.251: N136083 G1 F1200
...

> 20:02:29.331: ok 5024

< 20:02:29.332: N136101 G1 X137.761 Y108.853 E40.92600

> 20:02:29.353: ok 5025

< 20:02:29.353: N136102 G1 X143.647 Y114.739 E41.14642

You are reading the log wrong. The time between commands send has nothing to do with extrusion speed. The G1 Fxxx values set printing speed. What you measure is time between lines being send and that is completely indepedent from the printing speed. It only depend on the "ok" being returned from firmware indicating that firmware is ready to accept the next command. In both cases speed is 20mm/s but for xy moves. The E speed is linear depedent on the xy move and much lower.

TK3d

Yes, the time between two commands has nothing to do with extrusion speed. Thats clear to me. And it is clear to me that the Printer fills its buffer and then works off command for command. But over a longer period (a second or longer) you can look how much filament should be extruded. And that is what I can observe at the printer. The Extruder whants to push Filament in at extreme Speed, which he can´t  handle.

TK3d

Only if the printer thinks the commands (moves) are worked off he accepts the next command, if you look how frequentliy this happens,  you see how fast this is. It´s the same 3D Object. In the good print log file eg. 10 worked off Commands last a few seconds. In the failed log that last´s only fragments of of a second. Am I so confused or points that to the problem?

Repetier

Ok, so the commands being send do not show anything unusual. Before the "fast" part it gets set to 20mm/s fox xy moves which is not fast. A bit before it was 25mm/s still not fast. I assume that not only extrusion is fast but moves as well.
One thing I did not check was if you changed speed multiplier somehow. That would increase speed without having different gcode, but is limited to 300-400%. So not the factor 10 you mention. But that method you used is imprecise. Depends mainly when a long line blocks for longer and if then on many small lines many long lines get send it will increase the virtual speed.
Would be the idea that matches what I read from log.

TK3d

I´m sorry, that was not scientific accurate enough. But the guess was wright. Today I had the right thought to verify that:

The two print files (good and fail) contain the exact same commands, because it was the same Printfile. Every entire Command is unique (at least for one layer) and should be in both files. So I search for an Command after pause when the printer starts printing and before the fail print detects an jam. In Theory it should be exactly the same!!!:

I took the two files at https://gofile.io/?c=4s2Byy which are printed with relative extrusion.

In the "good log":

Starttime <  7:38:33.463: N118062 G1 X127.023 Y108.665

....

....

Endtime <  7:39:23.842: N118249 G1 X137.761 Y108.853 E0.01590

Between these Commands are 90379msec and 187N (Command Lines)

In the "fail log":

Starttime <  8:51:49.133: N133697 G1 X127.023 Y108.665

Endtime <  8:51:50.286: N133868 G1 X137.761 Y108.853 E0.01590

Between these Commands are 1153msec and 171N (Command Lines)

!!! This is 78x faster !!!

I checked it twice (with different selected start and end Commands, again after pause before jam):

In the good log:

Start: <  7:38:33.470: N118066 G1 X127.436 Y108.853 E0.04056

End:  <  7:39:19.722: N118239 G1 X140.763 Y108.853 E0.10801

Difference: 86252msec and 173 Lines

In the failed log:

Start: <  8:51:49.148: N133701 G1 X127.436 Y108.853 E0.04056

End:  <  8:51:50.229: N133859 G1 X140.763 Y108.853 E0.10801

Difference: 1081msec and 158 Lines

!!! This is 79,79x faster !!!

I hope this comprehensibly and accurate enough ;-)

To remember:

- my printer runs with an Arduino DUE

- The Move-Commands result in no move of the printhead in the failed print. He can not follow. The only noticeable action ist the extremely fast extruder move.

- The speed multiply is not modifyed by me. I don´t have a direct printer control/display attached. Only RepetierServer with Touchdisplay.

I can not understand why other users don´t run in the same problems. Is it because of the rare combination of jam detect and DUE? If I have the time, i will try to test the same with an other firmware (e.G. Marlin Kimbra). But this is a lot of work. I have to set up everything for my custom board and printer. But I want to stay at RepetierFirmware, because I think server and Firmware is a good companion.

Repetier

I see what you mean and factor 80 over a longer period can not come from speed multiplier either. Checking the log I also sow no speed multiplier. It is like the due is 80 times faster suddenly which is surely not the case:-)
I will try to replay at the weekend.

If I understand you correctly all you do is pause, wait for server timeout to disable heater and then hit continue, right?

TK3d

Yes, that´s all. The only difference between a good resume (with normal printing till end) and a failed resume, is the time between pause and resume. A short wait works, a long wait fails.....