Skip to content
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

[1.3.10rc4?] Websocket errors when using Apache reverse proxy #2941

Closed
foosel opened this issue Dec 4, 2018 · 17 comments

Comments

Projects
None yet
2 participants
@foosel
Copy link
Owner

commented Dec 4, 2018

As mentioned by @paukstelis here:

I have issues with all the release candidates that are likely related to web access/authentication setup. There is no issue in 1.3.9.

What happens:
No websocket connection.
Browser console log contains
can’t establish a connection to the server at ws://<server>/octoprint/sockjs/322/4imior1c/websocket
Apache config for reverse proxy looks like this:

ProxyPass http://127.0.0.1:5000/
ProxyPassReverse http://127.0.01:5000/
RequestHeader set X-SCRIPT-NAME /octoprint/
RequestHeader set X-SCHEME http
RewriteEngine on
RewriteCond %{HTTP:UPGRADE} ^WebSocket$ [NC]
RewriteCond %{HTTP:CONNECTION} Upgrade$ [NC]
RewriteRule .* ws://127.0.0.1:5000%{REQUEST_URI} [P]

The only thing I currently can reproduce is an HTTP 404 on the websocket caused by the URL accessed on OctoPrint still containing /octoprint/ due to the apache config. The very same behaviour is shown under 1.3.9 however, so it doesn't appear to be a regression introduced by 1.3.10 as observed by the OP.

@paukstelis Could you check your apache error.log? Maybe that contains some clues as well. Please also set tornado.access logging to INFO (Settings > Logging), reproduce the error and provide an octoprint.log, I want to see if the request even reaches the server.

@paukstelis

This comment has been minimized.

Copy link

commented Dec 4, 2018

Some bits from apache error_log after reloading page:

[Tue Dec 04 07:27:19.204565 2018] [proxy_http:error] [pid 7496:tid 139834144261888] (70007)The timeout specified has expired: [client ] AH01110: error reading response
[Tue Dec 04 07:27:19.279107 2018] [proxy:error] [pid 7498:tid 139834366220032] (111)Connection refused: AH00957: WS: attempt to connect to 127.0.0.1:3000 () failed
[Tue Dec 04 07:27:19.279149 2018] [proxy_wstunnel:error] [pid 7498:tid 139834366220032] [client :42226] AH02452: failed to make connection to backend: 127.0.0.1
[Tue Dec 04 07:27:26.942553 2018] [proxy:error] [pid 7498:tid 139834211403520] (111)Connection refused: AH00957: WS: attempt to connect to 127.0.0.1:3000 (
) failed
[Tue Dec 04 07:27:26.942601 2018] [proxy_wstunnel:error] [pid 7498:tid 139834211403520] [client :42242] AH02452: failed to make connection to backend: 127.0.0.1

Last 100 lines of octoprint.log after restart and some idle time are attached (tornado.access set to INFO).
truncated_octoprint.log

@foosel

This comment has been minimized.

Copy link
Owner Author

commented Dec 4, 2018

Wait, why port 3000? Your config above says port 5000.

@paukstelis

This comment has been minimized.

Copy link

commented Dec 4, 2018

That might have been me messing around with apache conf. Let me restart apache.
EDIT: Yeah, I hadn't restarted apache after messing around last night.

@foosel

This comment has been minimized.

Copy link
Owner Author

commented Dec 4, 2018

So what does the error.log say now? Based on octoprint.log, the request is definitely not even making it through to OctoPrint.

@paukstelis

This comment has been minimized.

Copy link

commented Dec 4, 2018

No errors from apache now.

Octoprint log after a restarting apache and octoprint:
truncated_octoprint.log

@foosel

This comment has been minimized.

Copy link
Owner Author

commented Dec 4, 2018

2018-12-04 07:57:38,204 - tornado.access - WARNING - 404 GET /octoprint/sockjs/336/itkv5znk/websocket (ip.ip.ip.ip) 5.69ms

