search

EricHigdon / OctoPrint-RGB_status

Adds RGB LED support to OctoPrint with the ability to choose effects based on the current status of your printer
33 stars 12 forks source link

Problem with restarting Octoprint because of RGBstatus with Raspberry Pi 4 latest octoprint #65

Closed vldfr closed 4 years ago

vldfr commented 4 years ago

Whenever I install a new plugin(after installing RGB status) i have to reboot the entire Raspberry Pi because Octoprint can't bind to the port 5000, because it says it's still in use: 2020-05-02 00:24:30,391 - octoprint.cli.server - ERROR - Uncaught exception Traceback (most recent call last): File "/home/pi/OctoPrint/venv/bin/octoprint", line 8, in <module> sys.exit(main()) File "/home/pi/OctoPrint/venv/local/lib/python2.7/site-packages/octoprint/__init__.py", line 615, in main octo(args=args, prog_name="octoprint", auto_envvar_prefix="OCTOPRINT") File "/home/pi/OctoPrint/venv/local/lib/python2.7/site-packages/click/core.py", line 764, in __call__ return self.main(*args, **kwargs) File "/home/pi/OctoPrint/venv/local/lib/python2.7/site-packages/click/core.py", line 717, in main rv = self.invoke(ctx) File "/home/pi/OctoPrint/venv/local/lib/python2.7/site-packages/click/core.py", line 1137, in invoke return _process_result(sub_ctx.command.invoke(sub_ctx)) File "/home/pi/OctoPrint/venv/local/lib/python2.7/site-packages/click/core.py", line 956, in invoke return ctx.invoke(self.callback, **ctx.params) File "/home/pi/OctoPrint/venv/local/lib/python2.7/site-packages/click/core.py", line 555, in invoke return callback(*args, **kwargs) File "/home/pi/OctoPrint/venv/local/lib/python2.7/site-packages/click/decorators.py", line 17, in new_func return f(get_current_context(), *args, **kwargs) File "/home/pi/OctoPrint/venv/local/lib/python2.7/site-packages/octoprint/cli/server.py", line 207, in serve_command ignore_blacklist) File "/home/pi/OctoPrint/venv/local/lib/python2.7/site-packages/octoprint/cli/server.py", line 119, in run_server octoprint_server.run() File "/home/pi/OctoPrint/venv/local/lib/python2.7/site-packages/octoprint/server/__init__.py", line 305, in run self._start_intermediary_server() File "/home/pi/OctoPrint/venv/local/lib/python2.7/site-packages/octoprint/server/__init__.py", line 1863, in _start_intermediary_server self._intermediary_server.server_bind() File "/usr/lib/python2.7/BaseHTTPServer.py", line 108, in server_bind SocketServer.TCPServer.server_bind(self) File "/usr/lib/python2.7/SocketServer.py", line 434, in server_bind self.socket.bind(self.server_address) File "/usr/lib/python2.7/socket.py", line 228, in meth return getattr(self._sock,name)(*args) error: [Errno 98] Address already in use

Recently it happened with the command M112(emergency stop) as well. after m112 is issued, the printer halts, i restart it and Octoprint can't connect to it, saying that the serial port is locked.(doesn't happen after disabling rgb-status),

2020-05-01 23:35:06,029 - octoprint.util.comm - INFO - Changing monitoring state from "Offline" to "Error: C onnection error, see Terminal tab" 2020-05-01 23:35:06,034 - octoprint.util.comm - ERROR - Unexpected error while connecting to serial port: /d ev/ttyACM0 SerialException: '[Errno 11] Could not exclusively lock port /dev/ttyACM0: [Errno 11] Resource te mporarily unavailable' @ comm.py:_openSerial:2691 (hook default) Traceback (most recent call last): File "/home/pi/OctoPrint/venv/local/lib/python2.7/site-packages/octoprint/util/comm.py", line 2691, in _op enSerial serial_obj = factory(self, self._port, self._baudrate, settings().getFloat(["serial", "timeout", "connec tion"])) File "/home/pi/OctoPrint/venv/local/lib/python2.7/site-packages/octoprint/util/comm.py", line 2671, in def ault serial_obj.open() File "/home/pi/OctoPrint/venv/local/lib/python2.7/site-packages/serial/serialposix.py", line 272, in open self._reconfigure_port(force_update=True) File "/home/pi/OctoPrint/venv/local/lib/python2.7/site-packages/serial/serialposix.py", line 312, in _reco nfigure_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 un available

