New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

OctoPrint 1.3.5rc1 fails to start with error Address already in use #2035

Closed
noahwilliamsson opened this Issue Jul 26, 2017 · 5 comments

Comments

2 participants
@noahwilliamsson

noahwilliamsson commented Jul 26, 2017

What were you doing?

I'm on the maintenance branch, commit 1a6dbb3, and frequently see that OctoPrint fails to start due to error: [Errno 98] Address already in use. I've seen this happen since around the 1.3.4 release but I cannot be more specific than that.

This appears to happen (just guessing here) when util/gcodeInterpreter.py takes a long time, which it usually does on the Pi Zero W I'm using and with the parts I attempt to print.

(see below for octoprint.log)

Only OctoPrint is supposed to be listening on port 5000 (which I'm guessing is the culprit here, unless OctoPrint listens on more sockets..). Interestingly it appears as if util/gcodeInterpreter also has bound this socket:

$ sudo netstat -nlap|grep 5000
tcp        0      0 0.0.0.0:5000            0.0.0.0:*               LISTEN      3448/python     
...
$ ps auxwf|grep -i octo
pi        3448 89.2  3.7  18132 14152 ?        R<   22:04   0:50 /home/pi/OctoPrint/venv/bin/python /home/pi/OctoPrint/venv/lib/python2.7/site-packages/OctoPrint-1.3.6.dev4_ga21f5c4-py2.7.egg/octoprint/util/gcodeInterpreter.py --speed-x=6000 --speed-y=6000 --max-t=10 --throttle=0.01 --throttle-lines=100 /home/pi/.octoprint/uploads/sample.gcode

Before the crash, I had two OctoPrint processes, one doing bin/octoprint serve --port=5000 and the other running util/gcodeInterpreter.py on the last print I attempted.

In case it is related, I usually have browser tabs with previous sessions to OctoPrint open when OctoPrint is restarted (and fails to start up).

What did you expect to happen?

OctoPrint should start successfully and listen on port 5000 after booting up the Raspberry Pi Zero W.

What happened instead?

OctoPrint's main process crashed with error: [Errno 98] Address already in use while util/gcodeInterpreter.py continued to run for 5-10 minutes, before exiting. In the end, zero OctoPrint processes remained.

I can workaround the problem by manually removing ~/.octoprint/upoads/[the last g-code file I was printing] followed by systemctl restart octoprint.

Did the same happen when running OctoPrint in safe mode?

Sorry, I didn't bother testing this.

Branch & Commit or Version of OctoPrint

The maintenance branch, commit a21f5c4 (pretty much 1.3.5rc1).

Operating System running OctoPrint

Raspbian latest, Python virtualenv install of OctoPrint.

Printer model & used firmware incl. version

Browser and Version of Browser, Operating System running Browser

Link to octoprint.log

2017-07-26 22:03:42,036 - octoprint.server - INFO - ******************************************************************************
2017-07-26 22:03:42,041 - octoprint.server - INFO - Starting OctoPrint 1.3.6.dev4+ga21f5c4 (maintenance branch)
2017-07-26 22:03:42,043 - octoprint.server - INFO - ******************************************************************************
2017-07-26 22:03:42,307 - octoprint.plugin.core - INFO - Loading plugins from /home/pi/OctoPrint/venv/lib/python2.7/site-packages/OctoPrint-1.3.6.dev4_ga21f5c4-py2.7.egg/octoprint/plugins, /home/pi/.octoprint/plugins and installed plugin packages...
2017-07-26 22:03:49,168 - octoprint.plugins.discovery - INFO - pybonjour is not installed, Zeroconf Discovery won't be available
2017-07-26 22:03:49,198 - octoprint.plugin.core - INFO - Found 7 plugin(s) providing 5 mixin implementations, 4 hook handlers
2017-07-26 22:03:49,323 - octoprint.plugin.core - INFO - Loading plugins from /home/pi/OctoPrint/venv/lib/python2.7/site-packages/OctoPrint-1.3.6.dev4_ga21f5c4-py2.7.egg/octoprint/plugins, /home/pi/.octoprint/plugins and installed plugin packages...
2017-07-26 22:03:50,824 - octoprint.plugin.core - INFO - Found 7 plugin(s) providing 5 mixin implementations, 4 hook handlers
2017-07-26 22:03:51,014 - octoprint.filemanager.storage - INFO - Initializing the file metadata for /home/pi/.octoprint/uploads...
2017-07-26 22:03:54,880 - octoprint.filemanager.storage - INFO - ... file metadata for /home/pi/.octoprint/uploads initialized successfully.
2017-07-26 22:03:55,025 - octoprint.plugins.softwareupdate - INFO - Version cache was created for another version of OctoPrint, not using it
2017-07-26 22:04:05,501 - octoprint.util.pip - INFO - Using "/home/pi/OctoPrint/venv/bin/python -m pip" as command to invoke pip
2017-07-26 22:04:15,758 - octoprint.util.pip - INFO - Version of pip is 9.0.1
2017-07-26 22:04:15,786 - octoprint.plugin.core - INFO - Initialized 5 plugin implementation(s)
2017-07-26 22:04:15,807 - octoprint.plugin.core - INFO - 7 plugin(s) registered with the system:
| !Announcement Plugin (bundled) = /home/pi/OctoPrint/venv/lib/python2.7/site-packages/OctoPrint-1.3.6.dev4_ga21f5c4-py2.7.egg/octoprint/plugins/announcements
|  Core Wizard (bundled) = /home/pi/OctoPrint/venv/lib/python2.7/site-packages/OctoPrint-1.3.6.dev4_ga21f5c4-py2.7.egg/octoprint/plugins/corewizard
| !CuraEngine (<= 15.04) (bundled) = /home/pi/OctoPrint/venv/lib/python2.7/site-packages/OctoPrint-1.3.6.dev4_ga21f5c4-py2.7.egg/octoprint/plugins/cura
|  Discovery (bundled) = /home/pi/OctoPrint/venv/lib/python2.7/site-packages/OctoPrint-1.3.6.dev4_ga21f5c4-py2.7.egg/octoprint/plugins/discovery
|  Plugin Manager (bundled) = /home/pi/OctoPrint/venv/lib/python2.7/site-packages/OctoPrint-1.3.6.dev4_ga21f5c4-py2.7.egg/octoprint/plugins/pluginmanager
|  Software Update (bundled) = /home/pi/OctoPrint/venv/lib/python2.7/site-packages/OctoPrint-1.3.6.dev4_ga21f5c4-py2.7.egg/octoprint/plugins/softwareupdate
|  Virtual Printer (bundled) = /home/pi/OctoPrint/venv/lib/python2.7/site-packages/OctoPrint-1.3.6.dev4_ga21f5c4-py2.7.egg/octoprint/plugins/virtual_printer
2017-07-26 22:04:15,820 - octoprint.filemanager - INFO - Adding backlog items from all storage types to analysis queue...
2017-07-26 22:04:15,871 - octoprint.server - INFO - Reset webasset folder /home/pi/.octoprint/generated/webassets...
2017-07-26 22:04:15,999 - octoprint.server - INFO - Reset webasset folder /home/pi/.octoprint/generated/.webassets-cache...
2017-07-26 22:04:16,108 - octoprint.filemanager.analysis - INFO - Starting analysis of local:xy-lm10luu.gcode
2017-07-26 22:04:16,139 - octoprint.filemanager - INFO - Added 1 items from storage type "local" to analysis queue
2017-07-26 22:04:16,142 - octoprint.filemanager.analysis - INFO - Invoking analysis command: /home/pi/OctoPrint/venv/bin/python /home/pi/OctoPrint/venv/lib/python2.7/site-packages/OctoPrint-1.3.6.dev4_ga21f5c4-py2.7.egg/octoprint/util/gcodeInterpreter.py --speed-x=6000 --speed-y=6000 --max-t=10 --throttle=0.01 --throttle-lines=100 /home/pi/.octoprint/uploads/xy-lm10luu.gcode
2017-07-26 22:04:18,656 - octoprint.cli.server - ERROR - Uncaught exception
Traceback (most recent call last):
  File "/home/pi/OctoPrint/venv/bin/octoprint", line 9, in <module>
    load_entry_point('OctoPrint==1.3.6.dev4-ga21f5c4', 'console_scripts', 'octoprint')()
  File "/home/pi/OctoPrint/venv/local/lib/python2.7/site-packages/OctoPrint-1.3.6.dev4_ga21f5c4-py2.7.egg/octoprint/__init__.py", line 405, in main
    octo(args=args, prog_name="octoprint", auto_envvar_prefix="OCTOPRINT")
  File "/home/pi/OctoPrint/venv/local/lib/python2.7/site-packages/click-6.2-py2.7.egg/click/core.py", line 716, in __call__
    return self.main(*args, **kwargs)
  File "/home/pi/OctoPrint/venv/local/lib/python2.7/site-packages/click-6.2-py2.7.egg/click/core.py", line 696, in main
    rv = self.invoke(ctx)
  File "/home/pi/OctoPrint/venv/local/lib/python2.7/site-packages/click-6.2-py2.7.egg/click/core.py", line 1060, in invoke
    return _process_result(sub_ctx.command.invoke(sub_ctx))
  File "/home/pi/OctoPrint/venv/local/lib/python2.7/site-packages/click-6.2-py2.7.egg/click/core.py", line 889, in invoke
    return ctx.invoke(self.callback, **ctx.params)
  File "/home/pi/OctoPrint/venv/local/lib/python2.7/site-packages/click-6.2-py2.7.egg/click/core.py", line 534, in invoke
    return callback(*args, **kwargs)
  File "/home/pi/OctoPrint/venv/local/lib/python2.7/site-packages/click-6.2-py2.7.egg/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-1.3.6.dev4_ga21f5c4-py2.7.egg/octoprint/cli/server.py", line 150, in serve_command
    allow_root, logging, verbosity, safe_mode)
  File "/home/pi/OctoPrint/venv/local/lib/python2.7/site-packages/OctoPrint-1.3.6.dev4_ga21f5c4-py2.7.egg/octoprint/cli/server.py", line 96, in run_server
    octoprint_server.run()
  File "/home/pi/OctoPrint/venv/local/lib/python2.7/site-packages/OctoPrint-1.3.6.dev4_ga21f5c4-py2.7.egg/octoprint/server/__init__.py", line 570, in run
    self._server.listen(self._port, address=self._host)
  File "/home/pi/OctoPrint/venv/local/lib/python2.7/site-packages/tornado-4.0.2-py2.7-linux-armv6l.egg/tornado/tcpserver.py", line 125, in listen
    sockets = bind_sockets(port, address=address)
  File "/home/pi/OctoPrint/venv/local/lib/python2.7/site-packages/tornado-4.0.2-py2.7-linux-armv6l.egg/tornado/netutil.py", line 145, in bind_sockets
    sock.bind(sockaddr)
  File "/usr/lib/python2.7/socket.py", line 224, in meth
    return getattr(self._sock,name)(*args)