So that is definitely the error I also am seeing which is caused by the /octoprint/ prefix still being there (I've figured out how to strip that but then some important websocket headers are still missing, looking into it), but which I can also reproduce just as well under 1.3.9. So I'm a bit confused why you are only seeing this with 1.3.10.

@foosel

This comment has been minimized.

Copy link
Owner Author

commented Dec 4, 2018

I've figured something out that works with a prefix path on 1.3.9 and 1.3.10, at least on my end:

<Location /octoprint/>
  RequestHeader set X-SCRIPT-NAME /octoprint/
  ProxyPassReverse http://127.0.0.1:5000/

  RewriteEngine on
  RewriteCond %{HTTP:UPGRADE} =websocket [NC]
  RewriteRule /octoprint/(.*) ws://127.0.0.1:5000/$1 [P,L]
  RewriteCond %{HTTP:UPGRADE} !=websocket [NC]
  RewriteRule /octoprint/(.*) http://127.0.0.1:5000/$1 [P,L]
</Location>

I've also updated the corresponding guide on the forums.

I had a couple of honest WTF moments while figuring this out since everything I found online on this topic didn't work even remotely with a path prefix thanks to websocket headers vanishing. Configuring haproxy or Nginx for websockets is seriously way less of a headache than Apache.

As stated earlier,

<Location /octoprint/>
  ProxyPass http://127.0.0.1:5000/
  ProxyPassReverse http://127.0.01:5000/
  RequestHeader set X-SCRIPT-NAME /octoprint/
  RequestHeader set X-SCHEME http
  RewriteEngine on
  RewriteCond %{HTTP:UPGRADE} ^WebSocket$ [NC]
  RewriteCond %{HTTP:CONNECTION} Upgrade$ [NC]
  RewriteRule .* ws://127.0.0.1:5000%{REQUEST_URI} [P]
</Location>

^ this or some variants of it didn't work with 1.3.9 for me either, which is no surprise considering that RewriteRule .* ws://127.0.0.1:5000%{REQUEST_URI} [P] is not taking the prefix path into account at all and just happily forwarding it to the downstream server which has no idea of that path.

Are you really seeing working websockets against 1.3.9 with this configuration? If so, I'd like to know what Apache version you are running because that seriously doesn't make any sense. I've also not made any changes to the websocket routing between 1.3.9 that I'm aware of.

@paukstelis

This comment has been minimized.

Copy link

commented Dec 4, 2018

I can't explain why 1.3.9 works. Perhaps to complicate matters, I have multiple octoprint instances running on the same machine and I noticed that for whatever reason I have no rewrite rules at all for those instances (independent setups in conf.d) and they work just fine in 1.3.9 (still don't work in 1.3.10). There are loads of errors in browser console, but all of the instances work as expected.

I applied your recommended changes and I no longer have any errors in the browser console or anything obvious in octoprint.log, but the end result is the same. The printer does connect to the server on startup (I can get temps through local api calls), but in the browser I have no control (no temps), nothing in terminal, etc.

/usr/bin/httpd -v
Server version: Apache/2.4.34 (Fedora)

@foosel

This comment has been minimized.

Copy link
Owner Author

commented Dec 4, 2018

The printer does connect to the server on startup (I can get temps through local api calls), but in the browser I have no control (no temps), nothing in terminal, etc.

I'm not seeing that here.

$ dpkg -l apache2
Desired=Unknown/Install/Remove/Purge/Hold
| Status=Not/Inst/Conf-files/Unpacked/halF-conf/Half-inst/trig-aWait/Trig-pend
|/ Err?=(none)/Reinst-required (Status,Err: uppercase=bad)
||/ Name                                           Version                      Architecture                 Description
+++-==============================================-============================-============================-==================================================================================================
ii  apache2                                        2.4.25-3+deb9u6              armhf                        Apache HTTP Server

I'll try to get my hands on a 2.4.34 tomorrow, maybe there's a difference between our versions that's causing the different behaviour.