I am running a raspberry Pi 4, 4GB RAM, latest octoprint, all updates installed(both rasPi and Octoprint)

cp2004 commented 4 years ago

I think I might have this issue as well. Didn't think much of it but last few times I have tried to install plugins and restart it hasn't worked. It was on Pi3 I think though - I've just upgraded. I'll have to have another look

vldfr commented 4 years ago

I have a theory: It might be because of the mandatory update to Python 3(that the latest Octoprint server requires) but I can't say for sure.

cp2004 commented 4 years ago

It's not a mandatory update to python 3, OctoPrint will run on both. As I understand it, they are waiting for more plugins to have compatability before forcing it. As of OctoPrint 1.4.0 it supports both Python 2 and 3 simultaneously and it is up to the user which to run on and up to plugin authors to do so too.

vldfr commented 4 years ago

Oh, I see, i just read that they want to keep Python 2 until 2021

drewzh commented 4 years ago

I also have this with my RP3 (latest versions of Octoprint/RGB). I have to manually SSH in and restart the server each time. Last I checked it looked like some sort of resource lock.

kareemtawab commented 4 years ago

I'm having the same issue with my RPi4 running latest version of Octoprint v1.4.0 and plugin v1.6.0. The system restarts in safe mode on power up and I need to restart it again to get it to boot in normal mode. Looking in the logs:

