search

MarlinFirmware / Marlin

Marlin is an optimized firmware for RepRap 3D printers based on the Arduino platform. Many commercial 3D printers come with Marlin installed. Check with your vendor if you need source code for your specific machine.
https://marlinfw.org
GNU General Public License v3.0
16.35k stars 19.26k forks source link

[BUG] Emergency Parser does not work on RAMPS 1.4 EFB no LCD with Marlin Bugfix #17129

Closed stevereno30 closed 4 years ago

stevereno30 commented 4 years ago

I have been trying to get Advanced Pause via Octoprint to work on my machine for a month now, and it simply does not work with the latest bugfix firmware. I updated today, but I still have a non-working advanced pause. The terminal output below shows my machine after it has unloaded filament after a filament runout event. After Octoprint serves a "continue" button and I press it, no command appears in the terminal. The machine will send a "paused for user" status until it times out and the hot end cools down. I can manually send an M108 to initiate filament loading, but if I do this, the machine will start printing after the set purge length passes through the extruder. 

Recv:  T:230.75 /230.00 B:60.02 /60.00 @:30 B@:44
Recv: echo:Insert filament and send M108
Recv: //action:prompt_end
Recv: //action:prompt_begin Nozzle Parked
Recv: //action:prompt_button Continue
Recv: //action:prompt_show
Recv: echo:busy: paused for user
Recv:  T:230.69 /230.00 B:60.00 /60.00 @:42 B@:49
Recv: echo:busy: paused for user
Recv:  T:230.94 /230.00 B:60.00 /60.00 @:37 B@:49
Recv: echo:busy: paused for user
Recv:  T:230.88 /230.00 B:60.01 /60.00 @:41 B@:45
Recv: echo:busy: paused for user
Recv:  T:230.56 /230.00 B:60.00 /60.00 @:52 B@:47
Recv: echo:busy: paused for user
stevereno30 commented 4 years ago

That is the branch I was using. I used the latest nightly from the Marlin website.

On Wed, Mar 11, 2020, 5:17 PM Scott Lahteine notifications@github.com wrote:

Please test the bugfix-2.0.x branch https://github.com/MarlinFirmware/Marlin/archive/bugfix-2.0.x.zip to see where it stands. If the problem has been resolved then we can close this issue. If the issue isn't resolved yet, then we should investigate further.

— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub https://github.com/MarlinFirmware/Marlin/issues/17129#issuecomment-597905259, or unsubscribe https://github.com/notifications/unsubscribe-auth/ABG574EBSVYOXJZOQIUQECTRHAEYTANCNFSM4LF64QNA .

thinkyhead commented 4 years ago

I can manually send an M108 to initiate filament loading

We'll need to re-familiarize ourselves with the Host Prompt stuff to figure out why the response from host is not being seen.

thinkyhead commented 4 years ago

@InsanityAutomation — Can you confirm whether load_filament is handling host prompts correctly? It looks ok to me.

I can see that host_response_handler is clearing the wait_for_user flag in response to PROMPT_USER_CONTINUE. And the load_filament method is indeed doing host_action_prompt_begin(PROMPT_USER_CONTINUE, ...).

The OP didn't fill out the template or supply configurations, so we're in the dark about whether other things might be enabled like EXTENSIBLE_UI which could interfere with host prompts. But from what I can see the pieces are in place for everything to work.

Upon a quick review of these methods, can you see any reason why host prompts would fail to clear wait_for_user?

InsanityAutomation commented 4 years ago

I reflashed a machine with it enabled on an extui only display less than a week ago. I can test it either tonight or tomorrow, as my travel plans tomorrow got cancelled a few hours ago.

Can you confirm if this is triggered by M600/ or M701/702 @stevereno30 that may be an important factor.

stevereno30 commented 4 years ago

Sorry I didn't fill out the template... here it is:

Bug Description

Emergency Parser does not receive M876 commands from Octoprint

My Configurations

Configuration.zip

Steps to Reproduce

  1. Enable action commands in Marlin and Octoprint.
  2. Enable emergency parser in Marlin
  3. Start Print
  4. Trigger filament runout
  5. Run through Advanced Pause in Octoprint and notice that none of the action commands sent by Octoprint are received by Marlin.
  6. Use M108 to resume print since it is the only thing that Marlin recognizes.

