Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

RC5 - Print don't start with pre-heated bed #3624

Closed
edwilliams16 opened this issue Apr 26, 2016 · 61 comments
Closed

RC5 - Print don't start with pre-heated bed #3624

edwilliams16 opened this issue Apr 26, 2016 · 61 comments
Labels
Bug: Potential ? Needs: More Data We need more data in order to proceed
Milestone

Comments

@edwilliams16
Copy link
Contributor

edwilliams16 commented Apr 26, 2016

Gets up to temperature, but then won't count down to start. I preheated for a while before I told S3D to start the print. This is with RC5.

Possible duplicate: #3585

SENT: G90
SENT: M82
SENT: M106 S0
SENT: M140 S95
SENT: M190 S95
RECEIVED: ok
RECEIVED: ok
RECEIVED: ok
RECEIVED: ok
RECEIVED:  T:229.2 /230.0 B:92.7 /95.0 B@:127 @:87
RECEIVED:  T:229.1 /230.0 B:92.8 /95.0 B@:127 @:89
RECEIVED:  T:229.1 /230.0 B:92.8 /95.0 B@:127 @:90
RECEIVED:  T:229.1 /230.0 B:92.9 /95.0 B@:127 @:93
RECEIVED:  T:229.3 /230.0 B:93.0 /95.0 B@:127 @:86
RECEIVED:  T:229.9 /230.0 B:93.0 /95.0 B@:127 @:70
RECEIVED:  T:230.0 /230.0 B:93.1 /95.0 B@:127 @:67
RECEIVED:  T:230.0 /230.0 B:93.1 /95.0 B@:127 @:69
RECEIVED:  T:229.9 /230.0 B:93.2 /95.0 B@:127 @:72
RECEIVED: echo:busy: processing
busy: processing
RECEIVED:  T:230.0 /230.0 B:93.2 /95.0 B@:127 @:71
RECEIVED:  T:230.0 /230.0 B:93.4 /95.0 B@:127 @:71
RECEIVED:  T:230.0 /230.0 B:93.4 /95.0 B@:127 @:72
RECEIVED:  T:230.1 /230.0 B:93.4 /95.0 B@:127 @:70
RECEIVED:  T:230.1 /230.0 B:93.5 /95.0 B@:127 @:70
RECEIVED:  T:230.0 /230.0 B:93.5 /95.0 B@:127 @:73
RECEIVED:  T:230.1 /230.0 B:93.6 /95.0 B@:127 @:70
RECEIVED:  T:230.0 /230.0 B:93.6 /95.0 B@:127 @:73
RECEIVED:  T:230.1 /230.0 B:93.8 /95.0 B@:127 @:71
RECEIVED:  T:230.2 /230.0 B:93.8 /95.0 B@:127 @:68
RECEIVED: echo:busy: processing
busy: processing
RECEIVED:  T:230.0 /230.0 B:93.8 /95.0 B@:127 @:73
RECEIVED:  T:230.4 /230.0 B:93.9 /95.0 B@:127 @:61
RECEIVED:  T:230.5 /230.0 B:93.9 /95.0 B@:127 @:58
RECEIVED:  T:230.5 /230.0 B:94.1 /95.0 B@:127 @:56
RECEIVED:  T:230.5 /230.0 B:94.1 /95.0 B@:127 @:55
RECEIVED:  T:230.6 /230.0 B:94.1 /95.0 B@:127 @:52
RECEIVED:  T:230.3 /230.0 B:94.2 /95.0 B@:127 @:61
RECEIVED:  T:230.2 /230.0 B:94.2 /95.0 B@:127 @:63
RECEIVED:  T:230.0 /230.0 B:94.3 /95.0 B@:125 @:69
RECEIVED:  T:230.0 /230.0 B:94.3 /95.0 B@:127 @:68
RECEIVED: echo:busy: processing
busy: processing
RECEIVED:  T:230.0 /230.0 B:94.4 /95.0 B@:115 @:67
RECEIVED:  T:230.0 /230.0 B:94.5 /95.0 B@:124 @:67
RECEIVED:  T:230.0 /230.0 B:94.5 /95.0 B@:127 @:66
RECEIVED:  T:230.0 /230.0 B:94.6 /95.0 B@:111 @:66
RECEIVED:  T:230.0 /230.0 B:94.6 /95.0 B@:115 @:66
RECEIVED:  T:230.0 /230.0 B:94.6 /95.0 B@:127 @:66
RECEIVED:  T:230.0 /230.0 B:94.7 /95.0 B@:107 @:65
RECEIVED:  T:230.0 /230.0 B:94.7 /95.0 B@:113 @:65
RECEIVED:  T:230.0 /230.0 B:94.7 /95.0 B@:127 @:65
RECEIVED:  T:230.0 /230.0 B:94.8 /95.0 B@:105 @:65
RECEIVED: echo:busy: processing
busy: processing
RECEIVED:  T:230.0 /230.0 B:94.9 /95.0 B@:106 @:65
RECEIVED:  T:230.0 /230.0 B:94.9 /95.0 B@:111 @:65
RECEIVED:  T:229.9 /230.0 B:94.9 /95.0 B@:117 @:67
RECEIVED:  T:230.0 /230.0 B:95.0 /95.0 B@:96 @:65
RECEIVED: ok
SENT: M105
SENT: M104 S230 T0
SENT: M109 S230 T0
RECEIVED: ok T:229.9 /230.0 B:95.0 /95.0 B@:95 @:69
RECEIVED: ok
RECEIVED:  T:229.9 /230.0 B:95.0 /95.0 B@:95 @:69 W:?
RECEIVED:  T:229.8 /230.0 B:95.0 /95.0 B@:95 @:73 W:?
RECEIVED:  T:229.6 /230.0 B:95.0 /95.0 B@:96 @:77 W:?
RECEIVED:  T:229.8 /230.0 B:95.0 /95.0 B@:92 @:72 W:?
RECEIVED:  T:229.3 /230.0 B:95.0 /95.0 B@:95 @:88 W:?
RECEIVED:  T:229.5 /230.0 B:95.0 /95.0 B@:95 @:81 W:?
RECEIVED:  T:229.6 /230.0 B:95.0 /95.0 B@:92 @:77 W:?
RECEIVED:  T:229.7 /230.0 B:95.0 /95.0 B@:94 @:76 W:?
RECEIVED:  T:229.9 /230.0 B:95.0 /95.0 B@:91 @:71 W:?
RECEIVED: echo:busy: processing
busy: processing
RECEIVED:  T:229.9 /230.0 B:95.0 /95.0 B@:93 @:70 W:?
RECEIVED:  T:230.0 /230.0 B:95.1 /95.0 B@:86 @:69 W:?
RECEIVED:  T:230.1 /230.0 B:95.0 /95.0 B@:91 @:67 W:?
RECEIVED:  T:230.0 /230.0 B:95.1 /95.0 B@:84 @:70 W:?
RECEIVED:  T:229.9 /230.0 B:95.0 /95.0 B@:89 @:72 W:?
RECEIVED:  T:230.0 /230.0 B:95.1 /95.0 B@:79 @:70 W:?
RECEIVED:  T:230.0 /230.0 B:95.0 /95.0 B@:86 @:70 W:?
RECEIVED:  T:230.0 /230.0 B:95.1 /95.0 B@:79 @:71 W:?
RECEIVED:  T:230.0 /230.0 B:95.0 /95.0 B@:79 @:71 W:?
RECEIVED:  T:230.0 /230.0 B:95.0 /95.0 B@:83 @:71 W:?
RECEIVED: echo:busy: processing
busy: processing
RECEIVED:  T:230.0 /230.0 B:95.0 /95.0 B@:81 @:71 W:?
RECEIVED:  T:230.0 /230.0 B:95.0 /95.0 B@:83 @:71 W:?
RECEIVED:  T:230.0 /230.0 B:95.0 /95.0 B@:84 @:71 W:?
RECEIVED:  T:230.1 /230.0 B:95.0 /95.0 B@:84 @:69 W:?
RECEIVED:  T:230.1 /230.0 B:95.0 /95.0 B@:83 @:68 W:?
RECEIVED:  T:230.2 /230.0 B:95.0 /95.0 B@:83 @:64 W:?
RECEIVED:  T:230.4 /230.0 B:95.0 /95.0 B@:83 @:59 W:?
RECEIVED:  T:230.1 /230.0 B:95.0 /95.0 B@:85 @:68 W:?
RECEIVED:  T:230.2 /230.0 B:95.0 /95.0 B@:82 @:66 W:?
RECEIVED:  T:230.5 /230.0 B:95.0 /95.0 B@:84 @:53 W:?
RECEIVED: echo:busy: processing
busy: processing
RECEIVED:  T:230.2 /230.0 B:95.0 /95.0 B@:84 @:63 W:?
RECEIVED:  T:230.3 /230.0 B:95.0 /95.0 B@:84 @:60 W:?
RECEIVED:  T:230.3 /230.0 B:95.0 /95.0 B@:84 @:60 W:?
RECEIVED:  T:230.3 /230.0 B:95.0 /95.0 B@:81 @:59 W:?
RECEIVED:  T:230.2 /230.0 B:95.0 /95.0 B@:83 @:63 W:?
RECEIVED:  T:230.1 /230.0 B:95.0 /95.0 B@:83 @:65 W:?
RECEIVED:  T:230.0 /230.0 B:95.0 /95.0 B@:83 @:67 W:?
RECEIVED:  T:230.0 /230.0 B:95.0 /95.0 B@:83 @:67 W:?
RECEIVED:  T:230.0 /230.0 B:95.0 /95.0 B@:85 @:66 W:?
RECEIVED:  T:229.9 /230.0 B:95.0 /95.0 B@:83 @:68 W:?
RECEIVED: echo:busy: processing
busy: processing
RECEIVED:  T:230.0 /230.0 B:95.0 /95.0 B@:81 @:65 W:?
RECEIVED:  T:230.0 /230.0 B:95.0 /95.0 B@:83 @:65 W:?
RECEIVED:  T:229.9 /230.0 B:95.0 /95.0 B@:83 @:67 W:?
RECEIVED:  T:230.0 /230.0 B:95.0 /95.0 B@:80 @:65 W:?
RECEIVED:  T:229.9 /230.0 B:95.0 /95.0 B@:78 @:67 W:?
RECEIVED:  T:230.0 /230.0 B:95.0 /95.0 B@:80 @:65 W:?
RECEIVED:  T:230.0 /230.0 B:95.0 /95.0 B@:80 @:65 W:?
RECEIVED:  T:229.9 /230.0 B:95.0 /95.0 B@:80 @:67 W:?
RECEIVED:  T:230.0 /230.0 B:95.0 /95.0 B@:79 @:65 W:?
RECEIVED:  T:229.7 /230.0 B:95.0 /95.0 B@:79 @:74 W:?
RECEIVED: echo:busy: processing
busy: processing
RECEIVED:  T:229.8 /230.0 B:95.0 /95.0 B@:79 @:70 W:?
RECEIVED:  T:229.8 /230.0 B:95.0 /95.0 B@:77 @:70 W:?
RECEIVED:  T:229.4 /230.0 B:95.0 /95.0 B@:81 @:84 W:?
RECEIVED:  T:229.6 /230.0 B:95.0 /95.0 B@:81 @:77 W:?
RECEIVED:  T:229.5 /230.0 B:95.0 /95.0 B@:81 @:81 W:?
RECEIVED:  T:229.8 /230.0 B:95.0 /95.0 B@:78 @:72 W:?
RECEIVED:  T:229.7 /230.0 B:95.0 /95.0 B@:80 @:76 W:?
RECEIVED:  T:229.9 /230.0 B:95.0 /95.0 B@:81 @:69 W:?
RECEIVED:  T:230.0 /230.0 B:95.0 /95.0 B@:83 @:68 W:?
RECEIVED:  T:230.0 /230.0 B:95.0 /95.0 B@:81 @:68 W:?
RECEIVED: echo:busy: processing
busy: processing
@Blue-Marlin
Copy link
Contributor

