Octoprint: After updating plugins, can't exclusively lock serial port to printer

[Patronics]

What were you doing?

1. Run Octoprint as nomal, connected to printer
2. Allow ocotprint to restart for a plugin update (or probably install, untested)
3. Attempt to connect to the printer again after the server restarts.
4. Printer fails to connect, and terminal tab shows this error:

Changing monitoring state from "Offline" to "Detecting serial port"
Serial port list: ['/dev/ttyACM0']
Connecting to: /dev/ttyACM0
Changing monitoring state from "Detecting serial port" to "Error: Connection error, see Terminal tab"
Unexpected error while connecting to serial port: AUTO SerialException: '[Errno 11] Could not exclusively lock port /dev/ttyACM0: [Errno 11] Resource temporarily unavailable' @ comm.py:_openSerial:2611 (hook default)

What did you expect to happen?

The printer connects sucessfully

What happened instead?

octoprint gives the error above, and fails to connect to the printer until the device is rebooted

Did the same happen when running OctoPrint in safe mode?

Yes, I had the exact same error in safe mode (at least when restarting into safe mode after the update, not tested when updating plugins while in safe mode)

Version of OctoPrint

1.3.11

Operating System running OctoPrint

Raspbian (Stretch or Jesse, not sure which) on Raspberry Pi 3B

Printer model & used firmware incl. version

Likely not relevant, but Prusa i3 Mk3s w/MMU2s

Browser and version of browser, operating system running browser

Link to octoprint.log

https://gist.github.com/Patronics/040a31f78833081803446bae7d32cd4c

Link to contents of terminal tab or serial.log

Posted above in error message

Link to contents of Javascript console in the browser

N/A

Screenshot(s)/video(s) showing the problem:

N/A

Yes, I have read the FAQ.

[foosel]

Hm... I cannot reproduce this. Tested 1.3.11 against a Prusa MK3. Serial port was successfully opened, no issues with the exclusive access.

ETA

Changing monitoring state from "Connecting" to "Offline"
Connecting to: /dev/ttyACM0
Changing monitoring state from "Offline" to "Opening serial port"
Connected to: Serial<id=0x65192f90, open=True>(port='/dev/ttyACM0', baudrate=115200, bytesize=8, parity='N', stopbits=1, timeout=10.0, xonxoff=False, rtscts=False, dsrdtr=False), starting monitor
Changing monitoring state from "Opening serial port" to "Connecting"
Send: N0 M110 N0*125
Recv: start
Send: N0 M110 N0*125
Recv: echo: 3.5.2-1999
Recv: echo: Last Updated: Feb 12 2019 11:36:02 | Author: (none, default config)
Recv: Compiled: Feb 12 2019
Recv: echo: Free Memory: 2042  PlannerBufferBytes: 1392
Recv: echo:Hardcoded Default Settings Loaded
Recv: adc_init
Recv: CrashDetect DISABLED
Recv: PAT9125_RES_X=0
Recv: PAT9125_RES_Y=240
Recv: PAT9125_init:1
Recv: FSensor DISABLED
Recv: 
Recv: echo:SD card ok
Recv: echo:busy: processing
Printer seems to support the busy protocol, will adjust timeouts and set busy interval accordingly
Recv: Error:No Line Number with checksum, Last Line: 0
Recv: Resend: 1
Recv: ok
Changing monitoring state from "Connecting" to "Operational"

Steps:

1. connect to printer
2. update a plugin (Firmware Updater in this case)
3. after server comes back up immediately connect to printer

[Patronics]

Thanks for testing. It's happened twice to me so far, over my last 2 plugin updates. I'll keep investigating (next time I get a plug-in update anyway), and see if it's consistently repeatable, and try to figure out how to investigate which process is grabbing the serial port, to verify it is indeed Octoprint. I'll comment again as I learn more.

[foosel]

Thank you!

[DanielJoyce]

Previous process likely not cleanly exiting after plugin update and still holding lock to serial port.

[mrdink]

Having the same issue on both of my setups. Following.

[gleonard3]

Same. Ender 3.

[foosel]

I strongly suggest to not just "follow" but also share some more information about the setup where this is reproducible, because otherwise probably nothing will ever change to the status of this ticket 🤷‍♀️

[supermanny81]

I was going to file this as a bug with the print time genius developer, but saw this issue first. So thought to share here.

I have seen the same on my instance a few times in the past week, I normally just restart the pi and go on with printing.

Changing monitoring state from "Offline" to "Detecting serial port"
Serial port list: ['/dev/ttyACM0']
Connecting to: /dev/ttyACM0
Changing monitoring state from "Detecting serial port" to "Error: Connection error, see Terminal tab"
Unexpected error while connecting to serial port: AUTO SerialException: '[Errno 11] Could not exclusively lock port /dev/ttyACM0: [Errno 11] Resource temporarily unavailable' @ comm.py:_openSerial:2611 (hook default)

This error happened after I updated the print time genius plugin this morning. Post reload, the OS still had a lock on the device, but had lost the process name (it was no longer running). I knew that last one should have been OctoPrint.

 $ lslocks
COMMAND           PID  TYPE SIZE MODE  M START END PATH
cron              343 FLOCK      WRITE 0     0   0 /run...
(unknown)         364 FLOCK      WRITE 0     0   0 /run...
(unknown)         384 FLOCK      WRITE 0     0   0 /run...
(unknown)         427 FLOCK      WRITE 0     0   0 /dev...

So I thought to see if any child processes might have been created by OctoPrint that were perhaps defunct (which was along the same lines as what actually happened).

Sorry, I didn't dig much deeper there, so don't have a lot to share. At this point, I just jumped to see which processes were created by the pi user and had a reference to OctoPrint.

pi        2128     1  0 Sep28 ?        00:00:00 /home/pi/oprint/bin/python2 /home/pi/oprint/lib/python2.7/site-packages/octoprint_PrintTimeGenius/analyzers/analyze_progress.py marlin-calc /home/pi/.octoprint/uploads/BB8/Internal_-_CF_ABS.gcode M200 D3.00 M200 D0 M92 X100.50 Y100.50 Z1600.00 E420.00 M203 X300.00 Y300.00 Z3.00 E25.00 M201 X9000 Y9000 Z100 E10000 M204 P500.00 R3000.00 T500.00 M205 B20000 E10.00 S0.00 T0.00 X8.00 Y8.00 Z0.40
pi        2133  2128 99 Sep28 ?        1-00:49:54 /home/pi/oprint/lib/python2.7/site-packages/octoprint_PrintTimeGenius/analyzers/marlin-calc.armv7l /home/pi/.octoprint/uploads/BB8/Internal_-_CF_ABS.gcode M200 D3.00 M200 D0 M92 X100.50 Y100.50 Z1600.00 E420.00 M203 X300.00 Y300.00 Z3.00 E25.00 M201 X9000 Y9000 Z100 E10000 M204 P500.00 R3000.00 T500.00 M205 B20000 E10.00 S0.00 T0.00 X8.00 Y8.00 Z0.40

Killing 2128 which was the parent for 2133 fixed my issue. I could imagine this process potentially ending up in zombie state, in my case it happened to be churning away. If you notice, it showed up here with a parent process ID of 1, because its original parent process (427) was killed (I assume but think I can repeat). In my case, it was in a sleep state and stayed linked until I sent it a SIGKILL. After the killing the process all the lock on the serial port was cleared.

My hunch here is that only the process for OctoPrint exits on a reload when the entire parent group should exit before starting back up.

[gleonard3]

This also happened for me after updating PrintTimeGenius plugin.

I hope this log is of some value.

bug.log

[xxSniper0xx]

Had the same issue after updating PrintTimeGenius. Doing the following seems to have fixed it:

1. Login to Raspberry Pi using an SSH resource (I used Putty)
2. "sudo apt-get update" without quotations
3. Wait for it to finish
4. "sudo apt-get upgrade" without quotations
5. Wait for it to finish
6. "sudo reboot" without quotations

Hope this works for others.

[Patronics]

@superManny81 what command did you use to list the processes created by 'pi' and referencing Octoprint?

Also @xxSniper0xx are you sure the update and upgrade actually fixed the issue, and it wasn't just worked-around by the reboot? I encountered the issue again today, and I'm pretty sure I've done an apt-get update and upgrade since the first time I encountered the issue.

[xxSniper0xx]

@patronics Now that you mention it, it is possible the reboot fixed it via some work around. I have limited knowledge when it comes to anything linux. As for your first question, I did exactly what I wrote. Nothing more.

[ken-snyder]

I'm having the same exact issue, but I can reproduce it at will. Hopefully this will give some insight into the cause of the problem.

Relavant data:

Running OctoPrint 1.3.11 on RPi 2B+.

All plug-ins are already up to date.

Last change to the printer/OctoPrint:

1. In OctoPrint under Connection checked boxes for:
   
   
   
   • Save Connection Settings
   
   
   • Auto-connect on server startup
   
   

Reflashed the firmware from plug-in Firmware Updater and get the following error:
"SerialException: [Errno 11] Could not exclusively lock port /dev/ttyUSB0: [Errno 11] Resource temporarily unavailable"

• Minor change to firmware for long retraction from 100 to 150, could not have caused this error.
• Firmware compiled fine. Message from Firmware Updater said that the flash was successful.

Troubleshooting Actions:

1. Reflashed firmware with USB connection directly from Arduino IDE, bypassing OctoPrint. Flashed fine, no errors.
2. Reconnected RPi to printer and rebooted both. Same error, no change. Conclusion, firmware and flashing not the issue.
3. Working backwards, unchecked the two checkboxes I recently changed mentioned above and rebooted the RPi.
4. Ding, ding, ding!!! We have a winner! Problem went away.
5. I checked the boxes again, problem came back. Rebooting doesn't help.
6. I tested the checkboxes separately. Turns out that the first one "Save Connection Settings" is the problem. Leaving the second box checked does not cause the error.

I hope this helps get the bug fixed.

[foosel]

All plug-ins are already up to date.

Could you also share an octoprint.log so I get an overview of what these plugins are and a bunch of other environmental information?

[gleonard3]

I just updated plugin PrintTimeGenius to v. 2.0.2, and this issue did not reoccur. I did have to manually hit Connect, even though I had enabled "Auto-connect on server startup", however it did connect as expected with no issue.

[foosel]

What I'm currently thinking what is happening here is that for some reason any spawned sub processes (e.g. spawned by PrintTimeGenius) get the serial port handle inherited because the CLOSE_ON_EXEC flag maybe isn't set on it. I'm not sure if I can even set that from my client code though because it would have to be set somewhere deeeeeep inside pyserial.

Since this has so far only happened with PrintTimeGenius however - has someone opened a ticket about this on their end, just to rule out any implementation details I'm not aware of being the culprit here?

[foosel]

Pushed a potential fix for that, needs testing though. Will be part of the next release.

[tunatime]

I have the same issue, and I do not have PrintTimeGenius.

v1.3.12

Ran my first print with this version of OctoPrint. Connected, loaded gcode, pressed print. Print immediately Started and Finished. Pressed Print again. Lost connection to printer. Restarted and attempted to print again. Had the same issue.

Changing monitoring state from "Operational" to "Starting"
Send: N0 M110 N0*125
Recv: ok
Changing monitoring state from "Starting" to "Printing"
Changing monitoring state from "Printing" to "Finishing"
[...]
Send: N2 M400*37
Recv: ok
Changing monitoring state from "Finishing" to "Operational"
[...]
Changing monitoring state from "Operational" to "Starting"
Send: N0 M110 N0*125
Recv: ok
Changing monitoring state from "Starting" to "Printing"
Changing monitoring state from "Printing" to "Finishing"
[...]
Send: N2 M400*37
Recv: ok
Changing monitoring state from "Finishing" to "Operational"
[...]
Connection closed, closing down monitor
Changing monitoring state from "Operational" to "Offline"
Connecting to: /dev/ttyACM0
Changing monitoring state from "Offline" to "Error: Connection error, see Terminal tab"
Unexpected error while connecting to serial port: /dev/ttyACM0 SerialException: '[Errno 11] Could not exclusively lock port /dev/ttyACM0: [Errno 11] Resource temporarily unavailable' @ comm.py:_openSerial:2661 (hook default)
Connecting to: /dev/ttyACM0
Changing monitoring state from "Offline" to "Error: Connection error, see Terminal tab"

Killed:
root 691 0.0 0.4 4040 1748 tty1 Ss+ 04:21 0:00 /sbin/agetty --noclear tty1 linux
root 692 0.0 0.5 3860 1964 ? Ss+ 04:21 0:00 /sbin/agetty --keep-baud 115200 38400 9600 ttyAMA0 vt102

Reloaded the print, and printed again. This time I waited, and the print eventually started. There may be a race condition here, but the main gap seems to be that I shouldn't be able to start a Print if I can't get a lock on the port, and "Cancel" should be able to clear this lock.

I only use a single instance of OctoPrint.

[foosel]

1.4.0 has been released.

[rossmckelvie]

I am getting this error on 1.4.0 after cleaning data from a plugin and restarting

[ColPanic]

I'm having this same problem. I'm wondering if it might be a version problem with pyserial as I updated that recently (I think).

Was there ever a resolution for 1.4.0 (which is what I'm running)

[Arakon]

Seeing the same on my Ender 3 on a Pi Zero W, but never happened on my Mendel90 with a Pi 1B and later Pi 3B.

[corbolais]

Seeing this after installation of WS281x LED Status plugin.
Latest octoprint version.

edit: correct plugin name causing the issue.

[jneilliii]

@cp2004 would probably want to know about that in his plugin's repo issue tracker.

[cp2004]

@corbolais Please read issue here, if you're having this issue.
https://github.com/cp2004/OctoPrint-WS281x_LED_Status/issues/13