2020-05-24` 01:20:57,842 - octoprint.startup - INFO - ** 2020-05-24 01:20:57,843 - octoprint.startup - INFO - Starting OctoPrint 1.4.0 2020-05-24 01:20:57,844 - octoprint.startup - INFO - ** 2020-05-24 01:20:58,255 - octoprint.util.connectivity_checker - INFO - Connectivity changed from offline to online 2020-05-24 01:20:59,261 - octoprint.startup - INFO - Blacklist processing done, adding 1 blacklisted plugin versions: roomtemp (any) 2020-05-24 01:20:59,318 - 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... 2020-05-24 01:20:59,773 - octoprint.plugin.core - INFO - Plugin Virtual Printer is disabled. 2020-05-24 01:21:00,143 - py.warnings - WARNING - /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_telegram/init.py:5: ExtDeprecationWarning: Importing flask.ext.babel is deprecated, use flask_babel instead. from flask.ext.babel import gettext 2020-05-24 01:21:00,144 - py.warnings - WARNING - /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_telegram/init.py:6: ExtDeprecationWarning: Importing flask.ext.login is deprecated, use flask_login instead. from flask.ext.login import current_user 2020-05-24 01:21:01,159 - octoprint.plugins.errortracking - INFO - Initialized error tracking 2020-05-24 01:21:01,161 - octoprint.startup - INFO - Added settings overlay from plugin filetab 2020-05-24 01:21:01,168 - octoprint.startup - INFO - Added settings overlay from plugin dashboard 2020-05-24 01:21:01,171 - octoprint.plugin.core - INFO - Found 40 plugin(s) providing 39 mixin implementations, 73 hook handlers 2020-05-24 01:21:01,498 - octoprint.server.heartbeat - INFO - Starting server heartbeat, 900.0s interval 2020-05-24 01:21:01,622 - octoprint.cli.server - ERROR - Uncaught exception Traceback (most recent call last): File "/home/pi/oprint/bin/octoprint", line 8, in sys.exit(main()) File "/home/pi/oprint/local/lib/python2.7/site-packages/octoprint/init.py", line 615, in main octo(args=args, prog_name="octoprint", auto_envvar_prefix="OCTOPRINT") File "/home/pi/oprint/local/lib/python2.7/site-packages/click/core.py", line 764, in call return self.main(args, kwargs) File "/home/pi/oprint/local/lib/python2.7/site-packages/click/core.py", line 717, in main rv = self.invoke(ctx) File "/home/pi/oprint/local/lib/python2.7/site-packages/click/core.py", line 1137, in invoke return _process_result(sub_ctx.command.invoke(sub_ctx)) File "/home/pi/oprint/local/lib/python2.7/site-packages/click/core.py", line 956, in invoke return ctx.invoke(self.callback, ctx.params) File "/home/pi/oprint/local/lib/python2.7/site-packages/click/core.py", line 555, in invoke return callback(args, kwargs) File "/home/pi/oprint/local/lib/python2.7/site-packages/click/decorators.py", line 17, in new_func return f(get_current_context(), *args, *kwargs) File "/home/pi/oprint/local/lib/python2.7/site-packages/octoprint/cli/server.py", line 207, in serve_command ignore_blacklist) File "/home/pi/oprint/local/lib/python2.7/site-packages/octoprint/cli/server.py", line 119, in run_server octoprint_server.run() File "/home/pi/oprint/local/lib/python2.7/site-packages/octoprint/server/init.py", line 305, in run self._start_intermediary_server() File "/home/pi/oprint/local/lib/python2.7/site-packages/octoprint/server/init.py", line 1863, in _start_intermediary_server self._intermediary_server.server_bind() File "/usr/lib/python2.7/BaseHTTPServer.py", line 108, in server_bind SocketServer.TCPServer.server_bind(self) File "/usr/lib/python2.7/SocketServer.py", line 434, in server_bind self.socket.bind(self.server_address) File "/usr/lib/python2.7/socket.py", line 228, in meth return getattr(self._sock,name)(args) error: [Errno 98] Address already in use 2020-05-24 01:25:00,860 - octoprint.startup - INFO - **** 2020-05-24 01:25:00,861 - octoprint.startup - INFO - Starting OctoPrint 1.4.0 2020-05-24 01:25:00,861 - octoprint.startup - INFO - Starting in SAFE MODE. Third party plugins will be disabled! 2020-05-24 01:25:00,862 - octoprint.startup - INFO - Reason for safe mode: problem during last startup 2020-05-24 01:25:00,863 - octoprint.startup - INFO - ** 2020-05-24 01:25:02,184 - octoprint.startup - INFO - We don't appear to be online, not fetching plugin blacklist 2020-05-24 01:25:02,331 - 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... 2020-05-24 01:25:04,381 - octoprint.plugin.core - INFO - Plugin Virtual Printer is disabled. 2020-05-24 01:25:05,844 - octoprint.plugins.errortracking - INFO - Initialized error tracking 2020-05-24 01:25:05,846 - octoprint.plugin.core - INFO - Found 40 plugin(s) providing 14 mixin implementations, 26 hook handlers 2020-05-24 01:25:05,990 - octoprint.server.heartbeat - INFO - Starting server heartbeat, 900.0s interval 2020-05-24 01:25:06,069 - octoprint.server - INFO - Intermediary server started 2020-05-24 01:25:06,070 - 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... 2020-05-24 01:25:06,161 - octoprint.plugin.core - INFO - Found 40 plugin(s) providing 14 mixin implementations, 26 hook handlers 2020-05-24 01:25:06,206 - octoprint.filemanager.storage - INFO - Initializing the file metadata for /home/pi/.octoprint/uploads... 2020-05-24 01:25:06,512 - octoprint.filemanager.storage - INFO - ... file metadata for /home/pi/.octoprint/uploads initialized successfully. 2020-05-24 01:25:06,515 - octoprint.server - INFO - Added new permission from plugin action_command_prompt: PLUGIN_ACTION_COMMAND_PROMPT_INTERACT (needs: u"Need(method='role', value=u'plugin_action_command_prompt_interact')") 2020-05-24 01:25:06,517 - octoprint.server - INFO - Added new permission from plugin announcements: PLUGIN_ANNOUNCEMENTS_READ (needs: u"Need(method='role', value=u'plugin_announcements_read')") 2020-05-24 01:25:06,518 - octoprint.server - INFO - Added new permission from plugin announcements: PLUGIN_ANNOUNCEMENTS_MANAGE (needs: u"Need(method='role', value=u'plugin_announcements_manage'), Need(method='role', value=u'plugin_announcements_read')") 2020-05-24 01:25:06,519 - octoprint.server - INFO - Added new permission from plugin appkeys: PLUGIN_APPKEYS_ADMIN (needs: u"Need(method='role', value=u'plugin_appkeys_admin')") 2020-05-24 01:25:06,520 - octoprint.server - INFO - Added new permission from plugin backup: PLUGIN_BACKUP_ACCESS (needs: u"Need(method='role', value=u'plugin_backup_access')")

I'm seeing error: [Errno 98] Address already in use that causes the server to restart in safe mode. I guess that the main service is not able to bind to port 5000.

I did $ sudo netstat -nlap|grep 5000 once after the plugin is installed:

tcp 0 0 127.0.0.1:5000 0.0.0.0: LISTEN 461/python2 tcp 0 0 127.0.0.1:5000 127.0.0.1:47620 ESTABLISHED 461/python2 tcp 0 0 127.0.0.1:47620 127.0.0.1:5000 ESTABLISHED 558/haproxy udp 0 0 0.0.0.0:50009 0.0.0.0: 556/haproxy

and once after the plugin is removed and cleaning its data:

tcp 0 0 127.0.0.1:5000 0.0.0.0:* LISTEN 458/python2 tcp 0 0 127.0.0.1:5000 127.0.0.1:45656 ESTABLISHED 458/python2 tcp 0 0 127.0.0.1:45656 127.0.0.1:5000 ESTABLISHED 589/haproxy

Removing the plugin and cleaning its data makes the system boot in normal mode on every power up as it should.

kareemtawab commented 4 years ago

That doesn't seem interesting?

cp2004 commented 4 years ago

I've done some digging and testing with this plugin, and it appears that it blocks Octoprint from shutting down. I've got a few likely candidates to investigate but will have to do some more experimentation to find the route cause.

Below is what a successful restart from the command line sudo service octoprint stop looks like, I wrote the plugin TestShutdown where all it does is log from the events octoprint.plugins.StartupPlugin.on_after_startup and octoprint.plugins.ShutdownPlugin.on_shutdown() to test the above theory

2020-06-08 10:37:55,453 - octoprint.server - INFO - Shutting down...
2020-06-08 10:37:56,287 - octoprint.events - INFO - Processing shutdown event, this will be our last event
2020-06-08 10:37:56,297 - octoprint.events - INFO - Event loop shut down
2020-06-08 10:37:56,329 - octoprint.plugins.TestShutdown - INFO - Shutting down! (plugin)
2020-06-08 10:37:56,332 - octoprint.server - INFO - Goodbye!
2020-06-08 10:37:59,291 - octoprint.startup - INFO - ******************************************************************************
2020-06-08 10:37:59,293 - octoprint.startup - INFO - Starting OctoPrint 1.4.0
2020-06-08 10:37:59,294 - octoprint.startup - INFO - ******************************************************************************
2020-06-08 10:37:59,376 - octoprint.startup - INFO - We don't appear to be online, not fetching plugin blacklist
2020-06-08 10:37:59,407 - octoprint.util.connectivity_checker - INFO - Connectivity changed from offline to online

And this is what it looks like when this plugin is enabled (below). The sudo service octoprint restart also hangs for a while whereas without the plugin it is near instant. Note no shutdown event:

2020-06-08 13:15:31,041 - octoprint.server.preemptive_cache - INFO - Preemptively caching / (ui _default) for {'query_string': 'l10n=en', 'path': '/', 'base_url': 'http://192.168.0.142/'}
2020-06-08 13:15:44,377 - octoprint.server.preemptive_cache - INFO - ... done in 13.34s
2020-06-08 13:15:44,378 - octoprint.server.preemptive_cache - INFO - Preemptively caching / (ui _default) for {'query_string': 'l10n=en', 'path': '/', 'base_url': 'http://127.0.0.1/'}
2020-06-08 13:15:47,187 - octoprint.server.preemptive_cache - INFO - ... done in 2.81s
2020-06-08 13:16:33,933 - octoprint.startup - INFO - ******************************************************************************
2020-06-08 13:16:33,935 - octoprint.startup - INFO - Starting OctoPrint 1.4.0
2020-06-08 13:16:33,935 - octoprint.startup - INFO - ******************************************************************************
2020-06-08 13:16:33,992 - octoprint.util.connectivity_checker - INFO - Connectivity changed from offline to online
2020-06-08 13:16:33,995 - octoprint.startup - INFO - Blacklist processing done, adding 1 blacklisted plugin versions: roomtemp (any)
2020-06-08 13:16:34,025 - 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...
2020-06-08 13:16:35,774 - octoprint.startup - INFO - Added settings overlay from plugin dashboard
2020-06-08 13:16:35,776 - octoprint.plugin.core - INFO - Found 32 plugin(s) providing 32 mixin implementations, 66 hook handlers
2020-06-08 13:16:35,988 - octoprint.server.heartbeat - INFO - Starting server heartbeat, 900.0s interval
2020-06-08 13:16:36,002 - octoprint.cli.server - ERROR - Uncaught exception

The exception is detailed in the original issue

So the overall story is that the RGB Status plugin is blocking shutdown, as there is no shutdown event registered.

cp2004 commented 4 years ago

I still can't get around this - Stripping it back and running without octoprint it seems to work to call kill_effect, the effect stops and everything is ok. The other thing that works is running octoprint directly with octoprint serve and pressing ctrl-C stops the thread, and you have to press again to stop octoprint. Interesting. @EricHigdon any word on this issue? And if I manage to fix it will you accept a pull request & release new version?

EricHigdon commented 4 years ago

I haven’t had a chance to touch this yet. If you have an idea, I’ll be happy to accept a pull request.

It seems to me like the on_shutdown() hook isn’t being called.

cp2004 commented 4 years ago

So it appears that Ocotoprint and the service restart don't play nice when there is more than one process.

To restart Octoprint, it calls sudo service octoprint restart:

The way I managed to test this was to play with Octoprint in development mode and start from command line using octoprint serve. Then to stop, use ctrl-c and wait and see. The 'effect' process captured the interrupt, but Octoprint carried on as normal. Then if I pressed it again, Octoprint would stop because the process wasn't running.

I might ask over on the community forum if there is a way to sort this out, as it is a great plugin and I just want to see it work well!

cp2004 commented 4 years ago

@EricHigdon I have created a quick test plugin just now, it's here Octoprint-TestProcess if you want to have a look. It doesn't work either. The process ends really quickly when it's asked to, and all it's doing is sleeping for 100 secs and then printing (Logging doesn't work from the process for some reason, that might be my fault). It also works with ctrl-c and the process is ended first, before the main process and OctoPrint exits cleanly. My next test is going to be taking this outside Octoprint, and to see if the way that we want multiprocessing to work actually works. I'll let you know.

EricHigdon commented 4 years ago

@cp2004 Do you have the ability to pul my latest changes and see if that fixes the problem for you? I think I have this working, but I had to break the progress code to do it, so before I put time into refactoring, I want to make sure that the fix works.

You should be able to pull the latest by going to the plugin folder and using git to checkout the main branch.

EricHigdon commented 4 years ago

It turned out to not take so long to refactor the progress functionality, so this issue should be fixed in v 1.7 which will be released shortly.

cp2004 commented 4 years ago

Thanks for doing that - I had found a couple of references to rpi_ws281x not being thread safe, and I was going to think about changing it in a similar way you did this weekend. When I get a chance (It could be tomorrow) I'll give it a thorough test and report back.