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.4.0rc3 exception - Insufficient permissions #3375

Closed
gdombiak opened this issue Dec 8, 2019 · 12 comments
Closed

1.4.0rc3 exception - Insufficient permissions #3375

gdombiak opened this issue Dec 8, 2019 · 12 comments

Comments

@gdombiak
Copy link
Contributor

@gdombiak gdombiak commented Dec 8, 2019

What were you doing?

Printing (from OctoPrint) using 1.4.0 rc3 (latest from github staging/devel branch). Running with Python 3.8

What did you expect to happen?

No exception in the logs

What happened instead?

Found the exception below while tailing octoprint.log. I do remember seeing this error before but not 100% sure.

2019-12-07 17:33:36,456 - octoprint.server.api - ERROR - Error calling SimpleApiPlugin action_command_prompt
Traceback (most recent call last):
File "/home/pi/oprint/local/lib/python3.8/site-packages/octoprint/server/api/init.py", line 70, in pluginData
response = api_plugin.on_api_get(request)
File "/home/pi/oprint/lib/python3.8/site-packages/octoprint/plugins/action_command_prompt/init.py", line 124, in on_api_get
return flask.abort(403, "Insufficient permissions")
File "/home/pi/oprint/local/lib/python3.8/site-packages/werkzeug/exceptions.py", line 772, in abort
return _aborter(status, *args, **kwargs)
File "/home/pi/oprint/local/lib/python3.8/site-packages/werkzeug/exceptions.py", line 753, in call
raise self.mapping[code](*args, **kwargs)
werkzeug.exceptions.Forbidden: 403 Forbidden: Insufficient permissions
2019-12-07 17:33:36,464 - tornado.access - ERROR - 500 GET /api/plugin/action_command_prompt (2601:1c0:4600:4c9:c40d:23e3:3fb:a07c) 14.39ms

Did the same happen when running OctoPrint in safe mode?

No tested

Version of OctoPrint

Latest from staging/devel. OctoPrint 1.4.0rc3.dev9+g124f01ca running on OctoPi 0.15.0 (environment up to date).

Operating System running OctoPrint

Raspbian. Using Python 3.8

Printer model & used firmware incl. version

Ender 3. Marlin 2.0.0 (released version)

Browser and version of browser, operating system running browser

Link to octoprint.log

Can provide if needed.

Link to contents of terminal tab or serial.log

Can provide if needed.

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.

Copy link
Owner

@foosel foosel commented Dec 9, 2019

Can you please provide a full log? I need some context to be able to track that down.

@foosel foosel modified the milestones: 1.4.1, 1.4.0 Dec 9, 2019
@gdombiak

This comment has been minimized.

Copy link
Contributor Author

@gdombiak gdombiak commented Dec 10, 2019

Log is available here: https://gist.github.com/gdombiak/d0813fed419e27a0a641932b769e4758

That log includes this exception as well as more examples of the other exception reported in the other issue.

@foosel

This comment has been minimized.

Copy link
Owner

@foosel foosel commented Dec 10, 2019

2019-12-07 17:33:36,172 - tornado.access - WARNING - 403 GET /api/system/commands (blablabla) 21.86ms
2019-12-07 17:33:36,196 - tornado.access - WARNING - 403 GET /api/access/groups (blablabla) 17.84ms
2019-12-07 17:33:36,298 - tornado.access - WARNING - 403 GET /api/printerprofiles (blablabla) 64.67ms
2019-12-07 17:33:36,316 - tornado.access - WARNING - 403 GET /api/timelapse?unrendered=true (blablabla) 13.90ms
2019-12-07 17:33:36,331 - tornado.access - WARNING - 403 GET /plugin/announcements/channels (blablabla) 11.14ms
2019-12-07 17:33:36,347 - tornado.access - WARNING - 403 GET /api/connection (blablabla) 11.93ms
2019-12-07 17:33:36,364 - tornado.access - WARNING - 403 GET /api/printer/command/custom (blablabla) 12.84ms
2019-12-07 17:33:36,381 - tornado.access - WARNING - 403 GET /api/slicing (blablabla) 12.82ms
2019-12-07 17:33:36,397 - tornado.access - WARNING - 403 GET /api/plugin/printer_safety_check (blablabla) 11.89ms
2019-12-07 17:33:36,413 - tornado.access - WARNING - 403 GET /api/plugin/pluginmanager (blablabla) 12.07ms
2019-12-07 17:33:36,428 - tornado.access - WARNING - 403 GET /plugin/softwareupdate/check (blablabla) 10.96ms
2019-12-07 17:33:36,446 - tornado.access - WARNING - 403 GET /api/files?recursive=true (blablabla) 13.11ms
2019-12-07 17:33:36,456 - octoprint.server.api - ERROR - Error calling SimpleApiPlugin action_command_prompt
Traceback (most recent call last):
  File "/home/pi/oprint/local/lib/python3.8/site-packages/octoprint/server/api/__init__.py", line 70, in pluginData
    response = api_plugin.on_api_get(request)
  File "/home/pi/oprint/lib/python3.8/site-packages/octoprint/plugins/action_command_prompt/__init__.py", line 124, in on_api_get
    return flask.abort(403, "Insufficient permissions")
  File "/home/pi/oprint/local/lib/python3.8/site-packages/werkzeug/exceptions.py", line 772, in abort
    return _aborter(status, *args, **kwargs)
  File "/home/pi/oprint/local/lib/python3.8/site-packages/werkzeug/exceptions.py", line 753, in __call__
    raise self.mapping[code](*args, **kwargs)
