[Bug] While plugin is installed no reconnect after failure

[hawkeyexp]

i noticed a ugly behaviour:

system: rpi4 / octoprint 1.5.3 octopi 0.18

If plugin is enabled and an error was reported from printer and you try to reconnect it is not possible caused by no exclusive access to interface - seems the plugin blocks access to the interface.

Only restart of octoprint or disabling plugin helps. I think only solution would be checking if printer is disconnected and then stop service etc. which is used by plugin and only restart it after successfull reconnect.

[cp2004]

That's not the intended behaviour, the plugin should not interfere with the serial port at all - it doesn't go near it. It just runs some LEDs from the GPIO pins.

How do you connect your printer? Could you give more details about the hardware/setup and maybe I can try and reproduce? I have no idea how, but will look into it.

[hawkeyexp]

Hi,

i catched the behaviour from logs:

| Recv: Error:Heating failed, system stopped! Heater_ID: 0
| Recv: Error:Printer halted. kill() called!
2021-02-25 18:31:16,785 - octoprint.util.comm - INFO - Changing monitoring state from "Printing" to "Error: Heating failed, system stopped! Heater_ID: 0 - Printer halted. kill() called!"
2021-02-25 18:31:16,792 - octoprint.util.comm - INFO - Force-sending M112 to the printer
2021-02-25 18:31:16,813 - octoprint.util.comm - INFO - Changing monitoring state from "Error: Heating failed, system stopped! Heater_ID: 0 - Printer halted. kill() called!" to "Offline (Error: Heating failed, system stopped! Heater_ID: 0 - Printer halted. kill() called!)"
2021-02-25 18:31:16,841 - octoprint.plugins.action_command_notification - INFO - Notifications cleared
2021-02-25 18:31:17,011 - octoprint.plugins.DisplayLayerProgress - INFO - Printing stopped. Detailed progress stopped.
2021-02-25 18:31:17,035 - octoprint.plugins.filamentmanager - INFO - Updating Filament usage for octoprint configured toolcount: 1
2021-02-25 18:31:17,035 - octoprint.plugins.filamentmanager - INFO - Filament tracked toolcount: 1
2021-02-25 18:31:17,035 - octoprint.plugins.filamentmanager - INFO - Filament tracked values: [0.0]
2021-02-25 18:31:17,036 - octoprint.plugins.filamentmanager - INFO - Filament used: 0.0 mm (tool0)
2021-02-25 18:31:17,100 - octoprint.plugins.filamentmanager - INFO - Updated remaining filament on spool 'Transparent-Grün - PETG (M4P)' from 67.79354758647992g to 67.79354758647992g (0.0g)
2021-02-25 18:31:18,312 - tornado.access - WARNING - 409 GET /api/printer (::ffff:192.168.188.2) 6.84ms
2021-02-25 18:31:20,265 - tornado.access - WARNING - 409 GET /api/printer (::ffff:192.168.188.2) 8.27ms
2021-02-25 18:31:22,613 - tornado.access - WARNING - 409 GET /api/printer (::ffff:192.168.188.2) 4.98ms
2021-02-25 18:31:24,281 - tornado.access - WARNING - 409 GET /api/printer (::ffff:192.168.188.2) 8.92ms
2021-02-25 18:31:26,545 - tornado.access - WARNING - 409 GET /api/printer (::ffff:192.168.188.2) 38.25ms
2021-02-25 18:31:28,272 - tornado.access - WARNING - 409 GET /api/printer (::ffff:192.168.188.2) 13.26ms
2021-02-25 18:31:30,279 - tornado.access - WARNING - 409 GET /api/printer (::ffff:192.168.188.2) 10.83ms
2021-02-25 18:31:32,287 - tornado.access - WARNING - 409 GET /api/printer (::ffff:192.168.188.2) 9.19ms
2021-02-25 18:31:34,294 - tornado.access - WARNING - 409 GET /api/printer (::ffff:192.168.188.2) 9.03ms
2021-02-25 18:31:34,720 - octoprint.util.comm - INFO - Changing monitoring state from "Offline" to "Opening serial connection"
2021-02-25 18:31:34,722 - octoprint.util.comm - INFO - Connecting to port /dev/ttyUSB0, baudrate 250000
2021-02-25 18:31:34,761 - octoprint.util.comm - INFO - Changing monitoring state from "Opening serial connection" to "Error: Connection error, see Terminal tab"
2021-02-25 18:31:34,762 - octoprint.util.comm - INFO - Changing monitoring state from "Error: Connection error, see Terminal tab" to "Offline (Error: Connection error, see Terminal tab)"
2021-02-25 18:31:34,766 - octoprint.util.comm - ERROR - Unexpected error while connecting to serial port /dev/ttyUSB0, baudrate 250000 from hook default: SerialException: '[Errno 11] Could not exclusively lock port /dev/ttyUSB0: [Errno 11] Resource temporarily unavailable' @ comm.py:_open_serial:3670
Traceback (most recent call last):
  File "/home/pi/oprint/lib/python3.7/site-packages/serial/serialposix.py", line 385, in _reconfigure_port
    fcntl.flock(self.fd, fcntl.LOCK_EX | fcntl.LOCK_NB)