error: [Errno 98] Address already in use

Link to contents of terminal tab or serial.log

Link to contents of Javascript console in the browser

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

I have read the FAQ.

@foosel

This comment has been minimized.

Show comment
Hide comment
@foosel

foosel Jul 27, 2017

Owner

Thank you for the hint with gcodeInterpreter. That is something to investigate. I currently do not understand why it apparently inherits the port, but that's definitely the most likely cause for this issue. I'll try to see if I can get a reproduction with an unanalysed file being present on startup.

Owner

foosel commented Jul 27, 2017

Thank you for the hint with gcodeInterpreter. That is something to investigate. I currently do not understand why it apparently inherits the port, but that's definitely the most likely cause for this issue. I'll try to see if I can get a reproduction with an unanalysed file being present on startup.

@foosel

This comment has been minimized.

Show comment
Hide comment
@foosel

foosel Jul 27, 2017

Owner

Huh... you learn something new every day. I knew that sub processes on Unix/Linux would inherit file descriptors, but I didn't know (or didn't think far enough to realize) that this would also translate to open ports. That would of course explain this behaviour.

Owner

foosel commented Jul 27, 2017

Huh... you learn something new every day. I knew that sub processes on Unix/Linux would inherit file descriptors, but I didn't know (or didn't think far enough to realize) that this would also translate to open ports. That would of course explain this behaviour.

