[1.4.0rc2] Losing session and running into permission errors

[gege2b]

This is the follow up from my message in #3360

What were you doing?

I wanted to open/print a file
or
restart octoprint in safe mode (or just restart it)
or
Start the mjpeg_streamer server from the menu
or
Reboot the system
or
Disable some plugins
...

What did you expect to happen?

The desired operation to complete flawlessly

What happened instead?

Errors everywheeeere (see screenshot above)

Did the same happen when running OctoPrint in safe mode?

Nope (Once restarted in safe mode with another way than the menu)

Version of OctoPrint

1.4.0rc2

Operating System running OctoPrint

Raspbian 9

Printer model & used firmware incl. version

Marlin 1.1.8

Browser and version of browser, operating system running browser

Firefox 70

Link to octoprint.log

octoprint.log (snipped to the two restart)

For every failing action, I got a " tornado.access - WARNING - 403 (...)"

Link to contents of terminal tab or serial.log

Not related (Octprint is correctly connected to the printer)

Link to contents of Javascript console in the browser

Nothing fancy

Less has finished and no sheets were loaded. less.min.js:13:12765
Champs mot de passe présents sur une page non sécurisée (http://). Cela représente un risque de sécurité permettant le vol d’identifiants de connexion.
5 prusa.local:5000
Starting dependency resolution... packed_core.js:16948:13
... dependency resolution done packed_core.js:17058:13
Initial application setup done, connecting to server... packed_core.js:17368:13
Initialized error tracking prusa.local:5000:15561:13
Connected to the server packed_core.js:14996:13
Finalizing application startup packed_core.js:17333:17
Going to bind 41 view models... packed_core.js:17208:21
Binding element to streamLoading packed_core.js:12087:44093
Did not bind view model UsageViewModel to target #wizard_plugin_tracking since it does not exist packed_core.js:17261:41
Did not bind view model SoftwareUpdateViewModel to target #softwareupdate_confirmation_dialog since it does not exist packed_core.js:17261:41
Did not bind view model SoftwareUpdateViewModel to target #wizard_plugin_softwareupdate since it does not exist packed_core.js:17261:41
User gege logged in packed_core.js:3334:29
... binding done packed_core.js:17300:21
Application startup complete packed_core.js:17312:21
Stream Closing.

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

see above

I have read the FAQ.

[foosel]

If this works in safe mode then whatever is happening there is happening due to a third party plugin. I cannot reproduce the behaviour at all, I got a bunch of instances on 1.4.0rc2 here and they all behave.

So let's take a look at your plugin list:

|  Action Command Prompt Support (bundled) = /home/pi/OctoPrint/venv/lib/python2.7/site-packages/octoprint/plugins/action_command_prompt
|  Announcement Plugin (bundled) = /home/pi/OctoPrint/venv/lib/python2.7/site-packages/octoprint/plugins/announcements
|  Anonymous Usage Tracking (bundled) = /home/pi/OctoPrint/venv/lib/python2.7/site-packages/octoprint/plugins/tracking
|  Application Keys Plugin (bundled) = /home/pi/OctoPrint/venv/lib/python2.7/site-packages/octoprint/plugins/appkeys
|  Backup & Restore (bundled) = /home/pi/OctoPrint/venv/lib/python2.7/site-packages/octoprint/plugins/backup
| !Cancel Objects (0.3.3) = /home/pi/OctoPrint/venv/local/lib/python2.7/site-packages/octoprint_cancelobject
|  Core Wizard (bundled) = /home/pi/OctoPrint/venv/lib/python2.7/site-packages/octoprint/plugins/corewizard
|  Discovery (bundled) = /home/pi/OctoPrint/venv/lib/python2.7/site-packages/octoprint/plugins/discovery
|  Error Tracking (bundled) = /home/pi/OctoPrint/venv/lib/python2.7/site-packages/octoprint/plugins/errortracking
| !Firmware Updater (1.6.1) = /home/pi/OctoPrint/venv/local/lib/python2.7/site-packages/octoprint_firmwareupdater
| !GcodeEditor (0.2.6) = /home/pi/OctoPrint/venv/local/lib/python2.7/site-packages/octoprint_GcodeEditor
|  Logging (bundled) = /home/pi/OctoPrint/venv/lib/python2.7/site-packages/octoprint/plugins/logging
| !Navbar Temperature Plugin (0.11) = /home/pi/OctoPrint/venv/local/lib/python2.7/site-packages/octoprint_navbartemp
| !Octolapse (0.4.0rc1.dev3) = /home/pi/OctoPrint/venv/local/lib/python2.7/site-packages/octoprint_octolapse
|  Pi Support Plugin (bundled) = /home/pi/OctoPrint/venv/lib/python2.7/site-packages/octoprint/plugins/pi_support
|  Plugin Manager (bundled) = /home/pi/OctoPrint/venv/lib/python2.7/site-packages/octoprint/plugins/pluginmanager
|  Printer Safety Check (bundled) = /home/pi/OctoPrint/venv/lib/python2.7/site-packages/octoprint/plugins/printer_safety_check
|  Software Update (bundled) = /home/pi/OctoPrint/venv/lib/python2.7/site-packages/octoprint/plugins/softwareupdate
|  Virtual Printer (bundled) = /home/pi/OctoPrint/venv/lib/python2.7/site-packages/octoprint/plugins/virtual_printer

The only third party plugins here appear to be

• Cancel Objects
• Firmware Updater
• GcodeEditor
• Navbar Temperature Plugin
• Octolapse

Can you try disabling/temporarily uninstalling Octolapse, then start in normal mode and see if the issue still reproduces? Considering that you ran into additional issues with that specific plugin according to your comment at #3360 (comment) it's currently the most likely candidate.

Also pinging @FormerLurker just in case.

edit Also please fix your undervoltage situation, that's known to cause all kinds of ridiculous problems:

2019-12-04 17:19:53,539 - octoprint.plugins.pi_support - WARNING - This Raspberry Pi is reporting problems that might lead to bad performance or errors caused by overheating or insufficient power.
!!! UNDERVOLTAGE REPORTED !!! Make sure that the power supply and power cable are capable of supplying enough voltage and current to your Pi.

[gege2b]

I just rebooted the pi and some more errors was in the log :

2019-12-04 17:51:53,581 - octoprint.server.api - ERROR - Error calling SimpleApiPlugin action_command_prompt
Traceback (most recent call last):
  File "/home/pi/OctoPrint/venv/local/lib/python2.7/site-packages/octoprint/server/api/__init__.py", line 70, in pluginData
    response = api_plugin.on_api_get(request)
  File "/home/pi/OctoPrint/venv/lib/python2.7/site-packages/octoprint/plugins/action_command_prompt/__init__.py", line 124, in on_api_get
    return flask.abort(403, "Insufficient permissions")
  File "/home/pi/OctoPrint/venv/local/lib/python2.7/site-packages/werkzeug/exceptions.py", line 772, in abort
    return _aborter(status, *args, **kwargs)
  File "/home/pi/OctoPrint/venv/local/lib/python2.7/site-packages/werkzeug/exceptions.py", line 753, in __call__
    raise self.mapping[code](*args, **kwargs)
Forbidden: 403 Forbidden: Insufficient permissions

And right now, even the octoprint menu isn't showing up

Can you please tell another way to disable (preferably) or uninstall Octolapse to do some more test ?

Also about the undervoltage problem, I know it's problematic but until now, it never caused me any trouble (TBH this setup run pretty flawlessly since years), it's the +5v of an ATX power
Need to get a decent power supply to test this out too

[FormerLurker]

@gege2b., are you running python 3? If so, Octolapse is not yet compatible (thought I've gotten it working mostly in devel). If you are running python 2.7, it looks like there is probably an error in your javascript console (make sure ERRORS are not being filtered from the console). Find it and paste it in here, but not until after you solve your issues with Octolapse disabled.

Thanks!

[foosel]

Restart in safe mode, uninstall, restart in normal mode.

Safe mode can asks so be triggered through the command line.

Or is that in safe mode?

[gege2b]

hi

So first, @FormerLurker : nope, I'm running Python 2.7 for now (but of course I'm planning to upgrade to 3 as soon as all is Ok)

@foosel : pretty weird, I got the same error this time in safe mode
octoprint.log

Weir thing is, once octolapse disabled and OP restarted in normal mode (from command line), it worked... a few minutes
As long as I refreshed the page, the problem was up again

2019-12-05 11:02:43,550 - octoprint.server.util.flask - INFO - Passively logging in user gege from 192.168.1.129
2019-12-05 11:02:44,752 - tornado.access - WARNING - 403 GET /api/access/groups (fe80::89f3:31bb:ced0:2093%wlan0) 27.77ms
2019-12-05 11:02:44,876 - tornado.access - WARNING - 403 GET /api/printerprofiles (fe80::89f3:31bb:ced0:2093%wlan0) 113.20ms
2019-12-05 11:02:44,915 - tornado.access - WARNING - 403 GET /api/system/commands (fe80::89f3:31bb:ced0:2093%wlan0) 29.14ms
2019-12-05 11:02:44,958 - tornado.access - WARNING - 403 GET /api/timelapse?unrendered=true (fe80::89f3:31bb:ced0:2093%wlan0) 31.91ms
2019-12-05 11:02:45,401 - tornado.access - WARNING - 403 GET /api/slicing (fe80::89f3:31bb:ced0:2093%wlan0) 29.71ms
2019-12-05 11:02:45,440 - tornado.access - WARNING - 403 GET /api/plugin/printer_safety_check (fe80::89f3:31bb:ced0:2093%wlan0) 30.77ms
2019-12-05 11:02:45,478 - tornado.access - WARNING - 403 GET /plugin/softwareupdate/check (fe80::89f3:31bb:ced0:2093%wlan0) 26.42ms
2019-12-05 11:02:45,519 - tornado.access - WARNING - 403 GET /api/files?recursive=true (fe80::89f3:31bb:ced0:2093%wlan0) 30.13ms
2019-12-05 11:02:45,555 - tornado.access - WARNING - 403 GET /plugin/announcements/channels (fe80::89f3:31bb:ced0:2093%wlan0) 25.76ms
2019-12-05 11:02:45,592 - tornado.access - WARNING - 403 GET /api/printer/command/custom (fe80::89f3:31bb:ced0:2093%wlan0) 26.90ms
2019-12-05 11:02:45,620 - octoprint.server.api - ERROR - Error calling SimpleApiPlugin action_command_prompt
Traceback (most recent call last):
  File "/home/pi/OctoPrint/venv/local/lib/python2.7/site-packages/octoprint/server/api/__init__.py", line 70, in pluginData
    response = api_plugin.on_api_get(request)
  File "/home/pi/OctoPrint/venv/lib/python2.7/site-packages/octoprint/plugins/action_command_prompt/__init__.py", line 124, in on_api_get
    return flask.abort(403, "Insufficient permissions")
  File "/home/pi/OctoPrint/venv/local/lib/python2.7/site-packages/werkzeug/exceptions.py", line 772, in abort
    return _aborter(status, *args, **kwargs)
  File "/home/pi/OctoPrint/venv/local/lib/python2.7/site-packages/werkzeug/exceptions.py", line 753, in __call__
    raise self.mapping[code](*args, **kwargs)
Forbidden: 403 Forbidden: Insufficient permissions
2019-12-05 11:02:45,830 - tornado.access - ERROR - 500 GET /api/plugin/action_command_prompt (fe80::89f3:31bb:ced0:2093%wlan0) 227.77ms
2019-12-05 11:02:46,068 - tornado.access - WARNING - 403 GET /api/plugin/pluginmanager (fe80::89f3:31bb:ced0:2093%wlan0) 28.14ms
2019-12-05 11:02:46,109 - octoprint.server.util.sockjs - INFO - User gege logged in on the socket from client fe80::89f3:31bb:ced0:2093%wlan0

If I do a ctrl+F5 then it's gone and all works as expected :

2019-12-05 11:02:49,857 - octoprint.plugins.navbartemp - INFO - Checking SoC internal temperature
2019-12-05 11:03:19,914 - octoprint.plugins.navbartemp - INFO - Checking SoC internal temperature
2019-12-05 11:03:22,461 - octoprint.server.util.sockjs - INFO - Client connection closed: fe80::89f3:31bb:ced0:2093%wlan0
2019-12-05 11:03:34,002 - octoprint.server.util.sockjs - INFO - New connection from client: 192.168.1.129
2019-12-05 11:03:34,304 - octoprint.server.util.sockjs - INFO - New connection from client: 192.168.1.129
2019-12-05 11:03:38,637 - octoprint.server.util.sockjs - INFO - New connection from client: 192.168.1.129
2019-12-05 11:03:49,972 - octoprint.plugins.navbartemp - INFO - Checking SoC internal temperature
2019-12-05 11:04:20,034 - octoprint.plugins.navbartemp - INFO - Checking SoC internal temperature
2019-12-05 11:04:44,989 - octoprint.server.util.sockjs - INFO - Client connection closed: 192.168.1.129
2019-12-05 11:04:45,003 - octoprint.server.util.sockjs - INFO - Client connection closed: 192.168.1.129
2019-12-05 11:04:45,021 - octoprint.server.util.sockjs - INFO - Client connection closed: 192.168.1.129
2019-12-05 11:04:45,245 - tornado.general - ERROR - Attempted to attach to session 2m2v02zc (192.168.1.129) from different IP (fe80::89f3:31bb:ced0:2093%wlan0)
2019-12-05 11:04:50,096 - octoprint.plugins.navbartemp - INFO - Checking SoC internal temperature
2019-12-05 11:04:53,556 - tornado.general - ERROR - Attempted to attach to session 2m2v02zc (192.168.1.129) from different IP (fe80::89f3:31bb:ced0:2093%wlan0)
2019-12-05 11:04:56,071 - octoprint.server.util.sockjs - INFO - New connection from client: 192.168.1.129
2019-12-05 11:04:58,541 - octoprint.server.util.sockjs - INFO - New connection from client: fe80::89f3:31bb:ced0:2093%wlan0
2019-12-05 11:04:58,767 - octoprint.server.util.flask - INFO - Passively logging in user gege from fe80::89f3:31bb:ced0:2093%wlan0
2019-12-05 11:05:04,062 - octoprint.server.util.sockjs - INFO - User gege logged in on the socket from client 192.168.1.129
2019-12-05 11:05:14,049 - octoprint.server.api.system - INFO - Performing command for custom:streamon
2019-12-05 11:05:20,400 - octoprint.plugins.navbartemp - INFO - Checking SoC internal temperature
2019-12-05 11:05:25,008 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-12-05 11:05:30,006 - octoprint.server.api.system - INFO - Performing command for core:restart: sudo service octoprint restart
2019-12-05 11:05:30,256 - octoprint.server - INFO - Shutting down...
2019-12-05 11:05:30,440 - octoprint.events - INFO - Processing shutdown event, this will be our last event
2019-12-05 11:05:30,468 - octoprint.events - INFO - Event loop shut down
2019-12-05 11:05:30,482 - octoprint.server - INFO - Goodbye!

But it's really random...

I've cleared the browser cache many times and nothing changes
It seems obvious to me that the tornado's 403 warning is the point here, but I may be wrong

[foosel]

It looks almost as if something is killing your session.

Can you share a screenshot of how your user and your groups look like in Settings > Access Control? And can you also mail me your users.yaml and groups.yaml from ~/.octoprint to gina -at- octoprint.org? Don't share it here publicly since there's API keys in there, and passwords, even though hashed with your instance's secret.

[gege2b]

Yep, I'll do that
Just another snippet of log, while in safe mode, I tried to disable any 3rd party :

2019-12-05 11:19:47,889 - octoprint.server.util.sockjs - INFO - New connection from client: 192.168.1.129
2019-12-05 11:19:50,208 - octoprint.server.util.sockjs - INFO - User gege logged in on the socket from client 192.168.1.129
2019-12-05 11:20:06,224 - tornado.access - WARNING - 403 POST /api/files/local/20191204-091625-Hinge_arm_-_long_6x_0.2-15-.gcode (fe80::89f3:31bb:ced0:2093%wlan0) 41.97ms
2019-12-05 11:20:10,766 - tornado.access - WARNING - 403 GET /api/languages (fe80::89f3:31bb:ced0:2093%wlan0) 28.25ms
2019-12-05 11:20:10,837 - tornado.access - WARNING - 403 GET /plugin/logging/ (fe80::89f3:31bb:ced0:2093%wlan0) 19.75ms
2019-12-05 11:20:10,900 - tornado.access - WARNING - 403 GET /api/printerprofiles (fe80::89f3:31bb:ced0:2093%wlan0) 56.84ms
2019-12-05 11:20:10,920 - tornado.access - WARNING - 403 GET /plugin/backup/ (fe80::89f3:31bb:ced0:2093%wlan0) 14.11ms
2019-12-05 11:20:19,586 - tornado.access - WARNING - 403 POST /api/plugin/pluginmanager (fe80::89f3:31bb:ced0:2093%wlan0) 34.39ms
2019-12-05 11:20:21,721 - tornado.access - WARNING - 403 POST /api/plugin/pluginmanager (fe80::89f3:31bb:ced0:2093%wlan0) 33.94ms
2019-12-05 11:20:23,508 - tornado.access - WARNING - 403 POST /api/plugin/pluginmanager (fe80::89f3:31bb:ced0:2093%wlan0) 33.37ms
2019-12-05 11:20:36,082 - tornado.access - WARNING - 403 POST /api/plugin/pluginmanager (fe80::89f3:31bb:ced0:2093%wlan0) 35.18ms

[foosel]

Got the files, thank you. I cannot see anything weird in either them or the screenshots. And I cannot reproduce your problems at all, neither with FF 70 nor 71. But I just spotted something in your log excerpt:

User gege logged in on the socket from client 192.168.1.129

v4 address on the login, but

2019-12-05 11:20:06,224 - tornado.access - WARNING - 403 POST /api/files/local/20191204-091625-Hinge_arm_-_long_6x_0.2-15-.gcode (fe80::89f3:31bb:ced0:2093%wlan0) 41.97ms
2019-12-05 11:20:10,766 - tornado.access - WARNING - 403 GET /api/languages (fe80::89f3:31bb:ced0:2093%wlan0) 28.25ms
2019-12-05 11:20:10,837 - tornado.access - WARNING - 403 GET /plugin/logging/ (fe80::89f3:31bb:ced0:2093%wlan0) 19.75ms
2019-12-05 11:20:10,900 - tornado.access - WARNING - 403 GET /api/printerprofiles (fe80::89f3:31bb:ced0:2093%wlan0) 56.84ms
2019-12-05 11:20:10,920 - tornado.access - WARNING - 403 GET /plugin/backup/ (fe80::89f3:31bb:ced0:2093%wlan0) 14.11ms
2019-12-05 11:20:19,586 - tornado.access - WARNING - 403 POST /api/plugin/pluginmanager (fe80::89f3:31bb:ced0:2093%wlan0) 34.39ms
2019-12-05 11:20:21,721 - tornado.access - WARNING - 403 POST /api/plugin/pluginmanager (fe80::89f3:31bb:ced0:2093%wlan0) 33.94ms
2019-12-05 11:20:23,508 - tornado.access - WARNING - 403 POST /api/plugin/pluginmanager (fe80::89f3:31bb:ced0:2093%wlan0) 33.37ms
2019-12-05 11:20:36,082 - tornado.access - WARNING - 403 POST /api/plugin/pluginmanager (fe80::89f3:31bb:ced0:2093%wlan0) 35.18ms

link local v6 addresses on the denied requests. I remember that the session cookies in Flask can also be bound to the client IP. I thought I had disabled that (specifically because windows clients appear to happily toggle between all possible options on name resolution for requests on the same page). I'll have to check if maybe some third party lib update or something changed the behaviour here which would explain what you are seeing.

A clue!

[gege2b]

damn it

At first when I read your comment, I wondered if the fact that eth AND wifi are connected at the same time could be the cause of all this mess, but the pair ipv4/ipv6 are both from my ethernet

EDIT : I tested under firefox on linux (kubuntu) and indeed, there is no such problem

Don't hesitate to ask me for any further infos

[foosel]

It would be interesting to know if the issue goes away if you only have wifi or ethernet connected. I've been digging through the related session code in Flask-Login for most of the day and so far I have not found a smoking gun sadly and am hence a bit at a loss for the moment.

[gege2b]

No it does not goes away (I'm testing in eth since I read your comment)

As edited on my comment above, tested under linux (different PC) and it's OK

[foosel]

So it definitely is that weird Windows issue again with the multiple host addresses, but for some reason the workaround for that using basic session protection instead of strong doesn't work anymore. And of course right now I can't get the situation to replicate and hence can't debug. Argh ;) But at least all signs point to the switching address to be the issue here, so if push comes to shove I'll add some more logging and ask you to try a special debugging branch to hopefully get some more info on what's going on.

[foosel]

Can you do me a favor and see if the issue goes away if you explicitly access OctoPrint only via the v4 address? I want to make sure it's really the ip switching that's at fault here, would suck if I was barking up the wrong tree.

[foosel]

Also, just to make sure - this issue does NOT happen with 1.3.12 and the exact same setup, right?

[gege2b]

I disabled ipv6 on my win10 machine and it does not happens anymore (I still have an error from octolapse about settings that could not be loaded, but it does not talk about permissions (like earlier), so I guess it's something else going on here)

And indeed, this didn't happen on 1.3.12

[foosel]

I didn't mean disabling v6, I meant accessing the whole instance via whatever the v4 IP might be instead of prusa.local, but with both v4 and v6 support enabled on the client. If you could test this please, that would hopefully help.

I'm still unable to reproduce this myself on site and it's driving me a bit nuts because I'm very sure the issue is the v4/v6 toggling and I need to solve this because if it happens for you it can happen for others, but right now I have no clue why it's even happening because the fix I did for it a year or so ago is still there and holds. Something weird is happening here and I don't get it yet.

[fieldOfView]

I didn't mean disabling v6,

But disabling IPv6 did force all the trafic over IPv4 instead, thus proving the theory that the IPv4/IPv6 hopping is the problem.

[foosel]

... you are indeed right and I'm apparently more tired than I thought. It's been a bit of a long week 😅

[gege2b]

@fieldOfView that was the point indeed :)
@foosel maybe you need some rest :D
Unfortunately I didn't read your comment in time, I won't be able to access my instance until monday at best. I will then do the test you asked for (just in case, even if it's unnecessary)

[FormerLurker]

@gege2b, checkout this issue in the Octolapse repo. Using that thread for anything Octolapse related will help keep the OctoPrint issues focused on OctoPrint itself.

FYI, I have just finished making Octolapse compatible with OctoPrint v1.4.0 (both python2 and 3) and have completed regression testing on OctoPrint v1.3.12. Hopefully your load state issues will go away. I believe I tracked your issue down to differences in the json.dumps command (actual syntax problems that didn't cause issues in an older version), though other since corrected issues could have contributed.

Thanks!

[foosel]

I think I know what is going on and why it is happening under 1.4.0 and not under 1.3.x:

https://github.com/foosel/OctoPrint/blob/devel/src/octoprint/server/__init__.py#L133-L136

This gets triggered when an IP change happens. Which causes the user to basically get logged out. Which right now appears to be wrong, but I'll have to dig a bit deeper and try to figure out why I thought that was necessary. Might just have been a simple misunderstanding though in which case the fix should be easy.

[foosel]

That should be fixed by the above commit, ready for 1.4.0rc3.

Note that I have still not been able to reproduce and thus cannot confirm myself. Based on the code though I see what was wrong.

[foosel]

1.4.0rc3 has just been released