Thank you for your report about RC5.
Should already be fixed in RC6 and RCBugFIX. Another test with one of these would be appreciated.

@jbrazio jbrazio changed the title Won't start - similar 3585? RC5 - Print don't start with pre-heated bed Apr 27, 2016
@jbrazio jbrazio added Bug: Potential ? Needs: More Data We need more data in order to proceed labels Apr 27, 2016
@edwilliams16
Copy link
Contributor Author

edwilliams16 commented Apr 27, 2016

It still hangs with RC6 - but in a slightly different way.

SENT: G90
SENT: M82
SENT: M106 S0
SENT: M140 S95
SENT: M190 S95
RECEIVED: ok
RECEIVED: ok
RECEIVED: ok
RECEIVED: ok
RECEIVED:  T:231.3 /230.0 B:57.7 /95.0 B@:127 @:37
RECEIVED:  T:231.3 /230.0 B:57.7 /95.0 B@:127 @:36
...
...
...
RECEIVED: echo:busy: processing
busy: processing
RECEIVED:  T:230.0 /230.0 B:94.9 /95.0 B@:127 @:65
RECEIVED:  T:230.0 /230.0 B:94.9 /95.0 B@:127 @:65
RECEIVED: ok
SENT: M105
RECEIVED: ok T:230.0 /230.0 B:95.0 /95.0 B@:127 @:65
       hangs here, with no further output and unresponsive to input.

@edwilliams16
Copy link
Contributor Author

I accidentally closed this.

@edwilliams16
Copy link
Contributor Author

edwilliams16 commented Apr 27, 2016

Here's from the log of a cold start. It looks like the problem is when the extruder is already preheated to temperature. From a cold start, the bed is heated first and the W:? countdown is initialized. When the extruder gets to temperature W: counts down and the print starts OK.
In the log above when bed reaches the target, and the extruder is already on temperature the countdown isn't triggered.

RECEIVED:  T:27.0 /0.0 B:94.3 /95.0 B@:127 @:0
RECEIVED:  T:27.0 /0.0 B:94.3 /95.0 B@:127 @:0
RECEIVED: echo:busy: processing
busy: processing
RECEIVED:  T:27.0 /0.0 B:94.5 /95.0 B@:127 @:0
RECEIVED:  T:27.0 /0.0 B:94.5 /95.0 B@:127 @:0
RECEIVED: echo:busy: processing
busy: processing
RECEIVED:  T:27.0 /0.0 B:94.5 /95.0 B@:127 @:0
RECEIVED:  T:27.0 /0.0 B:94.6 /95.0 B@:127 @:0
RECEIVED: echo:busy: processing
busy: processing
RECEIVED:  T:27.0 /0.0 B:94.6 /95.0 B@:127 @:0
RECEIVED:  T:27.0 /0.0 B:94.6 /95.0 B@:127 @:0
RECEIVED: echo:busy: processing
busy: processing
RECEIVED:  T:27.0 /0.0 B:94.7 /95.0 B@:127 @:0
RECEIVED:  T:27.1 /0.0 B:94.7 /95.0 B@:127 @:0
RECEIVED: echo:busy: processing
busy: processing
RECEIVED:  T:27.0 /0.0 B:94.9 /95.0 B@:127 @:0
RECEIVED:  T:27.0 /0.0 B:94.9 /95.0 B@:127 @:0
RECEIVED: echo:busy: processing
busy: processing
RECEIVED:  T:27.1 /0.0 B:94.9 /95.0 B@:127 @:0
RECEIVED: ok
SENT: M105
RECEIVED: ok T:27.2 /0.0 B:95.0 /95.0 B@:127 @:0
RECEIVED: ok T:27.2 /0.0 B:95.0 /95.0 B@:127 @:0
SENT: M104 S230 T0
SENT: M109 S230 T0
RECEIVED: ok
RECEIVED:  T:27.2 /230.0 B:95.0 /95.0 B@:127 @:0 W:?
RECEIVED:  T:27.2 /230.0 B:95.0 /95.0 B@:127 @:127 W:?
RECEIVED:  T:27.5 /230.0 B:95.1 /95.0 B@:0 @:127 W:?
RECEIVED: echo:busy: processing
busy: processing
RECEIVED:  T:27.5 /230.0 B:95.1 /95.0 B@:0 @:127 W:?
RECEIVED:  T:28.0 /230.0 B:95.0 /95.0 B@:0 @:127 W:?
RECEIVED: echo:busy: processing
busy: processing
RECEIVED:  T:28.5 /230.0 B:94.8 /95.0 B@:0 @:127 W:?
RECEIVED:  T:29.1 /230.0 B:94.6 /95.0 B@:0 @:127 W:?
RECEIVED: echo:busy: processing
busy: processing
RECEIVED:  T:30.0 /230.0 B:94.3 /95.0 B@:127 @:127 W:?
RECEIVED:  T:31.0 /230.0 B:94.1 /95.0 B@:127 @:127 W:?
RECEIVED: echo:busy: processing
busy: processing
RECEIVED:  T:32.1 /230.0 B:93.9 /95.0 B@:127 @:127 W:?
RECEIVED:  T:33.1 /230.0 B:94.1 /95.0 B@:127 @:127 W:?
RECEIVED: echo:busy: processing
busy: processing
...
...
...
RECEIVED:  T:227.0 /230.0 B:95.4 /95.0 B@:0 @:90 W:?
RECEIVED:  T:228.0 /230.0 B:95.2 /95.0 B@:0 @:73 W:?
RECEIVED: echo:busy: processing
busy: processing
RECEIVED:  T:228.3 /230.0 B:95.0 /95.0 B@:0 @:77 W:?
RECEIVED:  T:229.0 /230.0 B:94.8 /95.0 B@:0 @:65 W:?
RECEIVED: echo:busy: processing
busy: processing
RECEIVED:  T:229.1 /230.0 B:94.6 /95.0 B@:0 @:70 W:9
RECEIVED:  T:230.0 /230.0 B:94.3 /95.0 B@:0 @:50 W:8
RECEIVED: echo:busy: processing
busy: processing
RECEIVED:  T:230.0 /230.0 B:94.1 /95.0 B@:0 @:59 W:7
RECEIVED:  T:230.0 /230.0 B:93.9 /95.0 B@:127 @:64 W:6
RECEIVED: echo:busy: processing
busy: processing
RECEIVED:  T:230.1 /230.0 B:93.7 /95.0 B@:127 @:65 W:5
RECEIVED:  T:231.3 /230.0 B:93.6 /95.0 B@:127 @:32 W:4
RECEIVED: echo:busy: processing
busy: processing
RECEIVED:  T:231.3 /230.0 B:93.6 /95.0 B@:127 @:34 W:3
RECEIVED:  T:231.3 /230.0 B:93.8 /95.0 B@:127 @:36 W:2
RECEIVED: echo:busy: processing
busy: processing
RECEIVED:  T:231.3 /230.0 B:93.9 /95.0 B@:127 @:37 W:1
RECEIVED:  T:231.3 /230.0 B:94.1 /95.0 B@:127 @:37 W:0
RECEIVED: echo:busy: processing
busy: processing
RECEIVED: ok
SENT: M105
SENT: G28 
SENT: G92 E0
SENT: G1 E-1.0000 F1800
SENT: G1 Z0.180 F1000
SENT: T0
RECEIVED: ok T:231.3 /230.0 B:94.2 /95.0 B@:127 @:37
RECEIVED: echo:busy: processing
busy: processing
RECEIVED: echo:busy: processing
busy: processing
RECEIVED: echo:busy: processing
busy: processing
RECEIVED: echo:busy: processing
busy: processing
RECEIVED: echo:busy: processing
busy: processing
RECEIVED: echo:busy: processing
busy: processing
RECEIVED: echo:busy: processing
busy: processing
RECEIVED: echo:busy: processing
busy: processing
RECEIVED: echo:busy: processing
busy: processing
RECEIVED: echo:busy: processing
busy: processing
RECEIVED: echo:busy: processing
busy: processing
RECEIVED: echo:busy: processing
busy: processing
RECEIVED: echo:busy: processing
busy: processing
RECEIVED: echo:busy: processing
busy: processing
RECEIVED: X:0.00 Y:0.00 Z:0.00 E:0.00 Count X: 0 Y:0 Z:0
RECEIVED: ok
SENT: M105
RECEIVED: ok
RECEIVED: ok
SENT: G1 X98.712 Y85.785 F4800
RECEIVED: ok
SENT: G1 E0.0000 F540
SENT: G92 E0
RECEIVED: echo:Active Extruder: 0
Active Extruder: 0
RECEIVED: ok
RECEIVED: ok T:230.9 /230.0 B:94.9 /95.0 B@:0 @:47
RECEIVED: ok
SENT: G1 X99.697 Y84.801 E0.0589 F1800
RECEIVED: ok
RECEIVED: ok
SENT: G1 X121.088 Y84.801 E0.9639
RECEIVED: ok
SENT: G1 X121.167 Y84.880 E0.9686

