Connection Problem with serial

Get Help
1

Hy since i have installed the new version of Octoprint 1.3.8 on Octopi 0.14 i cannot start a Printjob anymore, after 20 to 25 sec octoprint tries to reconnect to the printer and i don't know why!
I used octoprint before also in version 1.3.8 but just had problems connecting via ssh - so i took a new image and setup octopi again.
I tried to play with the timeout settings on serial conection but with no sucess, always the reconnect in the interfeace but when i watch the terminal, ocotprint still gets data over serial.

I did not change anything on my setup except reinstall octoprint, i have the same firmware Marlin 1.1.8 and it's the same raspy and same connection cables.
I can start printing with a pc and simplify 3d with no problems.

What else do you need?

Kind regards
Manuel

serial.log:

2018-04-16 11:15:11,201 - Connecting to: /dev/ttyUSB0
2018-04-16 11:15:11,222 - Changing monitoring state from "Offline" to "Opening serial port"
2018-04-16 11:15:11,234 - Connected to: Serial<id=0x73a5d7b0, open=True>(port='/dev/ttyUSB0', baudrate=250000, bytesize=8, parity='N', stopbits=1, timeout=10.0, xonxoff=False, rtscts=False, dsrdtr=False), starting monitor
2018-04-16 11:15:11,236 - Changing monitoring state from "Opening serial port" to "Connecting"
2018-04-16 11:15:11,245 - Send: N0 M110 N0*125
2018-04-16 11:15:12,311 - Recv: start
2018-04-16 11:15:12,315 - Send: N0 M110 N0*125
2018-04-16 11:15:12,349 - Recv: echo: External Reset
2018-04-16 11:15:12,350 - Recv: Marlin bugfix-1.1.x
2018-04-16 11:15:12,351 - Recv: 
2018-04-16 11:15:12,352 - Recv: echo: Last Updated: 2018-01-20 | Author: (none, default config)
2018-04-16 11:15:12,353 - Recv: echo:Compiled: Mar 20 2018
2018-04-16 11:15:12,354 - Recv: echo: Free Memory: 3933  PlannerBufferBytes: 1232
2018-04-16 11:15:12,359 - Recv: echo:V52 stored settings retrieved (671 bytes; crc 26505)
2018-04-16 11:15:12,360 - Recv: echo:  G21    ; Units in mm
2018-04-16 11:15:12,361 - Recv: echo:  M149 C ; Units in Celsius
2018-04-16 11:15:12,362 - Recv: 
2018-04-16 11:15:12,362 - Recv: echo:Filament settings: Disabled
2018-04-16 11:15:12,363 - Recv: echo:  M200 D1.75
2018-04-16 11:15:12,364 - Recv: echo:  M200 D0
2018-04-16 11:15:12,378 - Recv: echo:Steps per unit:
2018-04-16 11:15:12,386 - Recv: echo:  M92 X80.00 Y80.00 Z1600.00 E424.00
2018-04-16 11:15:12,388 - Recv: echo:Maximum feedrates (units/s):
2018-04-16 11:15:12,388 - Recv: echo:  M203 X300.00 Y300.00 Z5.00 E40.00
2018-04-16 11:15:12,389 - Recv: echo:Maximum Acceleration (units/s2):
2018-04-16 11:15:12,390 - Recv: echo:  M201 X3000 Y3000 Z100 E5000
2018-04-16 11:15:12,391 - Recv: echo:Acceleration (units/s2): P<print_accel> R<retract_accel> T<travel_accel>
2018-04-16 11:15:12,392 - Recv: echo:  M204 P3000.00 R3000.00 T3000.00
2018-04-16 11:15:12,393 - Recv: echo:Advanced: S<min_feedrate> T<min_travel_feedrate> B<min_segment_time_us> X<max_xy_jerk> Z<max_z_jerk> E<max_e_jerk>
2018-04-16 11:15:12,394 - Recv: echo:  M205 S0.00 T0.00 B20000 X10.00 Y10.00 Z0.30 E5.00
2018-04-16 11:15:12,395 - Recv: echo:Home offset:
2018-04-16 11:15:12,396 - Recv: echo:  M206 X0.00 Y0.00 Z0.00
2018-04-16 11:15:12,397 - Recv: echo:Mesh Bed Leveling:
2018-04-16 11:15:12,398 - Recv: echo:  M420 S0 Z0.00
2018-04-16 11:15:12,399 - Recv: echo:  G29 S3 X1 Y1 Z-0.75000
2018-04-16 11:15:12,400 - Recv: echo:  G29 S3 X2 Y1 Z-0.72500
2018-04-16 11:15:12,401 - Recv: echo:  G29 S3 X3 Y1 Z-0.50000
2018-04-16 11:15:12,402 - Recv: echo:  G29 S3 X4 Y1 Z-0.35000
2018-04-16 11:15:12,403 - Recv: echo:  G29 S3 X5 Y1 Z-0.12500
2018-04-16 11:15:12,404 - Recv: echo:  G29 S3 X1 Y2 Z-0.55000
2018-04-16 11:15:12,404 - Recv: echo:  G29 S3 X2 Y2 Z-0.30000
2018-04-16 11:15:12,405 - Recv: echo:  G29 S3 X3 Y2 Z-0.15000
2018-04-16 11:15:12,406 - Recv: echo:  G29 S3 X4 Y2 Z-0.00000
2018-04-16 11:15:12,407 - Recv: echo:  G29 S3 X5 Y2 Z0.20000
2018-04-16 11:15:12,408 - Recv: echo:  G29 S3 X1 Y3 Z-0.17500
2018-04-16 11:15:12,409 - Recv: echo:  G29 S3 X2 Y3 Z0.02500
2018-04-16 11:15:12,410 - Recv: echo:  G29 S3 X3 Y3 Z0.17500
2018-04-16 11:15:12,411 - Recv: echo:  G29 S3 X4 Y3 Z0.30000
2018-04-16 11:15:12,412 - Recv: echo:  G29 S3 X5 Y3 Z0.42500
2018-04-16 11:15:12,413 - Recv: echo:  G29 S3 X1 Y4 Z-0.10000
2018-04-16 11:15:12,414 - Recv: echo:  G29 S3 X2 Y4 Z0.05000
2018-04-16 11:15:12,415 - Recv: echo:  G29 S3 X3 Y4 Z0.30000
2018-04-16 11:15:12,415 - Recv: echo:  G29 S3 X4 Y4 Z0.40000
2018-04-16 11:15:12,416 - Recv: echo:  G29 S3 X5 Y4 Z0.45000
2018-04-16 11:15:12,417 - Recv: echo:  G29 S3 X1 Y5 Z0.10000
2018-04-16 11:15:12,418 - Recv: echo:  G29 S3 X2 Y5 Z0.20000
2018-04-16 11:15:12,419 - Recv: echo:  G29 S3 X3 Y5 Z0.22500
2018-04-16 11:15:12,424 - Recv: echo:  G29 S3 X4 Y5 Z0.32500
2018-04-16 11:15:12,425 - Recv: echo:  G29 S3 X5 Y5 Z0.45000
2018-04-16 11:15:12,426 - Recv: echo:Material heatup parameters:
2018-04-16 11:15:12,427 - Recv: echo:  M145 S0 H180 B70 F0
2018-04-16 11:15:12,428 - Recv: echo:  M145 S1 H240 B110 F0
2018-04-16 11:15:12,429 - Recv: echo:PID settings:
2018-04-16 11:15:12,430 - Recv: echo:  M301 P22.20 I1.08 D114.00
2018-04-16 11:15:12,431 - Recv: echo:Stepper driver current:
2018-04-16 11:15:12,432 - Recv: echo:  M906 X 800 Y 800 Z 800 E0 800
2018-04-16 11:15:12,433 - Recv: echo:Sensorless homing threshold:
2018-04-16 11:15:12,434 - Recv: echo:  M914 X15 Y40 Z8
2018-04-16 11:15:16,259 - Recv: ok
2018-04-16 11:15:16,282 - Changing monitoring state from "Connecting" to "Operational"
2018-04-16 11:15:16,285 - Send: N1 M105*38
2018-04-16 11:15:17,882 - Recv: ok T:15.49 /0.00 B:17.30 /0.00 @:0 B@:0
2018-04-16 11:15:17,889 - Send: N0 M110 N0*125
2018-04-16 11:15:17,906 - Recv: ok
2018-04-16 11:15:17,908 - Send: N1 M115*39
2018-04-16 11:15:17,944 - Recv: FIRMWARE_NAME:Marlin bugfix-1.1.x (Github) SOURCE_CODE_URL:https://github.com/MarlinFirmware/Marlin PROTOCOL_VERSION:1.0 MACHINE_TYPE:Prusa i3 Pro B EXTRUDER_COUNT:1 UUID:cede2a2f-41a2-4748-9b12-c55c62f367ff
2018-04-16 11:15:17,948 - Recv: Cap:SERIAL_XON_XOFF:0
2018-04-16 11:15:17,949 - Recv: Cap:EEPROM:1
2018-04-16 11:15:17,950 - Recv: Cap:VOLUMETRIC:1
2018-04-16 11:15:17,952 - Recv: Cap:AUTOREPORT_TEMP:1
2018-04-16 11:15:17,955 - Recv: Cap:PROGRESS:0
2018-04-16 11:15:17,956 - Recv: Cap:PRINT_JOB:1
2018-04-16 11:15:17,957 - Recv: Cap:AUTOLEVEL:0
2018-04-16 11:15:17,959 - Recv: Cap:Z_PROBE:0
2018-04-16 11:15:17,960 - Recv: Cap:LEVELING_DATA:1
2018-04-16 11:15:17,961 - Recv: Cap:BUILD_PERCENT:0
2018-04-16 11:15:17,963 - Recv: Cap:SOFTWARE_POWER:1
2018-04-16 11:15:17,964 - Recv: Cap:TOGGLE_LIGHTS:0
2018-04-16 11:15:17,965 - Recv: Cap:CASE_LIGHT_BRIGHTNESS:0
2018-04-16 11:15:17,966 - Recv: Cap:EMERGENCY_PARSER:0
2018-04-16 11:15:17,967 - Recv: ok
2018-04-16 11:15:17,969 - Send: M21
2018-04-16 11:15:17,976 - Recv: ok
2018-04-16 11:15:17,978 - Send: M155 S2
2018-04-16 11:15:17,992 - Recv: ok
2018-04-16 11:15:19,989 - Recv:  T:15.09 /0.00 B:17.27 /0.00 @:0 B@:0
2018-04-16 11:15:21,987 - Recv:  T:16.87 /0.00 B:17.46 /0.00 @:0 B@:0
2018-04-16 11:15:24,001 - Recv:  T:16.07 /0.00 B:18.55 /0.00 @:0 B@:0
2018-04-16 11:15:25,999 - Recv:  T:14.69 /0.00 B:16.60 /0.00 @:0 B@:0
2018-04-16 11:15:28,004 - Recv:  T:15.54 /0.00 B:16.68 /0.00 @:0 B@:0
2018-04-16 11:15:29,994 - Recv:  T:15.04 /0.00 B:16.33 /0.00 @:0 B@:0
2018-04-16 11:15:31,990 - Recv:  T:16.07 /0.00 B:17.54 /0.00 @:0 B@:0
2018-04-16 11:15:33,988 - Recv:  T:16.52 /0.00 B:16.91 /0.00 @:0 B@:0
2018-04-16 11:15:35,985 - Recv:  T:15.98 /0.00 B:17.70 /0.00 @:0 B@:0
2018-04-16 11:15:37,998 - Recv:  T:16.43 /0.00 B:17.97 /0.00 @:0 B@:0
2018-04-16 11:15:39,996 - Recv:  T:15.54 /0.00 B:17.07 /0.00 @:0 B@:0
2018-04-16 11:15:41,993 - Recv:  T:16.96 /0.00 B:17.66 /0.00 @:0 B@:0
2018-04-16 11:15:43,992 - Recv:  T:15.09 /0.00 B:17.50 /0.00 @:0 B@:0
2018-04-16 11:15:46,005 - Recv:  T:16.29 /0.00 B:16.72 /0.00 @:0 B@:0
2018-04-16 11:15:48,001 - Recv:  T:15.76 /0.00 B:16.45 /0.00 @:0 B@:0
2018-04-16 11:15:50,000 - Recv:  T:16.87 /0.00 B:17.77 /0.00 @:0 B@:0
2018-04-16 11:15:51,998 - Recv:  T:15.76 /0.00 B:16.87 /0.00 @:0 B@:0
2018-04-16 11:15:53,995 - Recv:  T:16.38 /0.00 B:16.84 /0.00 @:0 B@:0
2018-04-16 11:15:56,008 - Recv:  T:16.03 /0.00 B:17.70 /0.00 @:0 B@:0
2018-04-16 11:15:58,006 - Recv:  T:15.98 /0.00 B:17.81 /0.00 @:0 B@:0
2018-04-16 11:16:00,003 - Recv:  T:16.16 /0.00 B:17.07 /0.00 @:0 B@:0
2018-04-16 11:16:02,001 - Recv:  T:16.61 /0.00 B:17.85 /0.00 @:0 B@:0
2018-04-16 11:16:03,998 - Recv:  T:14.96 /0.00 B:17.58 /0.00 @:0 B@:0
2018-04-16 11:16:05,995 - Recv:  T:15.04 /0.00 B:17.27 /0.00 @:0 B@:0
2018-04-16 11:16:08,009 - Recv:  T:16.03 /0.00 B:16.64 /0.00 @:0 B@:0
2018-04-16 11:16:10,006 - Recv:  T:16.65 /0.00 B:17.81 /0.00 @:0 B@:0
2018-04-16 11:16:12,003 - Recv:  T:15.40 /0.00 B:16.87 /0.00 @:0 B@:0
2018-04-16 11:16:14,001 - Recv:  T:16.43 /0.00 B:17.30 /0.00 @:0 B@:0
2018-04-16 11:16:15,998 - Recv:  T:16.92 /0.00 B:17.50 /0.00 @:0 B@:0
2018-04-16 11:16:17,996 - Recv:  T:15.80 /0.00 B:17.38 /0.00 @:0 B@:0
2018-04-16 11:16:19,993 - Recv:  T:16.61 /0.00 B:17.15 /0.00 @:0 B@:0
2018-04-16 11:16:22,006 - Recv:  T:16.29 /0.00 B:18.12 /0.00 @:0 B@:0
2018-04-16 11:16:24,003 - Recv:  T:15.13 /0.00 B:17.27 /0.00 @:0 B@:0
2018-04-16 11:16:26,001 - Recv:  T:14.78 /0.00 B:17.27 /0.00 @:0 B@:0
2018-04-16 11:16:27,998 - Recv:  T:16.16 /0.00 B:16.76 /0.00 @:0 B@:0
2018-04-16 11:16:29,996 - Recv:  T:16.29 /0.00 B:17.73 /0.00 @:0 B@:0
2018-04-16 11:16:31,994 - Recv:  T:16.03 /0.00 B:16.87 /0.00 @:0 B@:0
2018-04-16 11:16:34,007 - Recv:  T:16.47 /0.00 B:17.11 /0.00 @:0 B@:0
2018-04-16 11:16:36,004 - Recv:  T:16.47 /0.00 B:17.70 /0.00 @:0 B@:0
2018-04-16 11:16:38,002 - Recv:  T:15.31 /0.00 B:17.38 /0.00 @:0 B@:0
2018-04-16 11:16:39,999 - Recv:  T:16.61 /0.00 B:17.03 /0.00 @:0 B@:0
2018-04-16 11:16:42,013 - Recv:  T:16.34 /0.00 B:17.85 /0.00 @:0 B@:0
2018-04-16 11:16:44,010 - Recv:  T:15.45 /0.00 B:16.87 /0.00 @:0 B@:0
2018-04-16 11:16:46,008 - Recv:  T:15.27 /0.00 B:16.80 /0.00 @:0 B@:0
2018-04-16 11:16:48,005 - Recv:  T:16.43 /0.00 B:17.50 /0.00 @:0 B@:0
2018-04-16 11:16:50,002 - Recv:  T:15.18 /0.00 B:17.58 /0.00 @:0 B@:0
2018-04-16 11:16:52,015 - Recv:  T:15.45 /0.00 B:16.60 /0.00 @:0 B@:0
2018-04-16 11:16:54,013 - Recv:  T:16.43 /0.00 B:16.95 /0.00 @:0 B@:0
2018-04-16 11:16:56,010 - Recv:  T:16.38 /0.00 B:17.42 /0.00 @:0 B@:0
2018-04-16 11:16:58,007 - Recv:  T:15.63 /0.00 B:17.46 /0.00 @:0 B@:0
2018-04-16 11:17:00,005 - Recv:  T:16.79 /0.00 B:16.99 /0.00 @:0 B@:0
2018-04-16 11:17:02,002 - Recv:  T:15.94 /0.00 B:17.50 /0.00 @:0 B@:0
2018-04-16 11:17:04,000 - Recv:  T:16.12 /0.00 B:17.70 /0.00 @:0 B@:0
2018-04-16 11:17:06,013 - Recv:  T:15.04 /0.00 B:16.45 /0.00 @:0 B@:0
2018-04-16 11:17:08,010 - Recv:  T:16.74 /0.00 B:17.77 /0.00 @:0 B@:0
2018-04-16 11:17:08,417 - Changing monitoring state from "Operational" to "Printing"
2018-04-16 11:17:08,455 - Send: N0 M110 N0*125
2018-04-16 11:17:08,458 - Recv: ok
2018-04-16 11:17:08,464 - Send: N1 M80 192.168.1.2*18
2018-04-16 11:17:08,746 - Unexpected error while reading serial port, please consult octoprint.log for details: SerialException: 'device reports readiness to read but returned no data (device disconnected or multiple access on port?)' @ comm.py:_readline:2417
2018-04-16 11:17:08,747 - Please see https://faq.octoprint.org/serialerror for possible reasons of this.
2018-04-16 11:17:08,754 - Changing monitoring state from "Printing" to "Offline (Error: SerialException: 'device reports readiness to read but returned no data (device disconnected or multiple access on port?)' @ comm.py:_readline:2417)"
2018-04-16 11:17:08,760 - Connection closed, closing down monitor
3