BlockingIOError: [Errno 11] Resource temporarily unavailable

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/pi/oprint/lib/python3.7/site-packages/octoprint/util/comm.py", line 3670, in _open_serial
    settings().getFloat(["serial", "timeout", "connection"]),
  File "/home/pi/oprint/lib/python3.7/site-packages/octoprint/util/comm.py", line 3644, in default
    serial_obj.open()
  File "/home/pi/oprint/lib/python3.7/site-packages/serial/serialposix.py", line 332, in open
    self._reconfigure_port(force_update=True)
  File "/home/pi/oprint/lib/python3.7/site-packages/serial/serialposix.py", line 387, in _reconfigure_port
    raise SerialException(msg.errno, "Could not exclusively lock port {}: {}".format(self._port, msg))
serial.serialutil.SerialException: [Errno 11] Could not exclusively lock port /dev/ttyUSB0: [Errno 11] Resource temporarily unavailable
2021-02-25 18:31:34,785 - octoprint.plugins.action_command_notification - INFO - Notifications cleared
2021-02-25 18:31:36,300 - tornado.access - WARNING - 409 GET /api/printer (::ffff:192.168.188.2) 9.44ms
2021-02-25 18:31:38,326 - tornado.access - WARNING - 409 GET /api/printer (::ffff:192.168.188.2) 5.44ms
2021-02-25 18:31:40,305 - tornado.access - WARNING - 409 GET /api/printer (::ffff:192.168.188.2) 9.97ms
2021-02-25 18:31:42,315 - tornado.access - WARNING - 409 GET /api/printer (::ffff:192.168.188.2) 9.33ms
2021-02-25 18:31:44,331 - tornado.access - WARNING - 409 GET /api/printer (::ffff:192.168.188.2) 8.69ms
2021-02-25 18:31:46,352 - tornado.access - WARNING - 409 GET /api/printer (::ffff:192.168.188.2) 10.62ms
2021-02-25 18:31:48,322 - tornado.access - WARNING - 409 GET /api/printer (::ffff:192.168.188.2) 8.71ms
2021-02-25 18:31:50,321 - tornado.access - WARNING - 409 GET /api/printer (::ffff:192.168.188.2) 17.76ms
2021-02-25 18:31:52,361 - tornado.access - WARNING - 409 GET /api/printer (::ffff:192.168.188.2) 9.99ms
2021-02-25 18:31:54,358 - tornado.access - WARNING - 409 GET /api/printer (::ffff:192.168.188.2) 9.17ms
2021-02-25 18:31:56,479 - tornado.access - WARNING - 409 GET /api/printer (::ffff:192.168.188.2) 5.05ms
2021-02-25 18:31:58,357 - tornado.access - WARNING - 409 GET /api/printer (::ffff:192.168.188.2) 9.26ms
2021-02-25 18:31:59,463 - octoprint.server.util.flask - INFO - Passively logging in user root from ::ffff:192.168.188.2
2021-02-25 18:31:59,469 - octoprint.access.users - INFO - Logged in user: root
2021-02-25 18:32:00,257 - octoprint.server.util.flask - INFO - Passively logging in user root from ::ffff:192.168.188.2
2021-02-25 18:32:00,258 - octoprint.access.users - INFO - Logged in user: root
2021-02-25 18:32:00,394 - tornado.access - WARNING - 409 GET /api/printer (::ffff:192.168.188.2) 8.42ms
2021-02-25 18:32:02,988 - tornado.access - WARNING - 409 GET /api/printer (::ffff:192.168.188.2) 10.16ms
2021-02-25 18:32:04,061 - octoprint.server.api.system - INFO - Performing command for core:restart: sudo service octoprint restart
2021-02-25 18:32:04,163 - octoprint.server - INFO - Shutting down...
2021-02-25 18:32:04,167 - octoprint.server.api.system - WARNING - Command for core:restart failed with return code -15:
! STDOUT: 
! STDERR: 

Printer is an i3 Mega-S with marlin 2.0 firmware - the effect only happens if the plugin is enabled - if plugin is disabled a reconnect is no problem - crazy behaviour

[cp2004]

I have something else for you to test:

• Reproduce the issue where it fails
• Open the settings of the plugin, and adjust something (a colour etc.)
• Hit save and then try and reconnect to the printer

An explanation for that: Changing the settings restarts the effect process and therefore the LED strip connection stuff, which may allow you to connect again.

I am going to be asking around for some help with this one, since I am not sure of how or if I can fix this, or even what is causing it. There are many people using this plugin, I did have one report way back in #13, and we never found a good solution beyond unchecking 'request exclusive access'. The plugin does not try and interfere with the printer in any way, I can only assume that it is the library beneath it that it breaking the serial communication.

While you're there, enable debug logging (plugin settings > features > debug logging) and then upload the plugin_ws281x_led_status_debug.log file so I can check there are no unusual settings there.

