Google KMS on AppEngine Dev Server - logging clutter

Question

This is a known issue: https://issuetracker.google.com/issues/63253097

Further to my question about getting Google KMS working with App Engine, I'm opening a new question about a related but problematic side effect.

Namely, the Google Cloud API discovery appears to want to walk a number of paths outside the AppEngine sandbox. This itself is not a problem, but it makes testing and debugging very problematic because each attempt is logged, producing hundreds of lines like the following:

INFO 03 Jul 2017 14:44:51 Sandbox prevented access to file "/Users"

INFO 03 Jul 2017 14:44:51 If it is a static file, check that application_readable: true is set in your app.yaml

INFO 03 Jul 2017 14:44:52 Sandbox prevented access to file "/usr/lib/Acrobat9/Resource/CMap"

INFO 03 Jul 2017 14:44:52 If it is a static file, check that application_readable: true is set in your app.yaml

INFO 03 Jul 2017 14:44:52 Sandbox prevented access to file "/usr/lib/Acrobat8/Resource/CMap"

INFO 03 Jul 2017 14:44:52 If it is a static file, check that application_readable: true is set in your app.yaml

Is there a way to disable or silence these requests or logs?

EDIT* One of the many results printed by adding traceback.print_stack() to log_access_check_fail in stub.py (sorry it's not very legible here):

Test #1: Sentry.io's Raven imports `pkg_resources`

  File "/Users/bmh/testapp/application.py", line 3, in <module>
    from nassau.application import app, sentry
  File "/Users/bmh/testapp/nassau/application.py", line 28, in <module>
    from raven.contrib.flask import Sentry
  File "/Users/bmh/testapp/python-virtualenv/lib/python2.7/site-packages/raven/__init__.py", line 16, in <module>
    VERSION = __import__('pkg_resources') \
  File "/Users/bmh/testapp/python-virtualenv/lib/python2.7/site-packages/pkg_resources/__init__.py", line 3037, in <module>
    @_call_aside
  File "/Users/bmh/testapp/python-virtualenv/lib/python2.7/site-packages/pkg_resources/__init__.py", line 3021, in _call_aside
    f(*args, **kwargs)
  File "/Users/bmh/testapp/python-virtualenv/lib/python2.7/site-packages/pkg_resources/__init__.py", line 3050, in _initialize_master_working_set
    working_set = WorkingSet._build_master()
  File "/Users/bmh/testapp/python-virtualenv/lib/python2.7/site-packages/pkg_resources/__init__.py", line 646, in _build_master
    ws = cls()
  File "/Users/bmh/testapp/python-virtualenv/lib/python2.7/site-packages/pkg_resources/__init__.py", line 639, in __init__
    self.add_entry(entry)
  File "/Users/bmh/testapp/python-virtualenv/lib/python2.7/site-packages/pkg_resources/__init__.py", line 695, in add_entry
    for dist in find_distributions(entry, True):
  File "/Users/bmh/testapp/python-virtualenv/lib/python2.7/site-packages/pkg_resources/__init__.py", line 2006, in find_on_path
    path_item = _normalize_cached(path_item)
  File "/Users/bmh/testapp/python-virtualenv/lib/python2.7/site-packages/pkg_resources/__init__.py", line 2217, in _normalize_cached
    _cache[filename] = result = normalize_path(filename)
  File "/Users/bmh/testapp/python-virtualenv/lib/python2.7/site-packages/pkg_resources/__init__.py", line 2210, in normalize_path
    return os.path.normcase(os.path.realpath(filename))
  File "/Users/bmh/testapp/python-virtualenv/lib/python2.7/posixpath.py", line 375, in realpath
    path, ok = _joinrealpath('', filename, {})
  File "/Users/bmh/testapp/python-virtualenv/lib/python2.7/posixpath.py", line 400, in _joinrealpath
    if not islink(newpath):
  File "/Users/bmh/testapp/python-virtualenv/lib/python2.7/posixpath.py", line 135, in islink
    st = os.lstat(path)
  File "/usr/local/Caskroom/google-cloud-sdk/latest/google-cloud-sdk/platform/google_appengine/google/appengine/tools/devappserver2/python/stubs.py", line 286, in __call__
    log_access_check_fail(path)
  File "/usr/local/Caskroom/google-cloud-sdk/latest/google-cloud-sdk/platform/google_appengine/google/appengine/tools/devappserver2/python/stubs.py", line 51, in log_access_check_fail
    traceback.print_stack()

I removed the dependency on Sentry / Raven, but the stack traces continue, via:

Test #2: Flask imports `pkgutil`

  File "/Users/bmh/testapp/application.py", line 3, in <module>
    from nassau.application import app
  File "/Users/bmh/testapp/nassau/application.py", line 72, in <module>
    app = Flask('nassau')
  File "/Users/bmh/testapp/python-virtualenv/lib/python2.7/site-packages/flask/app.py", line 331, in __init__
    instance_path = self.auto_find_instance_path()
  File "/Users/bmh/testapp/python-virtualenv/lib/python2.7/site-packages/flask/app.py", line 622, in auto_find_instance_path
    prefix, package_path = find_package(self.import_name)
  File "/Users/bmh/testapp/python-virtualenv/lib/python2.7/site-packages/flask/helpers.py", line 661, in find_package
    loader = pkgutil.get_loader(root_mod_name)
  File "/usr/local/Cellar/python/2.7.13/Frameworks/Python.framework/Versions/2.7/lib/python2.7/pkgutil.py", line 464, in get_loader
    return find_loader(fullname)
  File "/usr/local/Cellar/python/2.7.13/Frameworks/Python.framework/Versions/2.7/lib/python2.7/pkgutil.py", line 475, in find_loader
    loader = importer.find_module(fullname)
  File "/usr/local/Cellar/python/2.7.13/Frameworks/Python.framework/Versions/2.7/lib/python2.7/pkgutil.py", line 184, in find_module
    path = [os.path.realpath(self.path)]
  File "/Users/bmh/testapp/python-virtualenv/lib/python2.7/posixpath.py", line 375, in realpath
    path, ok = _joinrealpath('', filename, {})
  File "/Users/bmh/testapp/python-virtualenv/lib/python2.7/posixpath.py", line 400, in _joinrealpath
    if not islink(newpath):
  File "/Users/bmh/testapp/python-virtualenv/lib/python2.7/posixpath.py", line 135, in islink
    st = os.lstat(path)
  File "/usr/local/Caskroom/google-cloud-sdk/latest/google-cloud-sdk/platform/google_appengine/google/appengine/tools/devappserver2/python/stubs.py", line 286, in __call__
    log_access_check_fail(path)
  File "/usr/local/Caskroom/google-cloud-sdk/latest/google-cloud-sdk/platform/google_appengine/google/appengine/tools/devappserver2/python/stubs.py", line 51, in log_access_check_fail
    traceback.print_stack()

There must be a better way to represent a stack trace on stack overflow :)