@Blue-Marlin
Copy link
Contributor

Blue-Marlin commented Apr 27, 2016

Are you sure you are on RC6 or newer?
Your M190 does not display the "W:" at all.
What we see with "W:" is M109.
Your bed now is in bang-bang mode - not in PID anymore.
My tests are ok for all 6 cases with today's RCBugFix

01:07:58.520 : N77 M105*23
01:07:58.536 : ok T:21.9 /0.0 B:75.0 /75.0 B@:37 @:0
01:08:07.253 : N78 M190 R75*100      // same temperature R
01:08:07.268 : T:22.1 /0.0 B:75.0 /75.0 B@:37 @:0 W:?
01:08:08.268 : T:22.1 /0.0 B:75.0 /75.0 B@:37 @:0 W:9
01:08:09.268 : T:22.0 /0.0 B:75.0 /75.0 B@:37 @:0 W:8
01:08:09.268 : echo:busy: processing
01:08:10.268 : T:22.0 /0.0 B:75.0 /75.0 B@:37 @:0 W:7
01:08:11.267 : T:22.1 /0.0 B:75.0 /75.0 B@:40 @:0 W:6
01:08:11.267 : echo:busy: processing
01:08:12.265 : T:22.1 /0.0 B:75.0 /75.0 B@:36 @:0 W:5
01:08:13.265 : T:22.2 /0.0 B:75.0 /75.0 B@:36 @:0 W:4
01:08:13.265 : echo:busy: processing
01:08:14.264 : T:22.1 /0.0 B:75.0 /75.0 B@:36 @:0 W:3
01:08:15.264 : T:22.1 /0.0 B:75.0 /75.0 B@:40 @:0 W:2
01:08:15.264 : echo:busy: processing
01:08:16.263 : T:22.1 /0.0 B:75.0 /75.0 B@:36 @:0 W:1
01:08:17.262 : T:22.1 /0.0 B:75.0 /75.0 B@:36 @:0 W:0
01:08:17.262 : echo:busy: processing
01:08:17.262 : ok N78 P15 B3
01:08:17.264 : N79 M105*25
01:08:17.279 : ok T:22.1 /0.0 B:75.0 /75.0 B@:36 @:0
01:08:18.611 : N80 M105*31
01:08:18.629 : ok T:22.4 /0.0 B:75.0 /75.0 B@:40 @:0
01:08:21.149 : N81 M190 S75*99      // same temperature S
01:08:21.165 : T:22.3 /0.0 B:75.0 /75.0 B@:37 @:0 W:?
01:08:22.164 : T:22.3 /0.0 B:75.0 /75.0 B@:37 @:0 W:9
01:08:23.164 : T:22.3 /0.0 B:75.0 /75.0 B@:37 @:0 W:8
01:08:23.164 : echo:busy: processing
01:08:24.164 : T:22.3 /0.0 B:75.0 /75.0 B@:43 @:0 W:7
01:08:25.164 : T:22.2 /0.0 B:75.0 /75.0 B@:36 @:0 W:6
01:08:25.164 : echo:busy: processing
01:08:26.162 : T:22.3 /0.0 B:75.0 /75.0 B@:36 @:0 W:5
01:08:27.162 : T:22.4 /0.0 B:75.0 /75.0 B@:36 @:0 W:4
01:08:27.162 : echo:busy: processing
01:08:28.163 : T:22.3 /0.0 B:75.0 /75.0 B@:36 @:0 W:3
01:08:29.161 : T:22.4 /0.0 B:75.0 /75.0 B@:37 @:0 W:2
01:08:29.161 : echo:busy: processing
01:08:30.160 : T:22.4 /0.0 B:75.0 /75.0 B@:37 @:0 W:1
01:08:31.160 : T:22.3 /0.0 B:75.0 /75.0 B@:37 @:0 W:0
01:08:31.160 : echo:busy: processing
01:08:31.160 : ok N81 P15 B3
01:08:31.160 : N82 M105*29
01:08:31.175 : ok T:22.3 /0.0 B:75.0 /75.0 B@:37 @:0
01:08:37.501 : N83 M190 S72*102           // down 3° with S
01:08:37.505 : ok N83 P15 B3
01:08:38.705 : N84 M105*27
01:08:38.720 : ok T:22.4 /0.0 B:75.0 /72.0 B@:0 @:0
01:08:48.751 : N85 M105*26
01:08:48.767 : ok T:22.5 /0.0 B:74.5 /72.0 B@:0 @:0 
01:08:50.884 : N86 M190 R72*98           // down 2.5° with R
01:08:50.901 : T:22.5 /0.0 B:74.4 /72.0 B@:0 @:0 W:?
01:08:51.901 : T:22.5 /0.0 B:74.3 /72.0 B@:0 @:0 W:?
01:08:52.884 : echo:busy: processing
01:08:52.899 : T:22.5 /0.0 B:74.2 /72.0 B@:0 @:0 W:?
01:08:53.898 : T:22.5 /0.0 B:74.0 /72.0 B@:0 @:0 W:?
01:08:54.898 : T:22.5 /0.0 B:74.0 /72.0 B@:0 @:0 W:?
01:08:54.898 : echo:busy: processing
01:08:55.898 : T:22.5 /0.0 B:73.9 /72.0 B@:0 @:0 W:?
01:08:56.897 : T:22.5 /0.0 B:73.7 /72.0 B@:0 @:0 W:?
01:08:56.897 : echo:busy: processing
01:08:57.896 : T:22.5 /0.0 B:73.7 /72.0 B@:0 @:0 W:?
01:08:58.896 : T:22.5 /0.0 B:73.5 /72.0 B@:0 @:0 W:?
01:08:58.896 : echo:busy: processing
01:08:59.896 : T:22.5 /0.0 B:73.5 /72.0 B@:0 @:0 W:?
01:09:00.894 : T:22.5 /0.0 B:73.4 /72.0 B@:0 @:0 W:?
01:09:00.894 : echo:busy: processing
01:09:01.894 : T:22.5 /0.0 B:73.2 /72.0 B@:0 @:0 W:?
01:09:02.893 : T:22.5 /0.0 B:73.2 /72.0 B@:0 @:0 W:?
01:09:02.893 : echo:busy: processing
01:09:03.893 : T:22.5 /0.0 B:73.1 /72.0 B@:0 @:0 W:?
01:09:04.897 : T:22.5 /0.0 B:73.0 /72.0 B@:0 @:0 W:9
01:09:04.897 : echo:busy: processing
01:09:05.892 : T:22.5 /0.0 B:72.9 /72.0 B@:0 @:0 W:8
01:09:06.896 : T:22.5 /0.0 B:72.7 /72.0 B@:0 @:0 W:7
01:09:06.896 : echo:busy: processing
01:09:07.896 : T:22.5 /0.0 B:72.7 /72.0 B@:0 @:0 W:6
01:09:08.893 : T:22.5 /0.0 B:72.6 /72.0 B@:0 @:0 W:5
01:09:08.893 : echo:busy: processing
01:09:09.893 : T:22.5 /0.0 B:72.4 /72.0 B@:32 @:0 W:4
01:09:10.892 : T:22.5 /0.0 B:72.4 /72.0 B@:16 @:0 W:3
01:09:10.892 : echo:busy: processing
01:09:11.892 : T:22.5 /0.0 B:72.3 /72.0 B@:44 @:0 W:2
01:09:12.891 : T:22.5 /0.0 B:72.2 /72.0 B@:58 @:0 W:1
01:09:12.891 : echo:busy: processing
01:09:13.891 : T:22.5 /0.0 B:72.1 /72.0 B@:60 @:0 W:0
01:09:14.707 : ok N86 P15 B3
01:09:14.707 : N87 M105*24
01:09:14.721 : ok T:22.5 /0.0 B:72.1 /72.0 B@:49 @:0
01:09:18.045 : N88 M190 R75*107              // up 3° with R
01:09:18.063 : T:22.5 /0.0 B:71.9 /75.0 B@:61 @:0 W:?
01:09:19.059 : T:22.5 /0.0 B:71.9 /75.0 B@:127 @:0 W:?
01:09:20.059 : T:22.5 /0.0 B:71.9 /75.0 B@:127 @:0 W:?
01:09:20.059 : echo:busy: processing
01:09:21.058 : T:22.5 /0.0 B:71.9 /75.0 B@:127 @:0 W:?
01:09:22.046 : echo:busy: processing
01:09:22.061 : T:22.5 /0.0 B:71.9 /75.0 B@:127 @:0 W:?
01:09:23.061 : T:22.5 /0.0 B:72.1 /75.0 B@:127 @:0 W:?
01:09:24.045 : echo:busy: processing
01:09:24.060 : T:22.5 /0.0 B:72.1 /75.0 B@:127 @:0 W:?
01:09:25.060 : T:22.5 /0.0 B:72.3 /75.0 B@:127 @:0 W:?
01:09:26.044 : echo:busy: processing
01:09:26.061 : T:22.5 /0.0 B:72.4 /75.0 B@:127 @:0 W:?
01:09:27.058 : T:22.5 /0.0 B:72.4 /75.0 B@:127 @:0 W:?
01:09:28.043 : echo:busy: processing
01:09:28.058 : T:22.5 /0.0 B:72.6 /75.0 B@:127 @:0 W:?
01:09:29.058 : T:22.5 /0.0 B:72.7 /75.0 B@:127 @:0 W:?
01:09:30.045 : echo:busy: processing
01:09:30.056 : T:22.5 /0.0 B:72.9 /75.0 B@:127 @:0 W:?
01:09:31.056 : T:22.5 /0.0 B:73.1 /75.0 B@:127 @:0 W:?
01:09:32.045 : echo:busy: processing
01:09:32.055 : T:22.5 /0.0 B:73.3 /75.0 B@:127 @:0 W:?
01:09:33.056 : T:22.5 /0.0 B:73.5 /75.0 B@:127 @:0 W:?
01:09:34.054 : T:22.5 /0.0 B:73.7 /75.0 B@:121 @:0 W:?
01:09:34.054 : echo:busy: processing
01:09:35.054 : T:22.5 /0.0 B:73.9 /75.0 B@:103 @:0 W:?
01:09:36.053 : T:22.5 /0.0 B:74.0 /75.0 B@:90 @:0 W:9
01:09:36.053 : echo:busy: processing
01:09:37.053 : T:22.5 /0.0 B:74.2 /75.0 B@:69 @:0 W:8
01:09:38.051 : T:22.5 /0.0 B:74.5 /75.0 B@:16 @:0 W:7
01:09:38.051 : echo:busy: processing
01:09:39.051 : T:22.5 /0.0 B:74.7 /75.0 B@:0 @:0 W:6
01:09:40.051 : T:22.5 /0.0 B:74.8 /75.0 B@:0 @:0 W:5
01:09:40.051 : echo:busy: processing
01:09:41.052 : T:22.5 /0.0 B:75.0 /75.0 B@:0 @:0 W:4
01:09:42.048 : T:22.5 /0.0 B:75.0 /75.0 B@:0 @:0 W:3
01:09:42.048 : echo:busy: processing
01:09:43.052 : T:22.5 /0.0 B:75.2 /75.0 B@:0 @:0 W:2
01:09:44.048 : T:22.5 /0.0 B:75.3 /75.0 B@:0 @:0 W:1
01:09:44.048 : echo:busy: processing
01:09:45.050 : T:22.5 /0.0 B:75.3 /75.0 B@:0 @:0 W:0
01:09:45.564 : ok N88 P15 B3
01:09:45.564 : N89 M105*22
01:09:45.579 : ok T:22.5 /0.0 B:75.3 /75.0 B@:0 @:0
01:09:49.034 : N90 M105*30
01:09:49.048 : ok T:22.5 /0.0 B:75.3 /75.0 B@:0 @:0
01:09:49.973 : N91 M190 S77*97               // up 2° with S
01:09:49.991 : T:22.5 /0.0 B:75.3 /77.0 B@:0 @:0 W:?
01:09:50.989 : T:22.5 /0.0 B:75.3 /77.0 B@:127 @:0 W:?
01:09:51.974 : echo:busy: processing
01:09:51.989 : T:22.5 /0.0 B:75.2 /77.0 B@:127 @:0 W:?
01:09:52.988 : T:22.5 /0.0 B:75.2 /77.0 B@:127 @:0 W:?
01:09:53.988 : T:22.5 /0.0 B:75.2 /77.0 B@:127 @:0 W:?
01:09:53.988 : echo:busy: processing
01:09:54.986 : T:22.5 /0.0 B:75.2 /77.0 B@:127 @:0 W:?
01:09:55.987 : T:22.5 /0.0 B:75.3 /77.0 B@:127 @:0 W:?
01:09:55.987 : echo:busy: processing
01:09:56.986 : T:22.5 /0.0 B:75.3 /77.0 B@:127 @:0 W:?
01:09:57.987 : T:22.5 /0.0 B:75.4 /77.0 B@:127 @:0 W:?
01:09:57.987 : echo:busy: processing
01:09:58.985 : T:22.5 /0.0 B:75.5 /77.0 B@:127 @:0 W:?
01:09:59.985 : T:22.5 /0.0 B:75.6 /77.0 B@:127 @:0 W:?
01:09:59.985 : echo:busy: processing
01:10:00.983 : T:22.5 /0.0 B:75.7 /77.0 B@:127 @:0 W:?
01:10:01.983 : T:22.5 /0.0 B:75.8 /77.0 B@:127 @:0 W:?
01:10:01.983 : echo:busy: processing
01:10:02.982 : T:22.5 /0.0 B:75.9 /77.0 B@:127 @:0 W:?
01:10:03.982 : T:22.5 /0.0 B:76.1 /77.0 B@:127 @:0 W:9
01:10:03.982 : echo:busy: processing
01:10:04.983 : T:22.5 /0.0 B:76.2 /77.0 B@:124 @:0 W:8
01:10:05.981 : T:22.5 /0.0 B:76.4 /77.0 B@:101 @:0 W:7
01:10:05.981 : echo:busy: processing
01:10:06.980 : T:22.5 /0.0 B:76.5 /77.0 B@:79 @:0 W:6
01:10:07.980 : T:22.5 /0.0 B:76.7 /77.0 B@:54 @:0 W:5
01:10:07.980 : echo:busy: processing
01:10:08.978 : T:22.5 /0.0 B:76.8 /77.0 B@:31 @:0 W:4
01:10:09.978 : T:22.5 /0.0 B:77.1 /77.0 B@:0 @:0 W:3
01:10:09.978 : echo:busy: processing
01:10:10.976 : T:22.5 /0.0 B:77.1 /77.0 B@:0 @:0 W:2
01:10:11.982 : T:22.5 /0.0 B:77.3 /77.0 B@:0 @:0 W:1
01:10:11.982 : echo:busy: processing
01:10:12.976 : T:22.5 /0.0 B:77.4 /77.0 B@:0 @:0 W:0
01:10:13.272 : ok N91 P15 B3
01:10:13.272 : N92 M105*28
01:10:13.311 : ok T:22.5 /0.0 B:77.4 /77.0 B@:0 @:0
01:10:19.169 : N93 M105*29
01:10:19.184 : ok T:22.5 /0.0 B:77.4 /77.0 B@:0 @:0
01:10:24.713 : N94 M104 T0 S0*28