foosel added a commit that referenced this issue Jul 27, 2017

Do not run subprocesses while intermediary server is active
Any processes inheriting the open port descriptor of that server will
cause the actual server startup to fail due to the port still being
claimed.

We can't fully prevent this under Windows thanks to fnctl not being
available and win32api being a PITA, and also close_fds on Popen not
being allowed if we also need to redirect stdout/stderr/stdin for a
process. So let's hope hardening against this problem when running
under *nix, adding a bit fat warning to never start a subprocess
during the intermediary's runtime and also moving the only actual
process we so far DID start (analysis backlog processing) to after
Tornado is running will suffice.

Fixes #2035

@foosel foosel added this to the 1.3.5 milestone Jul 27, 2017

@foosel

This comment has been minimized.

Show comment
Hide comment
@foosel

foosel Jul 27, 2017

Owner

Found and fixed. Will try to prep a new RC today (and then also merge the fix from staging/maintenance back up to maintenance and devel).

Owner

foosel commented Jul 27, 2017

Found and fixed. Will try to prep a new RC today (and then also merge the fix from staging/maintenance back up to maintenance and devel).

@foosel

This comment has been minimized.

Show comment
Hide comment
@foosel

foosel Jul 27, 2017

Owner

1.3.5rc2 just got released.

Owner

foosel commented Jul 27, 2017

1.3.5rc2 just got released.

@noahwilliamsson

This comment has been minimized.

Show comment
Hide comment
@noahwilliamsson

noahwilliamsson Jul 28, 2017

That was quick. Closing this as the 1.3.5rc2 release no longer crashes on startup. Thanks!

noahwilliamsson commented Jul 28, 2017

That was quick. Closing this as the 1.3.5rc2 release no longer crashes on startup. Thanks!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment