Google KMS on AppEngine Dev Server - logging clutt

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 :)

Answer 1

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())

Answer 2

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.

Answer 3

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

1. 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.

   2. 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