werkzeug.exceptions.Forbidden: 403 Forbidden: Insufficient permissions
2019-12-07 17:33:36,464 - tornado.access - ERROR - 500 GET /api/plugin/action_command_prompt (blablabla) 14.39ms

There's a whole bunch of 403's that go before this exception (which I need to figure out why it gets logged with a full trace and causes a 500 instead of simply returning a 403 as well). That reeks a bit of a lost session and hence #3370 which I already fixed in current RC3.dev versions late yesterday afternoon. It's sadly hard to say because you redacted the client IPs, which are the key here to figure out if it's indeed the same session issue. Can you check if the IP for which the login was logged at line 1701 (2019-12-07 17:33:34,035 - octoprint.server.util.flask - INFO - Passively logging in user qweqwe from blablabla) matches the one on the 403s? Alternatively, can you share an unmodified copy of the log in private by mailing it to gina -at- octoprint.org?

foosel added a commit that referenced this issue Dec 10, 2019
@foosel

This comment has been minimized.

Copy link
Owner

@foosel foosel commented Dec 10, 2019

At least the 500/stack trace should be fixed by the above commit. Actually not a regression in 1.4.0 but 1.3.11 already.

Still thinking the permission loss that triggered it is actually caused by #3370. Would be great if you could confirm or deny or just test if it is still reproducible with current staging/devel.

@gdombiak

This comment has been minimized.

Copy link
Contributor Author

@gdombiak gdombiak commented Dec 11, 2019

Arrggg! I never delete logs but just did that when running my other tests to have clean logs ...... grrrrrr!

I will try to do my best to find a way to reproduce this error. I only saw it once ever in the logs. Will see if an old http session can do the trick.

@gdombiak

This comment has been minimized.

Copy link
Contributor Author

@gdombiak gdombiak commented Dec 11, 2019

FYI, I just updated to run latest from staging/devel. Using commit 5d1ad5d

@gdombiak

This comment has been minimized.

Copy link
Contributor Author

@gdombiak gdombiak commented Dec 11, 2019

After many prints and many other tests .... I haven't been able to reproduce this exception or any 403 in the logs. :( Will keep an eye on this error. Will close ticket by the end of week if still not able to reproduce, sounds good?

@foosel

This comment has been minimized.

Copy link
Owner

@foosel foosel commented Dec 11, 2019

I haven't been able to reproduce this exception or any 403 in the logs. :(

You frown, but for me that is good news because it sounds like the 403 was indeed the one from #3370.

Will close ticket by the end of week if still not able to reproduce, sounds good?

I want to try to push out the third RC before that, so let's just hope it's really gone ;)

@gdombiak

This comment has been minimized.

Copy link
Contributor Author

@gdombiak gdombiak commented Dec 11, 2019

:D

I was expecting to see 403s followed by no stack trace. Did the fix also avoid seeing 403s? Been printing all night and still today. Will keep you up to date.

@foosel

This comment has been minimized.

Copy link
Owner

@foosel foosel commented Dec 11, 2019

The fix of this ticket didn't, but the fix for #3370 solved an issue that could lead to a loss of session and thus a ton of 403s.

@gdombiak

This comment has been minimized.

Copy link
Contributor Author

@gdombiak gdombiak commented Dec 11, 2019

Gotcha! Will close tonight after confirming no errors appeared in the last 24 hours.

@gdombiak

This comment has been minimized.

Copy link
Contributor Author

@gdombiak gdombiak commented Dec 12, 2019

Logs are clean! Closing ticket

@gdombiak gdombiak closed this Dec 12, 2019
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
3 participants
You can’t perform that action at this time.