I've noticed this on the most recent "traditional" sdk (1.9.56). I've to investigate whether these messages can be suppressed without suppressing other, useful log messages. But I can say that they don't appear in 1.9.50, so if downgrading your sdk is acceptable you could do that. — snakecharmerb, Jul 03 '17 at 15:33
@snakecharmerb Great idea, using gcloud how do you downgrade? Thanks! — Shaun, Jul 05 '17 at 21:53
@Shaun `gcloud components update --version xxx.x.x` will upgrade or downgrade the entire gcloud sdk to the provided version; I don't see a way to upgrade or downgrade specific subcomponents. — snakecharmerb, Jul 06 '17 at 06:03
@Shaun added [answer](https://stackoverflow.com/a/45044637/1953800) to filter out these messages without needing to downgrade gcloud — Alex, Jul 11 '17 at 21:22

score 6 · Accepted Answer · answered Jul 07 '17 at 19:49

6

I am a fulltime engineer working on dev_appserver. This log message is reported from /google/appengine/tools/devappserver2/python/stubs.py, in the method log_access_check_fail

We added this log message to remind users of dev_appserver's behavior of blocking file access.

Recommended workaround: dev_appserver.py --log_level warning

--log_level sets the log level in local python runtime process. The log_access_check_fail() is set to INFO and would not be logged. NOTE, this flag will also prevent other INFO level logging in your application.

Meanwhile, we are working on a fix to this log_access_check_fail method. It could be lowering log_access_check_fail() logging level to DEBUG.

answered Jul 07 '17 at 19:49

Kai Wang

179
1
2

2

Thanks Kai. FWIW, I think log-access failures can be useful debugging info, so it might be better not to disable them entirely (or perhaps make them optionally enabled with a flag); a better answer might be fixing the discovery API (if possible) to not check outside the dev_appserver habitat. – Brian M. Hunt Jul 07 '17 at 20:10
Hi Brian, I agree with the necessity of log-access. Actually, when trying to replicate your issue (on Mac OS & Ubuntu) with the mykms.py [1]. I did not see attempts to access with "/Users" or "/usr/lib/Acrobat9/Resource/CMap". Could you confirm these attempts are made by discovery api, instead of oauthclient2 or your application code? Thanks [1] https://stackoverflow.com/questions/44826934/google-kms-on-appengine-python-development-appserver – Kai Wang Jul 07 '17 at 20:40
@KaiWang, I see the `/usr/lib/Acrobat...` log messages in apps that import the [reportlab](https://pypi.python.org/pypi/reportlab) package. – snakecharmerb Jul 08 '17 at 06:58
@KaiWang is there a public bug report where we can comment on this behaviour? I have more comments on this but SO comments aren't the best location for this discussion. – snakecharmerb Jul 08 '17 at 07:00
@KaiWang It could indeed by oauthclient2 — The issue began when I started using the discovery API, but it could indeed be via the oauth2. We do also include reportlab - but that has been in there for years. – Brian M. Hunt Jul 08 '17 at 12:34
I've edited the question to add a stacktrace. It looks like a lot of things are triggering the access issue. Let me know if something other than the stacktrace would help illuminate. – Brian M. Hunt Jul 08 '17 at 13:11
@snakecharmerb to report GAE public bug/issue, go to this page: https://cloud.google.com/support/docs/issue-trackers#bug_reports and there's a hyperlink 'Create new App Engine issue' – Kai Wang Jul 10 '17 at 16:26
@BrianM.Hunt Admittedly KMS is not the only one triggering the access issue. I'd recommend opening a public issue at Google Cloud Platform's public issue tracker -- it is easier for issue triage, official technical support and also formatting stacktrace :) – Kai Wang Jul 10 '17 at 16:32

Alex · Answer 2 · 2017-07-11T21:25:28.340

This is quite annoying and there is a bug report for it.

In the meantime we can filter out these messages but we need to figure out which logger they are using. See the docs for more info on how logging records are handled. Taking a look at the source for stubs.py I found:

logging.info('Sandbox prevented access to file "%s"', filename)
logging.info('If it is a static file, check that '
           '`application_readable: true` is set in your app.yaml')

So they are using the root logger (bad practice generally). To filter out these messages on your root logger add the following to your appengine_config.py:

import logging

class StubsFilter(logging.Filter):

    def filter(self, record):
        return 'stubs.py' != record.filename

logging.root.addFilter(StubsFilter())

Steve Kritzer · Answer 3 · 2017-07-05T16:33:42.297

For me, these messages appear to originate from a GAE (.local) file called stubs.py.

In my first case, stubs.py was looking for files that were not there. So you might want to check to see if "/usr/lib/Acrobat8/Resource/CMap" actually exists. Then, starting with stubs.py, try to find out what file is trying to load it.
1. My project is using web.py, all of a sudden I started getting (stubs.py) messages again, this time about .pyc files. I put a skip_files: in the bottom of my app.yaml file, and it does suppress the messages, but I haven't tested to see if my app still fully compiles.
```
skip_files:
- ^(.*/)?\.pyc$
```

More on the Python GAE runtime and sandbox here. https://cloud.google.com/appengine/docs/standard/python/runtime

Google KMS on AppEngine Dev Server - logging clutter

Test #1: Sentry.io's Raven imports `pkg_resources`

Test #2: Flask imports `pkgutil`

3 Answers3

Linked

Related

Google KMS on AppEngine Dev Server - logging clutter

Test #1: Sentry.io's Raven imports pkg_resources

Test #2: Flask imports pkgutil

3 Answers3

Linked

Related

Test #1: Sentry.io's Raven imports `pkg_resources`

Test #2: Flask imports `pkgutil`