Also tested M109 and M109 with pre heated bed. All without problems.
Even switching the bed to bang-bang did not make a difference.

Or, maybe, you just copied your old config over to RC6?

@edwilliams16
Copy link
Contributor Author

I'm on
Marlin 1.1.0-RC6 - 24 April 2016

I'm not sure how I switched back to bang-bang on the bed - missed a change on Configuration.h I presume. However, when I tried to do an autotune, I got:
SENT: M303 E-1 C5 S95
RECEIVED: PID Autotune failed! Bad extruder number

which puzzles me.

@edwilliams16
Copy link
Contributor Author

I'll go back to PID on the bed and see what happens.

@Blue-Marlin
Copy link
Contributor

Blue-Marlin commented Apr 28, 2016

If your bed is in bang-bang mode you can't tune PID for the bed.

@edwilliams16
Copy link
Contributor Author

edwilliams16 commented Apr 28, 2016

OK. I had failed to enable PID on the bed when I was editing Configuration.h. I'm testing now with it on.
Should I be concerned about this?

RECEIVED: echo:  M200 D0
  Testing plaintext communication protocol...
  Testing binary communication protocol...
RECEIVED: echo:SD init fail
RECEIVED: ok
  Connected to machine!
SENT: T0
WARNING: CRC mismatch detected