Could you shoot me your full config? You can also send it privately through email to gina -at- octoprint.org if it contains sensitive information.

@paukstelis

This comment has been minimized.

Copy link

commented Dec 4, 2018

I've done the following:
Revert back to 1.3.9, still using your updated reverse proxy settings.
Everything works (didn't try printing)
Screenshot and log:
octoprint_1.3.9.log
screenshot from 2018-12-04 11-41-09

Update to 1.3.10rc4
Does not show temps or allow control of any kind.
Log and screenshot.
octoprint_1.3.10rc4.log
screenshot from 2018-12-04 11-43-18

I left my browser open at home, that's why there are the two connections.

@foosel

This comment has been minimized.

Copy link
Owner Author

commented Dec 5, 2018

@paukstelis could you also share a screenshot of the Network tab in the 1.3.10rc4 case? Might give some hints.

Based on how the 1.3.10rc4 screenshot looks and your log it looks like for some reason the client in the browser is not authenticating with the server through the web socket, meaning that no messages other than the initial connection handshake will go through (ForceLogin plugin being the cause of this). I'm missing a line like this in your log:

2018-12-05 11:09:55,773 - octoprint.server.util.sockjs - INFO - User admin logged in on the socket from client 192.168.1.3

Could be a caching issue, with the relevant code taking care of this authentication not being present in the browser, so just in case make sure that all caches on the way are cleared of old content (the caching headers should usually take care of that, but just in case).

There was a similar issue reported by @ctgreybeard during 1.3.10rc1, see #2875. In that case it was a left over from an older install that was messing with the static files, specifically the JS backing the UI, which caused crucial bits for the socket initialization to be missing. Could possibly be something similar. Could you provide me the packed_core.js that your browser is seeing?

image

I guess there is no possibility for me to poke around in this system?

@paukstelis

This comment has been minimized.

Copy link

commented Dec 5, 2018

packed_core.js attached.

I sent you an email about system access.

1310rc4_packed_core.js.txt

@paukstelis

This comment has been minimized.

Copy link

commented Dec 5, 2018

It would be pretty minimal effort to just entirely reinstall OctoPrint. Do you want to me to try that or would you prefer to track down the issue?

@foosel

This comment has been minimized.

Copy link
Owner Author

commented Dec 5, 2018

That's definitely the wrong code being active here.

Your LoginStateViewModel.fromResponse looks like this:

        self.fromResponse = function(response) {
            var process = function() {
                var currentLoggedIn = self.loggedIn();
                if (response && response.name) {
                    self.loggedIn(true);
                    self.updateCurrentUserData(response);
                    if (!currentLoggedIn) {
                        callViewModels(self.allViewModels, "onUserLoggedIn", [response]);
                        log.info("User " + response.name + " logged in")
                    }
                } else {
                    self.loggedIn(false);
                    self.resetCurrentUserData();
                    if (currentLoggedIn) {
                        callViewModels(self.allViewModels, "onUserLoggedOut");
                        log.info("User logged out");
                    }
                }
            };

            if (self.startupDeferred !== undefined) {
                // Make sure we only fire our "onUserLogged(In|Out)" message after the application
                // has started up.
                self.startupDeferred.done(process);
            } else {
                process();
            }
        };

And it should look like this:

self.fromResponse = function(response) {
var process = function() {
var currentLoggedIn = self.loggedIn();
if (response && response.name) {
self.loggedIn(true);
self.updateCurrentUserData(response);
if (!currentLoggedIn) {
callViewModels(self.allViewModels, "onUserLoggedIn", [response]);
log.info("User " + response.name + " logged in")
}
if (response.session) {
OctoPrint.socket.sendAuth(response.name, response.session);
}
// Show warning if connecting from what seems to be an external IP address, unless ignored
var ignorePublicAddressWarning = localStorage["loginState.ignorePublicAddressWarning"];
if (ignorePublicAddressWarning === undefined) {
ignorePublicAddressWarning = false;
} else {
ignorePublicAddressWarning = JSON.parse(ignorePublicAddressWarning);
}
if (response._is_external_client && !ignorePublicAddressWarning) {
var text = gettext("<p>It seems that you are connecting to OctoPrint over the public internet.</p>" +
"<p>This is strongly discouraged unless you have taken proper network security precautions. " +
"Your printer is an appliance you really should not be giving access to " +
"everyone with an internet connection.</p><p><strong>Please see " +
"<a href=\"%(url)s\" target=\"_blank\" rel=\"noreferrer noopener\">this blog post</a> for " +
"ways to safely access your OctoPrint instance from remote.</strong></p>" +
"<p><small>If you know what you are doing or you are sure this message is " +
"mistaken since you are in an isolated LAN, feel free to ignore it.</small></p>");
text = _.sprintf(text, {url: "https://octoprint.org/blog/2018/09/03/safe-remote-access/"});
if (self.externalAddressNotification !== undefined) {
self.externalAddressNotification.remove();
}
self.externalAddressNotification = new PNotify({
title: gettext("Possible external access detected"),
text: text,
hide: false,
type: "error",
confirm: {
confirm: true,
buttons: [{
text: gettext("Ignore"),
addClass: "btn btn-danger",
click: function(notice) {
notice.remove();
localStorage["loginState.ignorePublicAddressWarning"] = JSON.stringify(true);
}
}, {
text: gettext("Later"),
addClass: "btn btn-primary",
click: function(notice) {
notice.remove();
}
}]
},
buttons: {
sticker: false
}
})
}
} else {
self.loggedIn(false);
self.resetCurrentUserData();
if (currentLoggedIn) {
callViewModels(self.allViewModels, "onUserLoggedOut");
log.info("User logged out");
}
}
};
if (self.startupDeferred !== undefined) {
// Make sure we only fire our "onUserLogged(In|Out)" message after the application
// has started up.
self.startupDeferred.done(process);
} else {
process();
}
};

So for some reason your browser is using an old version of this JS file and that's causing the UI not to be properly initialized. Exactly the same symptom as encountered in #2875. The question is whether the cause is the same and that is something I'd like to figure out if possible before you nuke the system :) Should be something done rather quickly with access so I'll get back to you via email now to figure out how to best go about this. Thanks for your help in debugging this!

