What is the problem?
When starting a new print with 1.3.8 octoprint immediately pauses the print. Log shows Recv: action:pause which did not happen before 1.3.8
What did you already try to solve it?
no solution yet
Additional information about your setup (OctoPrint version, OctoPi version, printer, firmware, octoprint.log, serial.log or output on terminal tab, ...)
OctoPrint 1.3.8 running on OctoPi 0.13.0, Ultimaker 2 with Marlin firmware (see log)
I had to tweek the logs a bit and remove the double backslashes. Otherwise I couldn't post this topic...
Octoprint.log:
2018-04-21 13:08:48,195 - octoprint.util.comm - INFO - Changing monitoring state from "Offline" to "Detecting serial port"
2018-04-21 13:08:48,227 - octoprint.util.comm - INFO - Changing monitoring state from "Detecting serial port" to "Opening serial port"
2018-04-21 13:08:48,230 - octoprint.util.comm - INFO - Changing monitoring state from "Opening serial port" to "Connecting"
2018-04-21 13:08:48,235 - octoprint.util.comm - INFO - M110 detected, setting current line number to 0
2018-04-21 13:08:49,353 - octoprint.util.comm - INFO - M110 detected, setting current line number to 0
2018-04-21 13:08:51,868 - octoprint.util.comm - INFO - Ignoring resend request for line 1 == current line, we haven't sent that yet so the printer got N-1 twice from us, probably due to a timeout
2018-04-21 13:08:51,872 - octoprint.util.comm - INFO - Changing monitoring state from "Connecting" to "Operational"
2018-04-21 13:08:51,875 - octoprint.util.comm - INFO - M110 detected, setting current line number to 0
2018-04-21 13:08:51,892 - octoprint.util.comm - INFO - Printer reports firmware name "Marlin Ultimaker2; Sprinter/grbl mashup for gen6"
2018-04-21 13:09:08,723 - octoprint.filemanager.analysis - INFO - Starting analysis of local:Pumpenadapter.gcode
2018-04-21 13:09:08,729 - octoprint.filemanager.analysis - INFO - Invoking analysis command: /home/pi/oprint/bin/python -m octoprint analysis gcode --speed-x=6000 --speed-y=6000 --max-t=10 --throttle=0.0 --throttle-lines=100 /home/pi/.octoprint/uploads/Pumpenadapter.gcode
2018-04-21 13:09:12,475 - octoprint.util.comm - INFO - Changing monitoring state from "Operational" to "Printing"
2018-04-21 13:09:12,481 - octoprint.plugins.detailedprogress - INFO - Printing started. Detailed progress started.
2018-04-21 13:09:12,494 - octoprint.util.comm - INFO - M110 detected, setting current line number to 0
2018-04-21 13:09:12,516 - octoprint.util.comm - INFO - Changing monitoring state from "Printing" to "Pausing"
2018-04-21 13:09:12,519 - octoprint.filemanager.analysis - INFO - Starting analysis of local:Pumpenadapter.gcode
2018-04-21 13:09:12,522 - octoprint.filemanager.analysis - INFO - Invoking analysis command: /home/pi/oprint/bin/python -m octoprint analysis gcode --speed-x=6000 --speed-y=6000 --max-t=10 --throttle=0.0 --throttle-lines=100 /home/pi/.octoprint/uploads/Pumpenadapter.gcode
2018-04-21 13:09:13,046 - octoprint.util.comm - INFO - Changing monitoring state from "Pausing" to "Paused"
2018-04-21 13:09:17,402 - octoprint.util.comm - INFO - Changing monitoring state from "Paused" to "Cancelling"
2018-04-21 13:09:25,833 - octoprint.filemanager.analysis - INFO - Analysis of entry local:Pumpenadapter.gcode finished, needed 13.31s
2018-04-21 13:09:35,351 - tornado.access - WARNING - 403 GET /api/printerprofiles (127.0.0.1) 21.94ms
2018-04-21 13:09:36,016 - octoprint.server.util.sockjs - INFO - Client connection closed: 172.30.72.159
2018-04-21 13:09:36,839 - octoprint.server.util.sockjs - INFO - New connection from client: 172.30.72.159
2018-04-21 13:09:50,649 - octoprint.server.util.sockjs - INFO - Client connection closed: 172.30.72.159
2018-04-21 13:09:50,735 - tornado.access - WARNING - 403 GET /api/plugin/octopi_support (127.0.0.1) 21.59ms
2018-04-21 13:09:50,760 - tornado.access - WARNING - 403 GET /api/connection (127.0.0.1) 21.05ms
2018-04-21 13:09:50,783 - tornado.access - WARNING - 403 GET /api/printer/command/custom (127.0.0.1) 18.75ms
2018-04-21 13:09:50,806 - tornado.access - WARNING - 403 GET /api/system/commands (127.0.0.1) 19.03ms
2018-04-21 13:09:50,830 - tornado.access - WARNING - 403 GET /api/users (127.0.0.1) 19.20ms
2018-04-21 13:09:50,850 - tornado.access - WARNING - 403 GET /api/plugin/printer_safety_check (127.0.0.1) 16.25ms
2018-04-21 13:09:50,939 - tornado.access - WARNING - 403 GET /api/settings (127.0.0.1) 10.65ms
2018-04-21 13:09:50,952 - tornado.access - WARNING - 403 GET /api/files?recursive=true (127.0.0.1) 10.58ms
2018-04-21 13:09:51,561 - octoprint.server.util.sockjs - INFO - New connection from client: 172.30.72.159
2018-04-21 13:10:13,012 - octoprint.server.api.system - INFO - Performing command for core:restart: sudo service octoprint restart
2018-04-21 13:10:13,194 - octoprint.server - INFO - Shutting down...
2018-04-21 13:10:13,660 - octoprint.events - INFO - Processing shutdown event, this will be our last event
2018-04-21 13:10:13,673 - octoprint.events - INFO - Event loop shut down
2018-04-21 13:10:13,677 - octoprint.server - INFO - Goodbye!
2018-04-21 13:10:16,282 - octoprint.startup - INFO - ******************************************************************************
2018-04-21 13:10:16,283 - octoprint.startup - INFO - Starting OctoPrint 1.3.8
2018-04-21 13:10:16,283 - octoprint.startup - INFO - ******************************************************************************
2018-04-21 13:10:16,549 - octoprint.startup - INFO - Blacklist processing done
2018-04-21 13:10:16,593 - octoprint.plugin.core - INFO - Loading plugins from /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins, /home/pi/.octoprint/plugins and installed plugin packages...
2018-04-21 13:10:18,361 - octoprint.plugin.core - INFO - Found 11 plugin(s) providing 11 mixin implementations, 5 hook handlers
2018-04-21 13:10:18,454 - octoprint.server.heartbeat - INFO - Starting server heartbeat, 900.0s interval
2018-04-21 13:10:19,068 - octoprint.server - INFO - Intermediary server started
2018-04-21 13:10:19,069 - octoprint.plugin.core - INFO - Loading plugins from /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins, /home/pi/.octoprint/plugins and installed plugin packages...
2018-04-21 13:10:19,330 - octoprint.plugin.core - INFO - Found 11 plugin(s) providing 11 mixin implementations, 5 hook handlers
2018-04-21 13:10:19,361 - octoprint.filemanager.storage - INFO - Initializing the file metadata for /home/pi/.octoprint/uploads...
2018-04-21 13:10:19,845 - octoprint.filemanager.storage - INFO - ... file metadata for /home/pi/.octoprint/uploads initialized successfully.
2018-04-21 13:10:19,906 - octoprint.plugins.softwareupdate - INFO - Loaded version cache from disk
2018-04-21 13:10:21,595 - octoprint.util.pip - INFO - Using "/home/pi/oprint/bin/python -m pip" as command to invoke pip
2018-04-21 13:10:23,241 - octoprint.util.pip - INFO - Version of pip is 8.1.1
2018-04-21 13:10:23,242 - octoprint.util.pip - INFO - pip installs to /home/pi/oprint/lib/python2.7/site-packages (writable -> yes), --user flag needed -> no, virtual env -> yes
2018-04-21 13:10:23,243 - octoprint.util.pip - INFO - ==> pip ok -> yes
2018-04-21 13:10:23,245 - octoprint.plugin.core - INFO - Initialized 11 plugin implementation(s)
2018-04-21 13:10:23,251 - octoprint.plugin.core - INFO - 11 plugin(s) registered with the system:
| Announcement Plugin (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/announcements
| Core Wizard (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/corewizard
| CuraEngine (<= 15.04) (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/cura
| Detailed Progress Plugin (0.1.4) = /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_detailedprogress
| Discovery (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/discovery
| Logging (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/logging
| OctoPi Support Plugin (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/octopi_support
| Plugin Manager (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/pluginmanager
| Printer Safety Check (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/printer_safety_check
| Software Update (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/softwareupdate
| Virtual Printer (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/virtual_printer
2018-04-21 13:10:23,265 - octoprint.environment - INFO - Detected environment is Python 2.7.9 under Linux (linux2). Details:
| hardware:
| cores: 4
| freq: 1200.0
| ram: 901685248
| os:
| id: linux
| platform: linux2
| plugins:
| octopi_support:
| model: 3B
| revision: a02082
| version: 0.13.0
| python:
| pip: 8.1.1
| version: 2.7.9
| virtualenv: /home/pi/oprint
2018-04-21 13:10:23,273 - octoprint.server - INFO - Reset webasset folder /home/pi/.octoprint/generated/webassets...
2018-04-21 13:10:23,287 - octoprint.server - INFO - Reset webasset folder /home/pi/.octoprint/generated/.webassets-cache...
2018-04-21 13:10:23,459 - octoprint.server - INFO - Shutting down intermediary server...
2018-04-21 13:10:23,611 - octoprint.server - INFO - Intermediary server shut down
2018-04-21 13:10:24,213 - octoprint.events - INFO - Processing startup event, this is our first event
2018-04-21 13:10:24,214 - octoprint.events - INFO - Adding 0 events to queue that were held back before startup event
2018-04-21 13:10:24,216 - octoprint.filemanager - INFO - Adding backlog items from all storage types to analysis queue...
2018-04-21 13:10:24,225 - octoprint.filemanager - INFO - Added 0 items from storage type "local" to analysis queue
2018-04-21 13:10:24,251 - octoprint.plugins.discovery - INFO - Registered OctoPrint instance on octopi for _http._tcp
2018-04-21 13:10:24,271 - octoprint.plugins.discovery - INFO - Registered OctoPrint instance on octopi for _octoprint._tcp
2018-04-21 13:10:24,276 - octoprint.plugins.discovery - INFO - Registered OctoPrint instance on octopi for SSDP
2018-04-21 13:10:24,278 - octoprint.server - INFO - Listening on http://127.0.0.1:5000
2018-04-21 13:10:24,347 - octoprint.plugins.pluginmanager - INFO - Loaded plugin repository data from disk, was still valid
2018-04-21 13:10:24,905 - octoprint.plugins.pluginmanager - INFO - Loaded plugin notices data from https://plugins.octoprint.org/notices.json
2018-04-21 13:10:26,175 - octoprint.server.util.sockjs - INFO - New connection from client: 172.30.72.159
2018-04-21 13:10:29,689 - octoprint.util.comm - INFO - Changing monitoring state from "Offline" to "Opening serial port"
2018-04-21 13:10:29,693 - octoprint.util.comm - INFO - Changing monitoring state from "Opening serial port" to "Connecting"
2018-04-21 13:10:29,697 - octoprint.util.comm - INFO - M110 detected, setting current line number to 0
2018-04-21 13:10:30,822 - octoprint.util.comm - INFO - M110 detected, setting current line number to 0
2018-04-21 13:10:33,337 - octoprint.util.comm - INFO - Changing monitoring state from "Connecting" to "Operational"
2018-04-21 13:10:33,345 - octoprint.util.comm - INFO - M110 detected, setting current line number to 0
2018-04-21 13:10:33,375 - octoprint.util.comm - INFO - Printer reports firmware name "Marlin Ultimaker2; Sprinter/grbl mashup for gen6"
2018-04-21 13:10:46,312 - octoprint.util.comm - INFO - Changing monitoring state from "Operational" to "Printing"
2018-04-21 13:10:46,322 - octoprint.plugins.detailedprogress - INFO - Printing started. Detailed progress started.
2018-04-21 13:10:46,344 - octoprint.util.comm - INFO - M110 detected, setting current line number to 0
2018-04-21 13:10:46,406 - octoprint.util.comm - INFO - Changing monitoring state from "Printing" to "Pausing"
2018-04-21 13:10:46,943 - octoprint.util.comm - INFO - Changing monitoring state from "Pausing" to "Paused"
2018-04-21 13:11:02,870 - octoprint.util.comm - INFO - Changing monitoring state from "Paused" to "Printing"
Serial.log:
2018-04-21 13:10:28,989 - Connecting to: /dev/ttyACM0
2018-04-21 13:10:29,686 - Changing monitoring state from "Offline" to "Opening serial port"
2018-04-21 13:10:29,691 - Connected to: Serial<id=0x72f99370, open=True>(port='/dev/ttyACM0', baudrate=250000, bytesize=8, parity='N', stopbits=1, timeout=10.0, xonxoff=False, rtscts=False, dsrdtr=False), starting monitor
2018-04-21 13:10:29,693 - Changing monitoring state from "Opening serial port" to "Connecting"
2018-04-21 13:10:29,698 - Send: N0 M110 N0125
2018-04-21 13:10:30,815 - Recv: start
2018-04-21 13:10:30,823 - Recv: echo:Marlin 1.0.0
2018-04-21 13:10:30,826 - Send: N0 M110 N0125
2018-04-21 13:10:30,826 - Recv: echo: Last Updated: Sep 3 2016 18:56:13 | Author: Tinker_16.08.2
2018-04-21 13:10:30,828 - Recv: Compiled: Sep 3 2016
2018-04-21 13:10:30,830 - Recv: echo: Free Memory: 2585 PlannerBufferBytes: 1232
2018-04-21 13:10:30,831 - Recv: echo:Stored settings retrieved
2018-04-21 13:10:30,833 - Recv: echo:Steps per unit:
2018-04-21 13:10:30,834 - Recv: echo: M92 X80.00 Y80.00 Z200.00 E492.45
2018-04-21 13:10:30,836 - Recv: echo:Maximum feedrates (mm/s):
2018-04-21 13:10:30,837 - Recv: echo: M203 X300.00 Y300.00 Z40.00 E20.00
2018-04-21 13:10:30,838 - Recv: echo:Maximum Acceleration (mm/s2):
2018-04-21 13:10:30,839 - Recv: echo: M201 X9000 Y9000 Z100 E3000
2018-04-21 13:10:30,841 - Recv: echo:Acceleration: S=acceleration, T=retract acceleration
2018-04-21 13:10:30,842 - Recv: echo: M204 S3000.00 T3000.00
2018-04-21 13:10:30,844 - Recv: 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)
2018-04-21 13:10:30,845 - Recv: echo: M205 S0.00 T0.00 B20000 X20.00 Z0.40 E5.00
2018-04-21 13:10:30,846 - Recv: echo:Home offset (mm):
2018-04-21 13:10:30,847 - Recv: echo: M206 X0.00 Y0.00 Z-17.50
2018-04-21 13:10:30,849 - Recv: echo:PID settings:
2018-04-21 13:10:30,850 - Recv: echo: M301 P36.59 I3.65 D91.72
2018-04-21 13:10:33,324 - Recv: echo:SD init fail
2018-04-21 13:10:33,332 - Recv: ok
2018-04-21 13:10:33,336 - Changing monitoring state from "Connecting" to "Operational"
2018-04-21 13:10:33,350 - Send: N0 M110 N0125
2018-04-21 13:10:33,357 - Recv: echo:Unknown command: ""
2018-04-21 13:10:33,359 - Recv: ok
2018-04-21 13:10:33,361 - Send: N1 M11539
2018-04-21 13:10:33,373 - Recv: FIRMWARE_NAME:Marlin Ultimaker2; Sprinter/grbl mashup for gen6 FIRMWARE_URL:github.com/Ultimaker PROTOCOL_VERSION:1.0 MACHINE_TYPE:Ultimaker EXTRUDER_COUNT:1
2018-04-21 13:10:33,377 - Recv: ok
2018-04-21 13:10:33,381 - Send: M117 IP 172.30.72.102
2018-04-21 13:10:33,386 - Recv: ok
2018-04-21 13:10:38,338 - Send: M105
2018-04-21 13:10:38,347 - Recv: ok T:27.5 /0.0 B:25.0 /0.0 B@:0 @:0
2018-04-21 13:10:43,339 - Send: M105
2018-04-21 13:10:43,352 - Recv: ok T:27.6 /0.0 B:25.1 /0.0 B@:0 @:0
2018-04-21 13:10:46,311 - Changing monitoring state from "Operational" to "Printing"
2018-04-21 13:10:46,353 - Send: N0 M110 N0125
2018-04-21 13:10:46,363 - Recv: ok
2018-04-21 13:10:46,365 - Send: N1 G9017
2018-04-21 13:10:46,370 - Recv: ok
2018-04-21 13:10:46,373 - Send: N2 M8227
2018-04-21 13:10:46,379 - Recv: ok
2018-04-21 13:10:46,383 - Send: N3 M106 S255102
2018-04-21 13:10:46,387 - Recv: ok
2018-04-21 13:10:46,392 - Send: N4 G4 P500108
2018-04-21 13:10:46,404 - Recv: action:pause
2018-04-21 13:10:46,405 - Pausing on request of the printer...
2018-04-21 13:10:46,405 - Changing monitoring state from "Printing" to "Pausing"
2018-04-21 13:10:46,903 - Recv: action:resume
2018-04-21 13:10:46,904 - Resuming on request of the printer...
2018-04-21 13:10:46,905 - Recv: ok
2018-04-21 13:10:46,908 - Send: N5 M40034
2018-04-21 13:10:46,916 - Recv: ok
2018-04-21 13:10:46,918 - Send: N6 M114*33
2018-04-21 13:10:46,927 - Recv: X:0.00Y:0.00Z:0.00E:0.00 Count X: 0.00Y:0.00Z:0.00E:0.00
2018-04-21 13:10:46,938 - Recv: ok
2018-04-21 13:10:46,942 - Changing monitoring state from "Pausing" to "Paused"
2018-04-21 13:10:48,340 - Send: M105
2018-04-21 13:10:48,349 - Recv: ok T:27.2 /0.0 B:25.1 /0.0 B@:0 @:0
2018-04-21 13:10:53,341 - Send: M105
2018-04-21 13:10:57,192 - Recv: ok T:27.6 /0.0 B:24.9 /0.0 B@:0 @:0
2018-04-21 13:10:58,342 - Send: M105
2018-04-21 13:10:58,352 - Recv: ok T:26.9 /0.0 B:24.9 /0.0 B@:0 @:0
2018-04-21 13:11:00,437 - Disabling serial logging/