@Blue-Marlin
Copy link
Contributor

A missing or 0 TEMP_BED_RESIDENCY_TIME would explain the missing "W:"

@Blue-Marlin
Copy link
Contributor

What is your Arduino IDE version?

@edwilliams16
Copy link
Contributor Author

edwilliams16 commented Apr 28, 2016

Arduino 1.6.8

#define TEMP_BED_RESIDENCY_TIME 0   // (seconds)
#define TEMP_BED_HYSTERESIS 3       // (degC) range of +/- temperatures considered "close" to the target one
#define TEMP_BED_WINDOW     1       // (degC) Window around target to start the residency timer x degC early.

@edwilliams16
Copy link
Contributor Author

edwilliams16 commented Apr 28, 2016

Here's some "correct" behavior with no preheating.

Attempting connection at /dev/cu.usbmodem621...
RECEIVED: start
  Connected to machine!
RECEIVED: echo:Marlin 1.1.0-RC6
Marlin 1.1.0-RC6
SENT: T0
RECEIVED: echo: Last Updated: 2016-04-24 12:00 | Author: (EAW, 16t single ex RC6)
Last Updated: 2016-04-24 12:00 | Author: (EAW, 16t single ex RC6)
RECEIVED: Compiled: Apr 27 2016
RECEIVED: echo: Free Memory: 3192  PlannerBufferBytes: 1232
Free Memory: 3192  PlannerBufferBytes: 1232
RECEIVED: echo:Hardcoded Default Settings Loaded
Hardcoded Default Settings Loaded
RECEIVED: echo:Steps per unit:
Steps per unit:
RECEIVED: echo:  M92 X100.00 Y50.00 Z1600.00 E76.00
M92 X100.00 Y50.00 Z1600.00 E76.00
RECEIVED: echo:Maximum feedrates (mm/s):
Maximum feedrates (mm/s):
RECEIVED: echo:  M203 X500.00 Y500.00 Z5.00 E25.00
M203 X500.00 Y500.00 Z5.00 E25.00
RECEIVED: echo:Maximum Acceleration (mm/s2):
Maximum Acceleration (mm/s2):
RECEIVED: echo:  M201 X800 Y800 Z100 E10000
M201 X800 Y800 Z100 E10000
RECEIVED: echo:Accelerations: P=printing, R=retract and T=travel
Accelerations: P=printing, R=retract and T=travel
RECEIVED: echo:  M204 P600.00 R1000.00 T3000.00
M204 P600.00 R1000.00 T3000.00
RECEIVED: echo:Advanced variables: S=Min feedrate (mm/s), T=Min travel feedrate (mm/s), B=minimum segment time (ms), X=maximum XY jerk (mm/s),  Z=maximum Z jerk (mm/s),  E=maximum E jerk (mm/s)
Advanced variables: S=Min feedrate (mm/s), T=Min travel feedrate (mm/s), B=minimum segment time (ms), X=maximum XY jerk (mm/s),  Z=maximum Z jerk (mm/s),  E=maximum E jerk (mm/s)
RECEIVED: echo:  M205 S0.00 T0.00 B20000 X8.00 Z0.40 E5.00
M205 S0.00 T0.00 B20000 X8.00 Z0.40 E5.00
RECEIVED: echo:Home offset (mm):
Home offset (mm):
RECEIVED: echo:  M206 X0.00 Y0.00 Z0.00
M206 X0.00 Y0.00 Z0.00
RECEIVED: echo:Material heatup parameters:
Material heatup parameters:
RECEIVED: echo:  M145 S0 H180 B70 F255
M145 S0 H180 B70 F255
RECEIVED: echo:  M145 S1 H240 B110 F255
M145 S1 H240 B110 F255
RECEIVED: echo:PID settings:
PID settings:
RECEIVED: echo:  M301 P38.60 I3.96 D94.20 C100.00 L20
M301 P38.60 I3.96 D94.20 C100.00 L20
RECEIVED: echo:  M304 P355.00 I66.50 D480.00
M304 P355.00 I66.50 D480.00
RECEIVED: echo:Filament settings: Disabled
Filament settings: Disabled
RECEIVED: echo:  M200 D3.00
M200 D3.00
RECEIVED: echo:  M200 D0
M200 D0
SENT: M105
SENT: M105
RECEIVED: echo:SD init fail
SD init fail
RECEIVED: echo:Active Extruder: 0
Active Extruder: 0
RECEIVED: ok
RECEIVED: ok T:226.8 /0.0 B:91.9 /0.0 B@:0 @:0
RECEIVED: ok T:225.0 /0.0 B:91.5 /0.0 B@:0 @:0
SENT: M105
RECEIVED: ok T:224.0 /0.0 B:91.4 /0.0 B@:0 @:0
SENT: M105
RECEIVED: ok T:223.0 /0.0 B:90.9 /0.0 B@:0 @:0
SENT: M105
RECEIVED: ok T:221.0 /0.0 B:90.7 /0.0 B@:0 @:0
SENT: M105
RECEIVED: ok T:219.5 /0.0 B:90.3 /0.0 B@:0 @:0
SENT: M105
RECEIVED: ok T:218.3 /0.0 B:90.0 /0.0 B@:0 @:0
SENT: G90
SENT: M82
SENT: M106 S0
SENT: M140 S95
SENT: M190 S95
RECEIVED: ok
RECEIVED: ok
RECEIVED: ok
RECEIVED: ok
RECEIVED:  T:217.5 /0.0 B:89.9 /95.0 B@:0 @:0
RECEIVED:  T:216.7 /0.0 B:89.6 /95.0 B@:127 @:0
RECEIVED: echo:busy: processing
busy: processing
RECEIVED:  T:215.8 /0.0 B:89.6 /95.0 B@:127 @:0
RECEIVED:  T:215.0 /0.0 B:89.7 /95.0 B@:127 @:0
RECEIVED: echo:busy: processing
busy: processing
RECEIVED:  T:214.2 /0.0 B:90.0 /95.0 B@:127 @:0
RECEIVED:  T:213.3 /0.0 B:90.2 /95.0 B@:127 @:0
RECEIVED: echo:busy: processing
busy: processing
RECEIVED:  T:212.5 /0.0 B:90.4 /95.0 B@:127 @:0
RECEIVED:  T:211.7 /0.0 B:90.7 /95.0 B@:127 @:0
RECEIVED: echo:busy: processing
busy: processing
RECEIVED:  T:210.8 /0.0 B:90.9 /95.0 B@:127 @:0
RECEIVED:  T:210.0 /0.0 B:91.1 /95.0 B@:127 @:0
RECEIVED: echo:busy: processing
busy: processing
RECEIVED:  T:209.2 /0.0 B:91.4 /95.0 B@:127 @:0
RECEIVED:  T:208.4 /0.0 B:91.6 /95.0 B@:127 @:0
RECEIVED: echo:busy: processing
busy: processing
RECEIVED:  T:207.4 /0.0 B:91.8 /95.0 B@:127 @:0
RECEIVED:  T:206.6 /0.0 B:92.0 /95.0 B@:127 @:0
RECEIVED: echo:busy: processing
busy: processing
RECEIVED:  T:205.8 /0.0 B:92.2 /95.0 B@:127 @:0
RECEIVED:  T:205.0 /0.0 B:92.4 /95.0 B@:127 @:0
RECEIVED: echo:busy: processing
busy: processing
RECEIVED:  T:204.3 /0.0 B:92.6 /95.0 B@:127 @:0
RECEIVED:  T:203.5 /0.0 B:92.8 /95.0 B@:127 @:0
RECEIVED: echo:busy: processing
busy: processing
RECEIVED:  T:202.6 /0.0 B:93.0 /95.0 B@:127 @:0
RECEIVED:  T:201.4 /0.0 B:93.1 /95.0 B@:127 @:0
RECEIVED: echo:busy: processing
busy: processing
RECEIVED:  T:200.7 /0.0 B:93.3 /95.0 B@:127 @:0
RECEIVED:  T:200.0 /0.0 B:93.5 /95.0 B@:127 @:0
RECEIVED: echo:busy: processing
busy: processing
RECEIVED:  T:199.3 /0.0 B:93.6 /95.0 B@:127 @:0
RECEIVED:  T:198.4 /0.0 B:93.8 /95.0 B@:127 @:0
RECEIVED: echo:busy: processing
busy: processing
RECEIVED:  T:197.9 /0.0 B:93.9 /95.0 B@:127 @:0
RECEIVED:  T:197.2 /0.0 B:94.1 /95.0 B@:127 @:0
RECEIVED: echo:busy: processing
busy: processing
RECEIVED:  T:196.3 /0.0 B:94.3 /95.0 B@:127 @:0
RECEIVED:  T:195.8 /0.0 B:94.5 /95.0 B@:127 @:0
RECEIVED: echo:busy: processing
busy: processing
RECEIVED:  T:194.9 /0.0 B:94.6 /95.0 B@:127 @:0
RECEIVED:  T:194.2 /0.0 B:94.7 /95.0 B@:106 @:0
RECEIVED: echo:busy: processing
busy: processing
RECEIVED:  T:193.7 /0.0 B:94.9 /95.0 B@:94 @:0
RECEIVED: ok
SENT: M105
SENT: M104 S230 T0
SENT: M109 S230 T0
RECEIVED: ok T:192.8 /0.0 B:95.0 /95.0 B@:72 @:0
RECEIVED: ok
RECEIVED:  T:192.8 /230.0 B:95.0 /95.0 B@:72 @:0 W:?
RECEIVED:  T:192.1 /230.0 B:95.0 /95.0 B@:69 @:127 W:?
RECEIVED:  T:191.3 /230.0 B:95.1 /95.0 B@:56 @:127 W:?
RECEIVED: echo:busy: processing
busy: processing
...
...
RECEIVED:  T:229.0 /230.0 B:95.0 /95.0 B@:74 @:69 W:?
RECEIVED:  T:229.5 /230.0 B:95.0 /95.0 B@:74 @:64 W:9
RECEIVED: echo:busy: processing
busy: processing
RECEIVED:  T:230.0 /230.0 B:95.0 /95.0 B@:74 @:57 W:8
RECEIVED:  T:230.2 /230.0 B:95.0 /95.0 B@:76 @:59 W:7
RECEIVED: echo:busy: processing
busy: processing
RECEIVED:  T:231.3 /230.0 B:95.0 /95.0 B@:74 @:29 W:6
RECEIVED: echo:busy: processing
busy: processing
RECEIVED:  T:231.3 /230.0 B:95.0 /95.0 B@:76 @:34 W:5
RECEIVED:  T:231.3 /230.0 B:95.0 /95.0 B@:70 @:37 W:4
RECEIVED: echo:busy: processing
busy: processing
RECEIVED:  T:231.3 /230.0 B:95.0 /95.0 B@:72 @:39 W:3
RECEIVED:  T:231.5 /230.0 B:95.0 /95.0 B@:72 @:32 W:2
RECEIVED: echo:busy: processing
busy: processing
RECEIVED:  T:231.5 /230.0 B:95.0 /95.0 B@:74 @:32 W:1
RECEIVED:  T:231.6 /230.0 B:95.0 /95.0 B@:71 @:27 W:0
RECEIVED: ok
SENT: M105
SENT: G28 
SENT: G92 E0
SENT: G1 E-1.0000 F1800
SENT: G1 Z0.180 F1000
SENT: T0
RECEIVED: ok T:231.4 /230.0 B:95.0 /95.0 B@:69 @:34

