[Bug] Serial reconnect failure with plugin active

[guigro]

Description of the bug

I use the TP Link SmartPlug plugin to shut down the printer on idle and put it back on when I upload a file. When it's powered off and I try to power it on, Octoprint can't connect to the printer again, until I restart Octoprint.

I guess it's the same if I have Octoprint running and then power off manually the printer, the power it back on.

For info : Pi running is a 4, and the printer is a Prusa MK3S.

Steps to reproduce

1. When you're on Octoprint with the printer in Idle state (connected and working). Look nicely at the screen and love your devices.
2. Manually power off the printer (from the power source, power unit, power cable) but keep Octoprint runiing.
3. Power back the printer
4. Try to connect
5. There should be an error message
6. To make it work, you have to restart Octoprint

What did you expect to happen

I expect the printer to go back on and Octoprint to be able to reconnect to it :)

Logs and screenshots plugin_ws281x_led_status_debug.log :

[2021-04-20 17:56:05,858] INFO: Kill message recieved, all effects stopped. Bye!
[2021-04-20 17:56:05,905] INFO: Initialising LED strip
[2021-04-20 17:56:05,908] INFO: Strip successfully initialised
[2021-04-20 17:56:05,909] DEBUG: Current settings:
 | * STRIP SETTINGS *
 | - count: 64
 | - dma: 10
 | - reverse: False
 | - pin: 10
 | - brightness: 100
 | - freq_hz: 800000
 | - invert: False
 | - white_override: False
 | - white_brightness: 50
 | - adjustment: {u'B': 100, u'R': 100, u'G': 100}
 | - type: WS2811_STRIP_GRB
 | - channel: 0
 | * EFFECT SETTINGS *
 | disconnected
 | - color: #ff0000
 | - delay: 20
 | - enabled: False
 | - effect: Color Wipe
 | success
 | - color: #00ff00
 | - delay: 25
 | - enabled: True
 | - effect: Color Wipe
 | - return_to_idle: 300
 | progress_cooling
 | - color: #ff0000
 | - enabled: True
 | - effect: Progress Bar
 | - base: #0000ff
 | - bed_or_tool: tool
 | - threshold: 40
 | torch
 | - color: #ffffff
 | - enabled: True
 | - effect: Solid Color
 | - timer: 15
 | - delay: 1
 | - toggle: True
 | - auto_on_webcam: True
 | startup
 | - color: #00ff00
 | - delay: 75
 | - enabled: True
 | - effect: Color Wipe
 | progress_print
 | - color: #00ff00
 | - base: #ffffff
 | - enabled: True
 | - effect: Progress Bar
 | paused
 | - color: #ff8800
 | - delay: 40
 | - enabled: True
 | - effect: Color Wipe
 | failed
 | - color: #ff0000
 | - delay: 10
 | - enabled: True
 | - effect: Solid Color
 | idle
 | - color: #000000
 | - delay: 75
 | - enabled: True
 | - effect: Solid Color
 | - timeout: 0
 | printing
 | - color: #ffffff
 | - delay: 1
 | - enabled: False
 | - effect: Solid Color
 | progress_heatup
 | - color: #ff0000
 | - enabled: True
 | - effect: Progress Bar
 | - tool_enabled: True
 | - base: #0000ff
 | - bed_enabled: True
 | - tool_key: 0
 | * ACTIVE TIMES *
 | - enabled: False
 | - start: 09:00
 | - end: 21:00
[2021-04-20 17:56:05,914] INFO: On message received, turning on LEDs to idle

octoprint.log :