Expected behavior: Marlin receives M876 and responds using advanced pause options

Actual behavior: Nothing

Additional Information

stevereno30 commented 4 years ago

@InsanityAutomation How might I determine what triggers the filament runout in code? The terminal does not display what triggered it, though I expect it is M600 since (as far as I know) this is Marlin's default behavior.

InsanityAutomation commented 4 years ago

@stevereno30 reading the expanded description that appears to be the case. And no extui, so I'll bump the config for my raise3d that's been gutted in a corner for 6mo that has no local display either and matches better then see what happens.

InsanityAutomation commented 4 years ago

FYI, we did spot an issue with the emergency parser. Can you test the current bugfix? Thinky got a fix in a few minutes ago.

stevereno30 commented 4 years ago

I just started a 13 hour print, so I'll flash in the morning. Thanks for the update!

stevereno30 commented 4 years ago

After flashing the newest bugfix, this is now what happens:

Filament runout notification is sent to Octoprint: image

Filament is unloaded, then Octoprint receives this: image If I don't get filament loaded in time, the reheat button pops up, but it does nothing if I press it. The only way to get the machine to reheat at this point is to send a M108 command via the terminal. In the image below, you can see that Octoprint has the temp set to 230, but the machine is cooling. The point at which the hot end starts heating up again is where I sent the M108.

image

At this point, if I need to reheat the machine using M108, Marlin no longer responds to M876 commands. The print then must be resumed by sending a second M108 command before the reheating times out again.

However, if I happen to be sitting next to the machine when filament runs out, and I manage to reload the filament and hit the "Nozzle Parked" continue button, then the machine will receive the M876 command. The problem is that Marlin then behaves the exact same was as if it received an M108 command, and it resumes printing without any additional input from me. That means when this prompt is received by Octoprint: image Marlin has already resumed the print job. Here is the terminal output when this process all happens:

Recv: echo:busy: processing
Recv:  T:230.06 /230.00 B:60.23 /60.00 @:54 B@:26 W:1
Recv:  T:230.00 /230.00 B:60.24 /60.00 @:57 B@:23
Recv:  T:230.06 /230.00 B:60.19 /60.00 @:54 B@:41 W:0
Recv: ok
Recv: //action:paused
Send: N18 G90*41
Printer signalled that it paused, switching state...
Changing monitoring state from "Printing" to "Pausing"
Recv:  T:230.19 /230.00 B:60.14 /60.00 @:50 B@:56
Recv: echo:busy: processing
Recv:  T:230.25 /230.00 B:60.02 /60.00 @:48 B@:90
Recv: echo:busy: processing
Recv:  T:230.19 /230.00 B:60.05 /60.00 @:51 B@:76
Recv: echo:busy: processing
Recv: X:-4.00 Y:190.00 Z:30.00 E:17.47 Count X:-320 Y:15200 Z:24000
Communication timeout while printing, trying to trigger response from printer. Configure long running commands or increase communication timeout if that happens regularly on specific commands or long moves.
Changing monitoring state from "Pausing" to "Paused"
Send: M105
Recv: echo:busy: processing
Recv:  T:229.94 /230.00 B:60.15 /60.00 @:59 B@:27
Recv: echo:busy: processing
Recv:  T:230.00 /230.00 B:60.05 /60.00 @:56 B@:53
Recv: echo:busy: processing
Recv:  T:230.31 /230.00 B:60.03 /60.00 @:45 B@:53
Recv: echo:busy: processing
Recv:  T:230.38 /230.00 B:60.00 /60.00 @:44 B@:59
Recv: echo:busy: processing
Recv:  T:230.13 /230.00 B:60.01 /60.00 @:54 B@:53
Recv: echo:busy: processing
Recv:  T:230.25 /230.00 B:60.05 /60.00 @:48 B@:39
Recv: echo:Insert filament and send M108
Recv: //action:prompt_end
Recv: //action:prompt_begin Nozzle Parked
Recv: //action:prompt_button Continue
Recv: //action:prompt_show
Recv: echo:busy: paused for user
Recv:  T:230.00 /230.00 B:60.04 /60.00 @:58 B@:40
Recv: echo:busy: paused for user
Recv:  T:229.94 /230.00 B:59.99 /60.00 @:60 B@:54
Recv: echo:busy: paused for user
Recv:  T:230.00 /230.00 B:60.00 /60.00 @:57 B@:48
Send: M876 S0
Recv: M876 Responding PROMPT_FILAMENT_RUNOUT_CONTINUE
Recv:  T:230.00 /230.00 B:60.00 /60.00 @:56 B@:46 W:?
Recv: echo:busy: processing
Recv:  T:230.00 /230.00 B:60.00 /60.00 @:56 B@:46
Recv:  T:230.13 /230.00 B:60.01 /60.00 @:51 B@:43 W:19
Recv:  T:230.00 /230.00 B:60.01 /60.00 @:55 B@:43 W:18
Recv: echo:busy: processing
Recv:  T:230.00 /230.00 B:60.01 /60.00 @:55 B@:43
Recv:  T:229.81 /230.00 B:60.02 /60.00 @:62 B@:39 W:17
Recv:  T:230.00 /230.00 B:60.03 /60.00 @:54 B@:36 W:16
Recv: echo:busy: processing
Recv:  T:230.00 /230.00 B:59.98 /60.00 @:55 B@:53
Recv:  T:230.06 /230.00 B:60.05 /60.00 @:52 B@:29 W:15
Recv:  T:229.81 /230.00 B:60.03 /60.00 @:61 B@:35 W:13
Recv: echo:busy: processing
Recv:  T:229.81 /230.00 B:60.03 /60.00 @:61 B@:35
Recv:  T:229.81 /230.00 B:60.02 /60.00 @:62 B@:38 W:12
Recv:  T:229.81 /230.00 B:60.03 /60.00 @:62 B@:34 W:11
Recv: echo:busy: processing
Recv:  T:229.81 /230.00 B:60.03 /60.00 @:62 B@:34
Recv:  T:229.94 /230.00 B:60.02 /60.00 @:56 B@:36 W:10
Recv:  T:230.00 /230.00 B:60.00 /60.00 @:54 B@:42 W:9
Recv: echo:busy: processing
Recv:  T:230.00 /230.00 B:60.00 /60.00 @:54 B@:42
Recv:  T:229.88 /230.00 B:59.84 /60.00 @:59 B@:93 W:8
Recv:  T:229.81 /230.00 B:60.01 /60.00 @:61 B@:38 W:7
Recv: echo:busy: processing
Recv:  T:230.00 /230.00 B:59.96 /60.00 @:54 B@:53
Recv:  T:230.00 /230.00 B:60.00 /60.00 @:54 B@:41 W:6
Recv:  T:230.06 /230.00 B:60.00 /60.00 @:51 B@:41 W:5
Recv: echo:busy: processing
Recv:  T:229.81 /230.00 B:60.00 /60.00 @:61 B@:41
Recv:  T:229.94 /230.00 B:60.01 /60.00 @:57 B@:38 W:4
Recv:  T:229.94 /230.00 B:60.03 /60.00 @:57 B@:31 W:3
Recv: echo:busy: processing
Recv:  T:229.94 /230.00 B:60.03 /60.00 @:57 B@:31
Recv:  T:230.06 /230.00 B:60.04 /60.00 @:52 B@:28 W:2
Recv:  T:230.00 /230.00 B:60.01 /60.00 @:55 B@:38 W:1
Recv: echo:busy: processing
Recv:  T:230.00 /230.00 B:60.01 /60.00 @:55 B@:38
Recv:  T:230.13 /230.00 B:59.99 /60.00 @:51 B@:45 W:0
Recv: echo:busy: processing
Recv:  T:230.06 /230.00 B:60.01 /60.00 @:53 B@:37
Recv: echo:busy: processing
Recv:  T:230.06 /230.00 B:60.00 /60.00 @:54 B@:40
Recv: echo:busy: processing
Recv:  T:230.06 /230.00 B:60.02 /60.00 @:53 B@:32
Recv: echo:busy: processing
Recv:  T:230.00 /230.00 B:60.02 /60.00 @:56 B@:32
Recv: echo:busy: processing
Recv:  T:230.06 /230.00 B:60.01 /60.00 @:53 B@:35
Recv: echo:busy: processing
Recv:  T:229.94 /230.00 B:60.01 /60.00 @:58 B@:34
Recv: echo:busy: processing
Recv:  T:229.88 /230.00 B:60.01 /60.00 @:60 B@:34
Recv: echo:busy: processing
Recv:  T:230.06 /230.00 B:60.00 /60.00 @:52 B@:37
Recv: echo:busy: processing
Recv:  T:229.94 /230.00 B:59.98 /60.00 @:57 B@:44
Recv: echo:busy: processing
Recv:  T:229.88 /230.00 B:60.02 /60.00 @:59 B@:30
Recv: echo:busy: processing
Recv:  T:229.88 /230.00 B:60.00 /60.00 @:59 B@:36
Recv: //action:prompt_end
Recv: //action:prompt_begin Paused
Recv: //action:prompt_button PurgeMore
Recv: //action:prompt_button Continue
Recv: //action:prompt_show
Recv: echo:busy: processing
Recv:  T:229.88 /230.00 B:60.01 /60.00 @:59 B@:32
Recv: echo:busy: processing
Recv:  T:229.81 /230.00 B:60.01 /60.00 @:62 B@:32
Recv: echo:busy: processing
Recv:  T:230.06 /230.00 B:60.00 /60.00 @:52 B@:35
Recv: //action:resumed
Printer signalled that it resumed, switching state...
Changing monitoring state from "Paused" to "Resuming"
Recv: ok
Recv:  T:229.88 /230.00 B:60.00 /60.00 @:59 B@:35 W:?
Recv:  T:229.69 /230.00 B:60.06 /60.00 @:67 B@:16 W:19
Recv:  T:230.00 /230.00 B:59.99 /60.00 @:54 B@:40
Recv:  T:229.94 /230.00 B:60.01 /60.00 @:56 B@:32 W:18
Recv: echo:busy: processing
Recv:  T:229.81 /230.00 B:60.02 /60.00 @:61 B@:29 W:17
Recv:  T:230.00 /230.00 B:60.01 /60.00 @:53 B@:32
Recv:  T:229.75 /230.00 B:60.00 /60.00 @:63 B@:35 W:16
Recv: echo:busy: processing
Recv:  T:229.75 /230.00 B:59.83 /60.00 @:63 B@:91 W:15
Recv:  T:229.63 /230.00 B:60.04 /60.00 @:67 B@:22
Recv:  T:229.75 /230.00 B:60.02 /60.00 @:62 B@:29 W:14
Recv: echo:busy: processing
Recv:  T:229.94 /230.00 B:59.99 /60.00 @:54 B@:39 W:13
Recv:  T:229.44 /230.00 B:60.00 /60.00 @:74 B@:35
Recv:  T:229.88 /230.00 B:60.15 /60.00 @:56 B@:0 W:12
Recv: echo:busy: processing
Recv:  T:229.75 /230.00 B:60.02 /60.00 @:61 B@:28 W:11
Recv:  T:229.75 /230.00 B:59.85 /60.00 @:61 B@:82
Recv:  T:229.63 /230.00 B:59.95 /60.00 @:66 B@:50 W:10
Recv: echo:busy: processing
Recv:  T:229.56 /230.00 B:60.02 /60.00 @:68 B@:28 W:9
Recv:  T:229.69 /230.00 B:60.15 /60.00 @:63 B@:0
Recv:  T:229.75 /230.00 B:60.06 /60.00 @:61 B@:15 W:8
Recv: echo:busy: processing
Recv:  T:229.81 /230.00 B:59.95 /60.00 @:59 B@:50 W:7
Recv:  T:229.88 /230.00 B:60.11 /60.00 @:57 B@:0
Recv:  T:229.63 /230.00 B:60.01 /60.00 @:68 B@:31 W:5
Recv: echo:busy: processing
Recv:  T:229.88 /230.00 B:60.15 /60.00 @:59 B@:0 W:4
Recv:  T:229.94 /230.00 B:60.02 /60.00 @:57 B@:27
Recv:  T:229.88 /230.00 B:59.99 /60.00 @:59 B@:38 W:3
Recv: echo:busy: processing
Recv:  T:230.00 /230.00 B:60.03 /60.00 @:56 B@:24 W:2
Recv:  T:230.00 /230.00 B:60.01 /60.00 @:56 B@:30
Recv:  T:230.13 /230.00 B:60.01 /60.00 @:52 B@:30 W:1
Recv: echo:busy: processing
Recv:  T:230.19 /230.00 B:59.98 /60.00 @:50 B@:41 W:0
Recv:  T:230.00 /230.00 B:59.99 /60.00 @:58 B@:37
Recv: ok
Recv: ok
Changing monitoring state from "Resuming" to "Printing"
Recv: ok
Recv: ok T:230.13 /230.00 B:60.03 /60.00 @:53 B@:23
Send: N19 M82*33
Send: N20 G92 E0*117
Recv: ok
Send: N21 G1 Z0.900 F7800.000*49
Recv: ok
Send: N22 G1 E-2.00000 F1500.00000*0
Recv: X:10.00 Y:0.00 Z:10.00 E:0.00 Count X:800 Y:0 Z:8000
Recv: ok
Send: N23 G92 E0*118
Recv: ok
Send: N24 G1 X20.027 Y25.011 F7800.000*104
Send: N25 M876 S0*94
Recv: ok
Recv: X:10.00 Y:0.00 Z:0.90 E:0.00 Count X:800 Y:0 Z:8000
Recv: ok
Send: N26 G1 E2.00000 F1500.00000*41
Recv: //action:prompt_end
Recv: //action:prompt_begin Paused
Recv: //action:prompt_button PurgeMore
Recv: //action:prompt_button Continue
Recv: //action:prompt_show
Recv: M876 Responding PROMPT_FILAMENT_RUNOUT
Recv: ok
Send: N27 M204 S1000*98
Recv: Error:Line Number is not Last Line Number+1, Last Line: 25
Recv: Resend: 26
Recv: ok
Recv: ok
Send: N26 G1 E2.00000 F1500.00000*41
Recv: Error:Line Number is not Last Line Number+1, Last Line: 25
Recv: Resend: 26
Recv: ok
Send: N27 M204 S1000*98
Recv: ok
Send: N26 G1 E2.00000 F1500.00000*41
Recv: ok
Send: N27 M204 S1000*98
Recv: Error:Line Number is not Last Line Number+1, Last Line: 27
Recv: Resend: 28
Recv: ok
Send: N28 G1 F1800*125
Recv: ok
Send: N29 G1 X21.110 Y24.383 E2.10358*89
Recv: ok