@edwilliams16
Copy link
Contributor Author

I've had several tries reproducing the non-start behavior with PID bed heating with RC-6 and so far it hasn't shown up. I'll let you know if/when it happens again.

@edwilliams16
Copy link
Contributor Author

edwilliams16 commented Apr 28, 2016

I had sent commands to preheat the bed and the extruder, then started the print. This time it locked up when the bed reached target.
Not all the history is available. Can I make S3D's communication buffer bigger?

SENT: G90
SENT: M82
SENT: M106 S0
SENT: M140 S75
SENT: M190 S75
RECEIVED: ok
RECEIVED: ok
RECEIVED: ok
RECEIVED: ok
RECEIVED:  T:230.2 /230.0 B:63.5 /75.0 B@:127 @:68
RECEIVED:  T:230.2 /230.0 B:63.5 /75.0 B@:127 @:66
RECEIVED:  T:230.6 /230.0 B:63.7 /75.0 B@:127 @:54
RECEIVED: echo:busy: processing
busy: processing
RECEIVED:  T:230.6 /230.0 B:63.7 /75.0 B@:127 @:55
RECEIVED:  T:231.2 /230.0 B:63.9 /75.0 B@:127 @:38
RECEIVED: echo:busy: processing
busy: processing
RECEIVED:  T:231.3 /230.0 B:64.1 /75.0 B@:127 @:35
RECEIVED:  T:231.2 /230.0 B:64.1 /75.0 B@:127 @:37
RECEIVED: echo:busy: processing
busy: processing
RECEIVED:  T:231.2 /230.0 B:64.3 /75.0 B@:127 @:36
RECEIVED:  T:230.9 /230.0 B:64.3 /75.0 B@:127 @:44
RECEIVED: echo:busy: processing
busy: processing
RECEIVED:  T:230.5 /230.0 B:64.4 /75.0 B@:127 @:52
RECEIVED:  T:230.2 /230.0 B:64.5 /75.0 B@:127 @:63
RECEIVED: echo:busy: processing
busy: processing
...
...
RECEIVED:  T:230.0 /230.0 B:74.2 /75.0 B@:127 @:64
RECEIVED:  T:230.0 /230.0 B:74.4 /75.0 B@:113 @:64
RECEIVED: echo:busy: processing
busy: processing
RECEIVED:  T:230.0 /230.0 B:74.4 /75.0 B@:124 @:64
RECEIVED:  T:229.9 /230.0 B:74.5 /75.0 B@:114 @:68
RECEIVED: echo:busy: processing
busy: processing
RECEIVED:  T:229.6 /230.0 B:74.6 /75.0 B@:119 @:76
RECEIVED:  T:229.9 /230.0 B:74.7 /75.0 B@:106 @:68
RECEIVED: echo:busy: processing
busy: processing
RECEIVED:  T:229.6 /230.0 B:74.7 /75.0 B@:121 @:78
RECEIVED:  T:229.8 /230.0 B:74.8 /75.0 B@:96 @:70
RECEIVED: echo:busy: processing
busy: processing
RECEIVED:  T:229.8 /230.0 B:74.9 /75.0 B@:103 @:70
RECEIVED:  T:229.8 /230.0 B:75.0 /75.0 B@:84 @:73
RECEIVED: echo:busy: processing
busy: processing
RECEIVED: ok
SENT: M105
RECEIVED: ok T:229.9 /230.0 B:75.0 /75.0 B@:81 @:69
  • then locked up

@thinkyhead
Copy link
Member

A lockup is strange. Usually a crash will reboot or give screen trash. And a kill will try to display a message. This sounds like it could be a tricky one to track down.

@edwilliams16
Copy link
Contributor Author

edwilliams16 commented Apr 29, 2016

Could the communications be deadlocked somehow? There seem to be way more "echo:busy processing" messages than I used to get. In particular, I get them during the print. Before, I only got them during the initialization phase.

@thinkyhead
Copy link
Member

thinkyhead commented Apr 29, 2016

Communications seem to be okay. Do you have an LCD controller attached that also locks up?

Busy messages are the new normal. You'll get those messages during any long wait. They used to be 10s apart, now they are 2 by default.. You can disable them with M113 S0 or the DISABLE_HOST_KEEPALIVE option, but actually the ones you're seeing now will soon be going away, because they're not needed.

@edwilliams16
Copy link
Contributor Author

I have a Rigidbot LCD attached. I was running from S3D on my Mac and didn't test to see if the printer would respond to the LCD. It wouldn't respond to S3D.

@thinkyhead
Copy link
Member

A lockup is a more serious issue, which could be due to a buffer overrun possibly, or stack overflow. Have you customized any strings in your setup? What language are you using?

@edwilliams16
Copy link
Contributor Author

English.
I customized the author string:

Author: (EAW, 16t single ex RC6)

@thinkyhead
Copy link
Member

If it's too long, that could cause a crash. We don't sanity-check for long strings.

@edwilliams16
Copy link
Contributor Author

Is that too long? How many chars am I allowed?

@thinkyhead
Copy link
Member

Actually, from what I can see, any length is fine for that setting. Hmm… where to look next?

@edwilliams16
Copy link
Contributor Author

edwilliams16 commented Apr 29, 2016

In both cases above, the lockup occurs exactly when both bed and extruder have reached target temperature.

@thinkyhead
Copy link
Member

@edwilliams16 I don't think we've changed too much since RC6, so your RC6 configuration should be fine.

@jbrazio jbrazio added this to the 1.1.0 milestone May 11, 2016
@jbrazio
Copy link
Contributor

jbrazio commented May 11, 2016