2021-04-20 17:56:05,866 - octoprint.plugins.ws281x_led_status - INFO - WS281x LED Status runner stopped
2021-04-20 17:56:05,867 - octoprint.plugins.ws281x_led_status - INFO - WS281x LED Status runner stopped
2021-04-20 17:56:05,886 - octoprint.plugins.ws281x_led_status - INFO - WS281x LED Status runner started
2021-04-20 17:56:06,422 - octoprint.plugins.excluderegion - INFO - Setting update detected: g90InfluencesExtruder=False, clearRegionsAfterPrintFinishes=False, mayShrinkRegionsWhilePrinting=False, loggingMode=octoprint, enteringExcludedRegionGcode=None, exitingExcludedRegionGcode=None, extendedExcludeGcodes={'M73': {"gcode": "M73", "type": "ExcludedGcode", "mode": "merge", "description": "Suppress progress updates while excluding and output the most recent progress values encountered when exiting the excluded area"}, 'M117': {"gcode": "M117", "type": "ExcludedGcode", "mode": "last", "description": "Suppress display messages while excluding and output the last message encountered when exiting the excluded area"}, 'G4': {"gcode": "G4", "type": "ExcludedGcode", "mode": "exclude", "description": "Ignore all dwell commands in an excluded area to reduce delays while excluding"}, 'M205': {"gcode": "M205", "type": "ExcludedGcode", "mode": "merge", "description": "Record advanced setting changes while excluding and apply the most recent values in a single command after exiting the excluded area"}, 'M204': {"gcode": "M204", "type": "ExcludedGcode", "mode": "merge", "description": "Record default acceleration changes while excluding and apply the most recent values in a single command after exiting the excluded area"}}, atCommandActions={'ExcludeRegion': [{"action": "enable_exclusion", "type": "AtCommandAction", "command": "ExcludeRegion", "parameterPattern": "^\\s*(enable|on)(\\s|$)", "description": "Default action to enable exclusion"}, {"action": "disable_exclusion", "type": "AtCommandAction", "command": "ExcludeRegion", "parameterPattern": "^\\s*(disable|off)(\\s|$)", "description": "Default action to disable exclusion"}]}
2021-04-20 17:56:14,356 - octoprint.util.comm - INFO - Changing monitoring state from "Operational" to "Offline"
2021-04-20 17:56:14,366 - octoprint.plugins.action_command_notification - INFO - Notifications cleared
2021-04-20 17:56:36,631 - octoprint.util.comm - INFO - Changing monitoring state from "Offline" to "Detecting serial connection"
2021-04-20 17:56:36,679 - octoprint.util.comm - INFO - Serial detection: Performing autodetection with 4 port/baudrate candidates: /dev/ttyACM0@115200, /dev/ttyACM0@250000, /dev/ttyS0@115200, /dev/ttyS0@250000
2021-04-20 17:56:36,680 - octoprint.util.comm - INFO - Serial detection: Trying port /dev/ttyACM0, baudrate 115200
2021-04-20 17:56:36,681 - octoprint.util.comm - INFO - Connecting to port /dev/ttyACM0, baudrate 115200
2021-04-20 17:56:36,688 - octoprint.util.comm - ERROR - Unexpected error while connecting to serial port /dev/ttyACM0, baudrate 115200 from hook default: SerialException: '[Errno 11] Could not exclusively lock port /dev/ttyACM0: [Errno 11] Resource temporarily unavailable' @ comm.py:_open_serial:3670
Traceback (most recent call last):
  File "/home/pi/oprint/local/lib/python2.7/site-packages/octoprint/util/comm.py", line 3670, in _open_serial
    settings().getFloat(["serial", "timeout", "connection"]),
  File "/home/pi/oprint/local/lib/python2.7/site-packages/octoprint/util/comm.py", line 3644, in default
    serial_obj.open()
  File "/home/pi/oprint/local/lib/python2.7/site-packages/serial/serialposix.py", line 272, in open
    self._reconfigure_port(force_update=True)
  File "/home/pi/oprint/local/lib/python2.7/site-packages/serial/serialposix.py", line 312, in _reconfigure_port
    raise SerialException(msg.errno, "Could not exclusively lock port {}: {}".format(self._port, msg))
SerialException: [Errno 11] Could not exclusively lock port /dev/ttyACM0: [Errno 11] Resource temporarily unavailable
2021-04-20 17:56:36,690 - octoprint.util.comm - INFO - Serial detection: Could not open port /dev/ttyACM0, baudrate 115200, skipping
2021-04-20 17:56:36,691 - octoprint.util.comm - INFO - Serial detection: Trying port /dev/ttyACM0, baudrate 250000
2021-04-20 17:56:36,691 - octoprint.util.comm - INFO - Connecting to port /dev/ttyACM0, baudrate 250000
2021-04-20 17:56:36,694 - octoprint.util.comm - ERROR - Unexpected error while connecting to serial port /dev/ttyACM0, baudrate 250000 from hook default: SerialException: '[Errno 11] Could not exclusively lock port /dev/ttyACM0: [Errno 11] Resource temporarily unavailable' @ comm.py:_open_serial:3670
Traceback (most recent call last):
  File "/home/pi/oprint/local/lib/python2.7/site-packages/octoprint/util/comm.py", line 3670, in _open_serial
    settings().getFloat(["serial", "timeout", "connection"]),
  File "/home/pi/oprint/local/lib/python2.7/site-packages/octoprint/util/comm.py", line 3644, in default
    serial_obj.open()
  File "/home/pi/oprint/local/lib/python2.7/site-packages/serial/serialposix.py", line 272, in open
    self._reconfigure_port(force_update=True)
  File "/home/pi/oprint/local/lib/python2.7/site-packages/serial/serialposix.py", line 312, in _reconfigure_port
    raise SerialException(msg.errno, "Could not exclusively lock port {}: {}".format(self._port, msg))
SerialException: [Errno 11] Could not exclusively lock port /dev/ttyACM0: [Errno 11] Resource temporarily unavailable
2021-04-20 17:56:36,695 - octoprint.util.comm - INFO - Serial detection: Could not open port /dev/ttyACM0, baudrate 250000, skipping
2021-04-20 17:56:36,696 - octoprint.util.comm - INFO - Serial detection: Trying port /dev/ttyS0, baudrate 115200
2021-04-20 17:56:36,697 - octoprint.util.comm - INFO - Connecting to port /dev/ttyS0, baudrate 115200
2021-04-20 17:56:36,699 - octoprint.util.comm - ERROR - Unexpected error while connecting to serial port /dev/ttyS0, baudrate 115200 from hook default: SerialException: '[Errno 13] could not open port /dev/ttyS0: [Errno 13] Permission denied: '/dev/ttyS0'' @ comm.py:_open_serial:3670
Traceback (most recent call last):
  File "/home/pi/oprint/local/lib/python2.7/site-packages/octoprint/util/comm.py", line 3670, in _open_serial
    settings().getFloat(["serial", "timeout", "connection"]),
  File "/home/pi/oprint/local/lib/python2.7/site-packages/octoprint/util/comm.py", line 3644, in default
    serial_obj.open()
  File "/home/pi/oprint/local/lib/python2.7/site-packages/serial/serialposix.py", line 268, in open
    raise SerialException(msg.errno, "could not open port {}: {}".format(self._port, msg))