@foosel

This comment has been minimized.

Copy link
Owner Author

commented Dec 5, 2018

Thanks for the remote access. It indeed looks like the exact issue as described in #2875 - there's an old install (1.3.9) left on sys.path for some reason thanks to a corresponding entry in easy-install.pth. As stated in #2875 I have currently no idea how that got there - updates should usually go via pip these days, and uninstall old versions first, and not via python setup.py install anymore which still used easy-install under the hood. Odd.

In any case, this is probably easy to fix just by manually removing the offending entry in easy-install.pth and restarting the instance(s), but I'd rather get the green light for that from your side.

Basically, this line in {venv location}/lib/python2.7/site-packages/easy-install.pth has to go (currently trying to figure out the proper sed commands to make this a one line bash fix but I'm a bit rusty ;)):

./OctoPrint-1.3.9-py2.7.egg

Fairly sure that once that's gone things will just work (TM).

@paukstelis

This comment has been minimized.

Copy link

commented Dec 5, 2018

Fixed!

Not sure how it got their either. At one point I was playing around with tracking commits for updates as opposed to releases. Not sure if that could have been responsible.

Thanks for looking into this.

@foosel

This comment has been minimized.

Copy link
Owner Author

commented Dec 5, 2018

At one point I was playing around with tracking commits for updates as opposed to releases. Not sure if that could have been responsible.

Possibly. I have to look a bit more into this, however it's an issue that's unrelated to 1.3.10 so I didn't dare to try to push a work around for situations like this into it (quite invasive). Closing this since we still have #2875 to track the underlying environmental problem.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.