When i dont start a printjob, the printer stays connected with octoprint and i can turn on the heater from the bed and hotend without any troubles but just when i start a print after 20seconds he disconnects

4

I got it, it was the Autoconnect feature in TP-Link Smartplug, so he autoconnects after a few seconds after the command is send, so the printer connects then and when the serial is already established!
So Problem SOLVED!

5

Please mark the solution then with the little :marksolved:

6

I think I might have found an issue and a fix
USB autosuspend on kernel 3.7.10 or above

Check if your USB autosuspends...
cat /sys/module/usbcore/parameters/autosuspend
If it does not say -1
then you might have the chance of your USB going to sleep
I have done this on my old busted screen laptop running Linux Lite 4.0 and octoprint...going to see if it fails again...I have had a BUNCH of these errors

327 - octoprint.util.comm - INFO - Changing monitoring state from "Operational" to "Offline (Error: SerialException: 'device reports readiness to read but returned no data (device disconnected or multiple access on port?)' @ comm.py:_readline:2417)"

Lets hope this works...because the failed prints are freeking KILLING me!

Well first test print passed...it failed 2x times before...which is weird becuase it is such a small print

7

It worked on two prints (sub 2 hr prints)..currently testing on a very long print without octoprint

I service octoprint stop

installed pronterface