Thank you for your interest making Marlin better and reporting this issue but this topic has been open for a long period of time without any further development. Marlin has been under heavy development for the past couple of months and moving to it's last mile to finish the RC cycle and release Marlin v1.1.0. We suggest you to try out the latest RCBugfix branch and reopening this issue if required.

@jbrazio jbrazio closed this as completed May 11, 2016
@edwilliams16
Copy link
Contributor Author

This issue has not gone away even with today's RCBugfix. The problem occurred this time when I started the print, when the bed and extruder were nominally exactly on temperature. It just hung.
I've learned an easy work around. Disconnect and reconnect the serial connection and restart.

@thinkyhead
Copy link
Member

thinkyhead commented Jun 13, 2016

@edwilliams16 I assume that it just kept looping and printing the temperature report. Were you watching the output, and did you notice whether it was stuck on waiting for the bed or waiting for the hotend?

Also, what are your settings for TEMP_RESIDENCY_TIME, TEMP_WINDOW, and TEMP_HYSTERESIS?

I'm reviewing the logic of M109 / M190 at the moment to see if holes exist in cases where the temperature may already be in range.

@edwilliams16
Copy link
Contributor Author

In my case, it stops printing the temperature report and becomes unresponsive. I'll try to get a log next time. It has scrolled off by the time I get to it.

Sent from my iPad

On Jun 13, 2016, at 13:05, Scott Lahteine [email protected] wrote:

@edwilliams16 I assume that it just kept looping and printing the temperature report. Were you watching the output, and did you notice whether it was stuck on waiting for the bed or waiting for the hotend?

I'm reviewing the logic of M109 at the moment to see if holes exist in cases where the temperature may already be in range.


You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub, or mute the thread.

@edwilliams16
Copy link
Contributor Author

edwilliams16 commented Jun 14, 2016

I captured a log here. I'm using Simplify3D.
I start up then request 40C for the bed and 220C for the extruder to preheat from the machine page interface. At a later point, after the bed is on temperature, I start the print from USB.
It seems the M190 never returns.

Configuration.h:#define TEMP_RESIDENCY_TIME 10  // (seconds)
Configuration.h:#define TEMP_HYSTERESIS 3       // (degC) range of +/- temperatures considered "close" to the target one
Configuration.h:#define TEMP_WINDOW     1       // (degC) Window around target to start the residency timer x degC early.
Configuration.h:#define TEMP_BED_RESIDENCY_TIME 10  // (seconds)
Configuration.h:#define TEMP_BED_HYSTERESIS 3       // (degC) range of +/- temperatures considered "close" to the target one
Configuration.h:#define TEMP_BED_WINDOW     1       // (degC) Window around target to start the residency timer x degC early.
Attempting connection at /dev/cu.usbmodem621...
RECEIVED: ÔÔÊcstart
RECEIVED: echo:Marlin 1.1.0-RCBugFix
RECEIVED: echo: Last Updated: 2016-04-27 12:00 | Author: (EAW, 16t single ex RC6)
RECEIVED: Compiled: Jun 14 2016
RECEIVED: echo: Free Memory: 3195  PlannerBufferBytes: 1232
RECEIVED: echo:V23 stored settings retrieved (396 bytes)
RECEIVED: echo:Steps per unit:
RECEIVED: echo:  M92 X100.00 Y50.00 Z1600.00 E76.00
RECEIVED: echo:Maximum feedrates (mm/s):
RECEIVED: echo:  M203 X500.00 Y500.00 Z5.00 E25.00
RECEIVED: echo:Maximum Acceleration (mm/s2):
RECEIVED: echo:  M201 X800 Y800 Z100 E10000
RECEIVED: echo:Accelerations: P=printing, R=retract and T=travel
RECEIVED: echo:  M204 P600.00 R1000.00 T3000.00
RECEIVED: echo:Advanced variables: S=Min feedrate (mm/s), T=Min travel feedrate (mm/s), B=minimum segment time (ms), X=maximum XY jerk (mm/s),  Z=maximum Z jerk (mm/s),  E=maximum E jerk (mm/s)
RECEIVED: echo:  M205 S0.00 T0.00 B20000 X8.00 Z0.40 E5.00
RECEIVED: echo:Home offset (mm):
RECEIVED: echo:  M206 X0.00 Y0.00 Z0.00
RECEIVED: echo:Material heatup parameters:
RECEIVED: echo:  M145 S0 H180 B70 F255
RECEIVED: echo:  M145 S1 H240 B110 F255
RECEIVED: echo:PID settings:
RECEIVED: echo:  M301 P38.60 I3.96 D94.20 C100.00 L20
RECEIVED: echo:  M304 P355.00 I66.50 D480.00
RECEIVED: echo:Filament settings: Disabled
RECEIVED: echo:  M200 D3.00
RECEIVED: echo:  M200 D0
  Testing plaintext communication protocol...
  Testing binary communication protocol...
RECEIVED: echo:SD init fail
RECEIVED: ok
  Connected to machine!
SENT: T0
WARNING: CRC mismatch detected
RECEIVED: 
SENT: M105
RECEIVED: ok T:23.5 /0.0 B:23.7 /0.0 B@:0 @:0
.....  // lots of M105's
SENT: M105
RECEIVED: ok T:23.5 /0.0 B:23.7 /0.0 B@:0 @:0
SENT: M104 S220 T0                                                      ////  preheat nozzle
RECEIVED: ok
SENT: M140 S40                                                             //  preheat bed
RECEIVED: ok
SENT: M105
RECEIVED: ok T:23.5 /220.0 B:23.7 /40.0 B@:0 @:127
SENT: M105
RECEIVED: ok T:24.0 /220.0 B:23.7 /40.0 B@:127 @:127
SENT: M105
RECEIVED: ok T:25.0 /220.0 B:24.4 /40.0 B@:127 @:127
......  //more M105s
SENT: M105
RECEIVED: ok T:170.0 /220.0 B:40.0 /40.0 B@:58 @:127  // "start print over USB"
SENT: G90
SENT: M82
SENT: M106 S0
SENT: M140 S40              
SENT: M190 S40
RECEIVED: ok
RECEIVED: ok
RECEIVED: ok
RECEIVED: ok
RECEIVED:  T:171.1 /220.0 B:40.0 /40.0 B@:53 @:127
RECEIVED: ok

— hangs here

Filament heats up to 220 according to the LCD, but control never returns. Have bed heated message.

@Blue-Marlin
Copy link
Contributor

Blue-Marlin commented Jun 14, 2016

SENT: M105
RECEIVED: ok T:170.0 /220.0 B:40.0 /40.0 B@:58 @:127 // "start print over USB"
SENT: G90  ;1
SENT: M82 ;2
SENT: M106 S0 ;3
SENT: M140 S40 ;4

SENT: M190 S40 ;5
RECEIVED: ok ;1
RECEIVED: ok ;2
RECEIVED: ok ; 3
RECEIVED: ok ;4
RECEIVED: T:171.1 /220.0 B:40.0 /40.0 B@:53 @:127 ;from  M190 S40? Where is W:?
RECEIVED: ok ;5

Your host does not send. Did the file end here?

@edwilliams16
Copy link
Contributor Author

The filament heated up to 220, but the log ended. An S3D bug?

@thinkyhead
Copy link
Member

thinkyhead commented Jun 16, 2016

Where is W:?

Do you have BED_WATTS and/or EXTRUDER_WATTS enabled?

Nevermind, not relevant options for this.

@edwilliams16
Copy link
Contributor Author

No BED_WATTS or EXTRUDER_WATTS
Only editing I did was remove a few M105 and responses, otherwise what you see is what I got.

@Blue-Marlin
Copy link
Contributor

Blue-Marlin commented Jun 16, 2016

I mean the "W:" at the end of the line you get when TEMP_BED_RESIDENCY_TIME / TEMP_RESIDENCY_TIME is defined.

01:10:02.982 : T:22.5 /0.0 B:75.9 /77.0 B@:127 @:0 W:?
01:10:03.982 : T:22.5 /0.0 B:76.1 /77.0 B@:127 @:0 W:9
01:10:04.983 : T:22.5 /0.0 B:76.2 /77.0 B@:124 @:0 W:8
01:10:05.981 : T:22.5 /0.0 B:76.4 /77.0 B@:101 @:0 W:7
...

The problem with edited logs is - the relevant information might be edited out. You can't trust them.

@edwilliams16
Copy link
Contributor Author

edwilliams16 commented Jun 16, 2016

There were no lines with W:? - including those I edited out. I indicated where I edited out the lines that were identical in form to those that followed and preceeded them.

@edwilliams16
Copy link
Contributor Author

edwilliams16 commented Jun 16, 2016

Here is another example. (no edits!) I can get it to happen about 50% of the time. At the end I have "bed heating done", the extruder goes to 220C and stabilizes (on the LCD), but the print does not start and the printer is unresponsive to the S3D machine control panel.