[hawkeyexp]

Hi,

i have checked it like you recommended:

force the error - enter settings - change a setting in plugin safe and now i can reconnect again without a problem - so the effect process seems to bee the problem.

Here is the debug log:

 | * STRIP SETTINGS *
 | - led_count: 52
 | - led_pin: 10
 | - led_freq_hz: 800000
 | - led_dma: 10
 | - led_invert: False
 | - led_brightness: 255
 | - led_channel: 0
 | - strip_type: WS2812_STRIP
 | - reverse: False
 | * EFFECT SETTINGS *
 | startup
 | - enabled: True
 | - color: #ffffff
 | - effect: solid
 | - delay: 25.0
 | idle
 | - enabled: True
 | - color: #003c3c
 | - effect: solid
 | - delay: 25.0
 | disconnected
 | - enabled: True
 | - color: #5b225b
 | - effect: solid
 | - delay: 25.0
 | progress_print
 | - enabled: True
 | - color: #00ff00
 | - base: #10010b
 | progress_heatup
 | - enabled: True
 | - color: #ff0000
 | - base: #0000ff
 | progress_cooling
 | - enabled: True
 | - color: #ff0000
 | - base: #0000ff
 | failed
 | - enabled: True
 | - color: #ff0000
 | - effect: pulse
 | - delay: 25.0
 | success
 | - enabled: True
 | - color: #808000
 | - effect: cycle
 | - delay: 25.0
 | paused
 | - enabled: True
 | - color: #0000ff
 | - effect: bounce
 | - delay: 25.0
 | printing
 | - enabled: False
 | - color: #000080
 | - effect: cross
 | - delay: 1.0
 | torch
 | - enabled: True
 | - color: #ffffff
 | - effect: solid
 | - delay: 25.0
 | * ACTIVE TIMES *
 | - start: 08:00
 | - end: 00:00
[2021-03-06 15:46:45,101] INFO: On message recieved, turning on LEDs
[2021-03-06 15:46:57,565] DEBUG: Recieved message to change effect: idle
[2021-03-06 15:47:12,008] DEBUG: Recieved message to change effect: disconnected
[2021-03-06 15:49:51,068] INFO: Kill message recieved, Bye!
[2021-03-06 15:49:51,120] INFO: Initialising LED strip
[2021-03-06 15:49:51,121] INFO: Strip successfully initialised
[2021-03-06 15:49:51,123] DEBUG: Current settings:
 | * STRIP SETTINGS *
 | - led_count: 52
 | - led_pin: 10
 | - led_freq_hz: 800000
 | - led_dma: 10
 | - led_invert: False
 | - led_brightness: 255
 | - led_channel: 0
 | - strip_type: WS2812_STRIP
 | - reverse: False
 | * EFFECT SETTINGS *
 | startup
 | - enabled: True
 | - color: #c0c0c0
 | - effect: solid
 | - delay: 25.0
 | idle
 | - enabled: True
 | - color: #003c3c
 | - effect: solid
 | - delay: 25.0
 | disconnected
 | - enabled: True
 | - color: #5b225b
 | - effect: solid
 | - delay: 25.0
 | progress_print
 | - enabled: True
 | - color: #00ff00
 | - base: #10010b
 | progress_heatup
 | - enabled: True
 | - color: #ff0000
 | - base: #0000ff
 | progress_cooling
 | - enabled: True
 | - color: #ff0000
 | - base: #0000ff
 | failed
 | - enabled: True
 | - color: #ff0000
 | - effect: pulse
 | - delay: 25.0
 | success
 | - enabled: True
 | - color: #808000
 | - effect: cycle
 | - delay: 25.0
 | paused
 | - enabled: True
 | - color: #0000ff
 | - effect: bounce
 | - delay: 25.0
 | printing
 | - enabled: False
 | - color: #000080
 | - effect: cross
 | - delay: 1.0
 | torch
 | - enabled: True
 | - color: #ffffff
 | - effect: solid
 | - delay: 25.0
 | * ACTIVE TIMES *
 | - start: 08:00
 | - end: 00:00
[2021-03-06 15:49:51,124] INFO: On message recieved, turning on LEDs
[2021-03-06 15:50:04,635] DEBUG: Recieved message to change effect: idle

[cp2004]

Thanks, that kind of confirms my suspicions - it seems in your case that when the serial port goes down, something inside the effect running code is taking some control of this. I am not sure how this might be fixed - the library it depends on does not get much attention, pretty much everything is PR led - I don't hold out much hope if I even manage to find the bug that it would be fixed.

I will still ask to see if it is something related to the use of multiprocessing in the plugin - I hope not, but in that case I may be able to fix it. At least it is kind of confirmed part of the issue. I've never experienced this or been able to reproduce, so everything I have to go by is theoretical.

[hawkeyexp]

One solution is working: by default octoprint enables exclusive access which could be disabled via gui - i tried out and it sems all is working currently without problems - printing + light :-)