Also, here is my config with the new bugfix if that is needed: Configuration.zip

InsanityAutomation commented 4 years ago

Looking at that log it appears that there was a lost line of communication from octoprint to the printer and then everything got out of sequence and crapped out. I cannot reproduce this from a terminal, can you confirm what octoprint version you are using so I can match it?

stevereno30 commented 4 years ago

I'm on Octoprint 1.4.0 running on Octopi/Raspberry Pi 3b.

I thought this was the problem initially when I first noticed the lost communication, so I enabled NO_TIMEOUTS in configuration_adv. Should I try increasing the value of this beyond 1000 ms?

stevereno30 commented 4 years ago

Have we hit a dead-end?

InsanityAutomation commented 4 years ago

I haven't had open time to get back into it around the day job. Things are in turmoil right now..

boelle commented 4 years ago

@stevereno30 is the issue gone?

stevereno30 commented 4 years ago

@boelle unfortunately no. Within the past four weeks, I reinstalled Octoprint and updated Marlin to the latest bugfix release, but the issue remains. The only way I can recover from a filament runout is to manually enter M108 in Octoprint's terminal. This works, but it makes the "purge more" and "continue" buttons non-functional.

github-actions[bot] commented 4 years ago

This issue is stale because it has been open 30 days with no activity. Remove stale label / comment or this will be closed in 5 days.

stevereno30 commented 4 years ago

So the issue is being labeled stale, but it still exists. Should I re-submit this bug to the tracker?

github-actions[bot] commented 4 years ago

This issue is stale because it has been open 30 days with no activity. Remove stale label / comment or this will be closed in 5 days.

github-actions[bot] commented 4 years ago

This issue has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.