Attempting connection at /dev/cu.usbmodem621...
RECEIVED: ��~��ø�~��fæà��þ����f�ø����ø�
RECEIVED: echo:Marlin 1.1.0-RCBugFix
RECEIVED: echo: Last Updated: 2016-04-27 12:00 | Author: (EAW, 16t single ex RC6)
RECEIVED: Compiled: Jun 14 2016
RECEIVED: echo: Free Memory: 3195  PlannerBufferBytes: 1232
RECEIVED: echo:V23 stored settings retrieved (396 bytes)
RECEIVED: echo:Steps per unit:
RECEIVED: echo:  M92 X100.00 Y50.00 Z1600.00 E76.00
RECEIVED: echo:Maximum feedrates (mm/s):
RECEIVED: echo:  M203 X500.00 Y500.00 Z5.00 E25.00
RECEIVED: echo:Maximum Acceleration (mm/s2):
RECEIVED: echo:  M201 X800 Y800 Z100 E10000
RECEIVED: echo:Accelerations: P=printing, R=retract and T=travel
RECEIVED: echo:  M204 P600.00 R1000.00 T3000.00
RECEIVED: echo:Advanced variables: S=Min feedrate (mm/s), T=Min travel feedrate (mm/s), B=minimum segment time (ms), X=maximum XY jerk (mm/s),  Z=maximum Z jerk (mm/s),  E=maximum E jerk (mm/s)
RECEIVED: echo:  M205 S0.00 T0.00 B20000 X8.00 Z0.40 E5.00
RECEIVED: echo:Home offset (mm):
RECEIVED: echo:  M206 X0.00 Y0.00 Z0.00
RECEIVED: echo:Material heatup parameters:
RECEIVED: echo:  M145 S0 H180 B70 F255
RECEIVED: echo:  M145 S1 H240 B110 F255
RECEIVED: echo:PID settings:
RECEIVED: echo:  M301 P38.60 I3.96 D94.20 C100.00 L20
RECEIVED: echo:  M304 P355.00 I66.50 D480.00
RECEIVED: echo:Filament settings: Disabled
RECEIVED: echo:  M200 D3.00
RECEIVED: echo:  M200 D0
  Testing plaintext communication protocol...
  Testing binary communication protocol...
RECEIVED: echo:SD init fail
RECEIVED: ok
  Connected to machine!
SENT: T0
WARNING: CRC mismatch detected
RECEIVED: 
SENT: M105
RECEIVED: ok T:162.9 /0.0 B:38.3 /0.0 B@:0 @:0
SENT: M105
RECEIVED: ok T:161.5 /0.0 B:38.3 /0.0 B@:0 @:0
SENT: M140 S40
RECEIVED: ok
SENT: M105
RECEIVED: ok T:160.3 /0.0 B:38.3 /40.0 B@:0 @:0
SENT: M104 S220 T0
RECEIVED: ok
SENT: M105
RECEIVED: ok T:159.0 /220.0 B:38.3 /40.0 B@:127 @:127
SENT: M105
RECEIVED: ok T:158.0 /220.0 B:38.7 /40.0 B@:127 @:127
SENT: M105
RECEIVED: ok T:157.6 /220.0 B:39.4 /40.0 B@:91 @:127
SENT: M105
RECEIVED: ok T:157.6 /220.0 B:40.0 /40.0 B@:19 @:127
SENT: M105
RECEIVED: ok T:158.2 /220.0 B:40.3 /40.0 B@:0 @:127
SENT: M105
RECEIVED: ok T:159.0 /220.0 B:40.1 /40.0 B@:62 @:127
SENT: M105
RECEIVED: ok T:160.3 /220.0 B:40.2 /40.0 B@:50 @:127
SENT: M105
RECEIVED: ok T:162.0 /220.0 B:40.3 /40.0 B@:11 @:127
SENT: M105
RECEIVED: ok T:163.8 /220.0 B:40.6 /40.0 B@:0 @:127
SENT: M105
RECEIVED: ok T:165.8 /220.0 B:40.3 /40.0 B@:27 @:127
SENT: M105
RECEIVED: ok T:167.6 /220.0 B:40.2 /40.0 B@:15 @:127
SENT: M105
RECEIVED: ok T:169.7 /220.0 B:40.3 /40.0 B@:0 @:127
SENT: M105
RECEIVED: ok T:172.0 /220.0 B:40.1 /40.0 B@:33 @:127
SENT: M105
RECEIVED: ok T:174.4 /220.0 B:40.0 /40.0 B@:42 @:127
SENT: G90
SENT: M82
SENT: M106 S0
SENT: M140 S40
SENT: M190 S40
RECEIVED: ok
RECEIVED: ok
RECEIVED: ok
RECEIVED: ok
RECEIVED:  T:174.6 /220.0 B:40.1 /40.0 B@:33 @:127
RECEIVED: ok

```

@thinkyhead
Copy link
Member

RECEIVED: T:174.6 /220.0 B:40.1 /40.0 B@:33 @:127

Is the temperature only ever getting to T:174.6 /220.0?

@thinkyhead
Copy link
Member

thinkyhead commented Jun 17, 2016

There were no lines with W:?

No worries. They only appear if you have TEMP_RESIDENCY_TIME and/or TEMP_BED_RESIDENCY_TIME enabled.

@edwilliams16
Copy link
Contributor Author

The log ends with 174.6 /220. According to the LCD the temperature gets up to 220 and holds it. However, the print doesn't continue and the the S3D machine panel has no effect. I have to disconnect and reconnect to restart the print.

@Blue-Marlin
Copy link
Contributor

    do {
      now = millis();
      if (ELAPSED(now, next_temp_ms)) { //Print Temp Reading every 1 second while heating up.
        next_temp_ms = now + 1000UL;
        print_heaterstates();
        #if TEMP_BED_RESIDENCY_TIME > 0
          SERIAL_PROTOCOLPGM(" W:"); // !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
          if (residency_start_ms) {
            long rem = (((TEMP_BED_RESIDENCY_TIME) * 1000UL) - (now - residency_start_ms)) / 1000UL;
            SERIAL_PROTOCOLLN(rem);

@thinkyhead
Copy link
Member

thinkyhead commented Jun 17, 2016

@edwilliams16 Probably getting closer to the answer soon. If you're not using TEMP_RESIDENCY_TIME or TEMP_BED_RESIDENCY_TIME then we won't see any countdown. Heating will be considered done when the temperature reaches (or goes over) target. And if you were waiting for cooling, the loop simply waits for the temperature to reach (or go below) target.

@thinkyhead
Copy link
Member

With M109 or M190 there should be continuous output to serial for as long as the loop is going. If the output stops, that indicates that the loop exited. Or it's possible the machine got hung up due to some kind of buffer overflow or other software error. Could your host software be disconnecting for some reason? Perhaps you can test with Pronterface to see if the behavior changes.

@thinkyhead
Copy link
Member

thinkyhead commented Jun 18, 2016

@Blue-Marlin I see that we are comparing ints to floats in some of these temperature comparison functions.

static float current_temperature[HOTENDS];
static int target_temperature[HOTENDS];
. . .
return target_temperature[HOTEND_ARG] > current_temperature[HOTEND_ARG];

But I don't think a comparison like this if (intVal > floatVal) should be problematic, since intVal will be cast to float first anyway.

@Blue-Marlin
Copy link
Contributor

There is nothing Marlin could do better. M190 exited with an ok. The host should continue to send, but it does not. Even if Marlin had crashed the host should at least try to send the next line. But there is no hint in the log. So likely the host crashed.

But who knows. The user is ether not able to give us a correct config.

Configuration.h:#define TEMP_BED_RESIDENCY_TIME 10 // (seconds)

or does not use RCBugFix.

Several test with other hosts (RH, Pronterface, Octoprint) have already be done by me. Works.
I don't have S3D and i'm not willing to pay for it.
So i agree. The user should make tests with other hosts.

int float compares do work in C since K&R. (forever)

@edwilliams16
Copy link
Contributor Author

edwilliams16 commented Jun 18, 2016

I gave you the TEMP_BED_RESIDENCY_TIME etc. three days ago and pointed out I'd changed to RCBugFix five days ago when I reopened the issue.
I agree it's likely an S3D bug. I switched to the just updated S3D 3.1 yesterday, so far the issue has not repeated - we'll see. The host has not crashed, because it will accept disconnect and reconnect (but not movement) commands. However, it may have lost track of whose turn it is to transmit.

@thinkyhead
Copy link
Member

int float compares do work

Of course. Just trying to cover all bases, in case weird rounding could be happening outside of my ability to visualize. But of course it up-casts to float so all is well.

I gave you the TEMP_BED_RESIDENCY_TIME etc. three days ago and pointed out I'd changed to RCBugFix five days ago when I reopened the issue.

Sorry, some days we have the memory retention of a goldfish.

@edwilliams16
Copy link
Contributor Author

If the error persists with the updated S3D, I'll ping them - being unable to reproduce the error with other hosts is a smoking gun.

@jbrazio jbrazio reopened this Jul 11, 2016
@jbrazio jbrazio closed this as completed Jul 11, 2016
@github-actions
Copy link

github-actions bot commented Apr 7, 2022

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.

@github-actions github-actions bot locked and limited conversation to collaborators Apr 7, 2022
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
Bug: Potential ? Needs: More Data We need more data in order to proceed
Projects
None yet
Development

No branches or pull requests

4 participants