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

[noahwilliamsson]

What were you doing?

I'm on the maintenance branch, commit 1a6dbb3f4a5bef857cdeb13c031b9deca2cf30a2, 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 a21f5c44973ae6c855c2d1c2e21a1fd967f58cde (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]

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]

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]

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]

1.3.5rc2 just got released.

[noahwilliamsson]

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