SerialException: [Errno 13] could not open port /dev/ttyS0: [Errno 13] Permission denied: '/dev/ttyS0'
2021-04-20 17:56:36,700 - octoprint.util.comm - INFO - Serial detection: Could not open port /dev/ttyS0, baudrate 115200, skipping
2021-04-20 17:56:36,701 - octoprint.util.comm - INFO - Serial detection: Trying port /dev/ttyS0, baudrate 250000
2021-04-20 17:56:36,701 - octoprint.util.comm - INFO - Connecting to port /dev/ttyS0, baudrate 250000
2021-04-20 17:56:36,703 - octoprint.util.comm - ERROR - Unexpected error while connecting to serial port /dev/ttyS0, baudrate 250000 from hook default: SerialException: '[Errno 13] could not open port /dev/ttyS0: [Errno 13] Permission denied: '/dev/ttyS0'' @ comm.py:_open_serial:3670
Traceback (most recent call last):
  File "/home/pi/oprint/local/lib/python2.7/site-packages/octoprint/util/comm.py", line 3670, in _open_serial
    settings().getFloat(["serial", "timeout", "connection"]),
  File "/home/pi/oprint/local/lib/python2.7/site-packages/octoprint/util/comm.py", line 3644, in default
    serial_obj.open()
  File "/home/pi/oprint/local/lib/python2.7/site-packages/serial/serialposix.py", line 268, in open
    raise SerialException(msg.errno, "could not open port {}: {}".format(self._port, msg))
SerialException: [Errno 13] could not open port /dev/ttyS0: [Errno 13] Permission denied: '/dev/ttyS0'
2021-04-20 17:56:36,704 - octoprint.util.comm - INFO - Serial detection: Could not open port /dev/ttyS0, baudrate 250000, skipping
2021-04-20 17:56:36,705 - octoprint.util.comm - INFO - Changing monitoring state from "Detecting serial connection" to "Error: No more candidates to test, and no working port/baudrate combination detected."
2021-04-20 17:56:36,708 - octoprint.util.comm - INFO - Changing monitoring state from "Error: No more candidates to test, and no working port/baudrate combination detected." to "Offline (Error: No more candidates to test, and no working port/baudrate combination detected.)"
2021-04-20 17:56:36,712 - octoprint.plugins.excluderegion - INFO - Printing stopped: event=Error
2021-04-20 17:56:36,726 - octoprint.plugins.action_command_notification - INFO - Notifications cleared
2021-04-20 17:57:30,766 - octoprint.server.util.flask - INFO - Passively logging in user guigro from ****
2021-04-20 17:57:30,768 - octoprint.access.users - INFO - Logged in user: guigro
2021-04-20 17:57:30,951 - octoprint.server.util.sockjs - INFO - Client connection closed: ****
2021-04-20 17:57:32,090 - octoprint.server.util.sockjs - INFO - New connection from client: ****
2021-04-20 17:57:32,131 - octoprint.server.util.flask - INFO - Passively logging in user guigro from ****
2021-04-20 17:57:32,133 - octoprint.access.users - INFO - Logged in user: guigro
2021-04-20 17:57:34,087 - octoprint.server.util.sockjs - INFO - User **** logged in on the socket from client ::ffff:192.168.50.100

Version of plugin and OctoPrint

Plugin 0.7.2 Octoprint : 1.5.3

(If applicable) Browser version & browser error console

Not applicable

Additional context

I made the same kind of feedback to the TPLinkSmartPlug plugin creator on his Github

[cp2004]

A duplicate of #113 & #13, yeah I have no idea how to fix this one. I still haven't been able to reproduce the issue here to try and fix it. It obviously does not affect all that many people, since I have 3 reports of it in like 8 months & over 780 instances in the last month.

The latest theory we were able to come up with was that there was a resource being inherited by the sub process the plugin uses to run the LED strip & effects etc.

There are two current workarounds, not necessary to restart OctoPrint:

• Open the settings dialog -> change a WS281x setting > save. This will cause the process to restart, removing the resource lock.
• Uncheck 'request exclusive access to the serial port' in the serial connection settings

I will look into it again - but I can't guarantee I'll be able to find much. It could be printer/hardware specific, but there is no pattern with the people that have this issue. I spent ages looking through documentation and code, to find nothing of much use...

[guigro]

Alright you got it, the second tip (the request exclusive) make it work perfectly !

Sorry for the duplicate, and thanks for the amazing work !