Printing with that...right now seeing if it completes with pronterface...

It completed a 14+ hr print no errors...same hardware...no change, only thing I did was turn off octoprint
I don't know what the deal is...

8

OctoPrint needs more resources than pronterface. So it could be that there's an insufficient power scenario there which makes the WiFi/serial device brownout/lose connection.

9

Yeah...not a pronterface issue either...just got a failure with that as well

serial info before it died

2018-07-13 20:34:18,987 - SENT: G1 E-5.0 F100
2018-07-13 20:34:18,988 - SENT: G90
2018-07-13 20:34:18,991 - RECV: ok
2018-07-13 20:34:18,992 - RECV: ok
2018-07-13 20:34:18,994 - RECV: ok
2018-07-13 20:34:18,995 - RECV: ok
2018-07-13 20:34:19,004 - RECV: X:-33.00 Y:220.00 Z:28.96 E:2646.51 Count X: -33.00 Y:200.04 Z:28.96
2018-07-13 20:34:19,005 - RECV: ok
2018-07-13 20:34:19,006 - RECV: ok
2018-07-13 20:34:19,008 - RECV: echo: cold extrusion prevented
2018-07-13 20:34:19,008 - RECV: ok
2018-07-13 20:34:19,524 - SENT: M105
2018-07-13 20:34:19,534 - RECV: ok T:27.8 /0.0 B:31.9 /0.0 T0:27.8 /0.0 @:0 B@:0
2018-07-13 20:34:22,533 - SENT: M105
2018-07-13 20:34:22,547 - RECV: ok T:27.8 /0.0 B:32.0 /0.0 T0:27.8 /0.0 @:0 B@:0
2018-07-13 22:50:10,754 - Generating grammar tables from /usr/lib/python2.7/lib2to3/Grammar.txt
2018-07-13 22:50:10,866 - Generating grammar tables from /usr/lib/python2.7/lib2to3/PatternGrammar.txt
2018-07-13 22:50:14,813 - Connecting...
2018-07-13 22:50:19,400 - Printer is now online.
2018-07-13 22:53:52,674 - Loading file: /home/user1/.octoprint/uploads/box.gcode
2018-07-13 22:54:07,978 - Loaded /home/user1/.octoprint/uploads/box.gcode, 316631 lines
2018-07-13 22:54:07,994 - 20341.01mm of filament used in this print
2018-07-13 22:54:07,994 - The print goes:
2018-07-13 22:54:07,995 - - from 0.00 mm to 181.00 mm in X and is 181.00 mm wide
2018-07-13 22:54:07,996 - - from 0.00 mm to 194.45 mm in Y and is 194.45 mm deep
2018-07-13 22:54:07,997 - - from 0.00 mm to 27.18 mm in Z and is 27.18 mm high
2018-07-13 22:54:08,001 - Estimated duration: 114 layers, 3:50:23
2018-07-13 22:54:19,433 - Print started at: 22:54:19
2018-07-13 22:54:21,544 - Locking interface.
2018-07-14 01:35:58,001 - [ERROR] Can't read from printer (disconnected?) (SerialException): device reports readiness to read but returned no data (device disconnected or multiple access on port?)
2018-07-14 01:35:58,003 - [ERROR] Can't write to printer (disconnected?) (SerialException): write failed: [Errno 5] Input/output error

image
image.jpg1201×933 356 KB

That's the VLC stream from mjpeg-streamer that is running

Not sure if it is the laptop (it's ethernet connected)...it has full battery power and is on AC wall power, no sleep mode and I turned off the usbcore.autosuspend=-1 in the kernel...guess I need to start looking at the power supply for the printer itself even though the other day when I tested it (not under full load for a long time) it was at 12.54 vdc..(even went thru and made sure all the electrical connections were tight to make sure something wasn't getting hot and coming loose)

Daggum it...sporadic and intermittent problems are such a pain to troubleshoot

Just saw the generating grammar thing...both python 2 and 3 I believe
Generating grammar tables from /usr/lib/python2.7/lib2to3/Grammar.txt
I wonder why it said preventing cold extrusion...when there was no indication of it ever loosing temp