Your data. Anywhere you go.

New Relic for iOS or Android


Download on the App Store    Android App on Google play


New Relic Insights App for iOS


Download on the App Store


Learn more

Close icon

Agent doesn't start well with aiohttp

errors
wsgi
gunicorn

#1
  • Python agent newrelic 4.10.0.112
  • aiohttp 3.4.4

I run aiohttp.web.Application in a docker container through gunicorn as a simple command:

gunicorn websockets.app:websockets_app -w 2 -b 0.0.0.0:9000 -k aiohttp.worker.GunicornWebWorker

When I prepend it with NEW_RELIC_CONFIG_FILE=newrelic.ini newrelic-admin run-program ... i get a wsgi error:

  File "/usr/local/lib/python3.6/site-packages/aiohttp/worker.py", line 60, in run
    self.wsgi = self.loop.run_until_complete(self.wsgi())
  File "/usr/local/lib/python3.6/site-packages/newrelic/api/web_transaction.py", line 1189, in _nr_wsgi_application_wrapper_
    environ, start_response = _args(*args, **kwargs)
TypeError: _args() missing 2 required positional arguments: 'environ' and 'start_response'

my entrypoint is an app factory which returns web.Application instance:

async def websockets_app(*args, **kwargs):
    """Creates an app for gunicorn."""
    app = await create_app()
    return app

Thinking of web.Application.__call__ signature, I tried to switch to initialize agent on top of my app.py:

# -*- coding: utf-8 -*-
import newrelic.agent  # noqa isort:skip
newrelic.agent.initialize('newrelic.ini')  # noqa

import asyncio
import logging
... the rest of the file ...

alas I get the nasty message:

Some modules were uninstrumented during the current time window: aiohttp.web, aiohttp.client, aiohttp.web_response, aiohttp.web_urldispatcher, aiohttp.client_reqrep, jinja2.environment . Make sure newrelic.agent.initialize() is called before any of these modules are imported.

and these are the imports:

2019-01-16 15:40:11,643 (6/MainThread) newrelic.config DEBUG - register module ('asyncio.tasks', 'newrelic.hooks.coroutines_asyncio', 'instrument_asyncio_tasks')
2019-01-16 15:40:11,644 (6/MainThread) newrelic.config DEBUG - instrument module (<module 'asyncio.tasks' from '/usr/local/lib/python3.6/asyncio/tasks.py'>, 'newrelic.hooks.coroutines_asyncio', 'instrument_asyncio_tasks')
2019-01-16 15:40:11,645 (6/MainThread) newrelic.config DEBUG - register module ('django.core.handlers.base', 'newrelic.hooks.framework_django', 'instrument_django_core_handlers_base')
2019-01-16 15:40:11,645 (6/MainThread) newrelic.config DEBUG - register module ('django.core.handlers.wsgi', 'newrelic.hooks.framework_django', 'instrument_django_core_handlers_wsgi')
...
2019-01-16 15:40:11,656 (6/MainThread) newrelic.config DEBUG - register module ('jinja2.environment', 'newrelic.hooks.template_jinja2', 'instrument')
2019-01-16 15:40:11,656 (6/MainThread) newrelic.api.import_hook DEBUG - Module <module 'jinja2.environment' from '/usr/local/lib/python3.6/site-packages/jinja2/environment.py'> has been imported before the newrelic.agent.initialize call. Import and initialize the New Relic agent before all other modules for best monitoring results.
...
2019-01-16 15:40:11,660 (6/MainThread) newrelic.api.import_hook DEBUG - Module <module 'aiohttp.web' from '/usr/local/lib/python3.6/site-packages/aiohttp/web.py'> has been imported before the newrelic.agent.initialize call. Import and initialize the New Relic agent before all other modules for best monitoring results.
...

etc.

why is that? And how come that I can’t initialize through newrelic-admin run-program command in the first place?

I would really appreciate any help


#2

wandering through the logs (after I fired it up with newrelic.agent.initialize('newrelic.ini')) I also encountered this record:

newrelic.core.agent DEBUG - Application was activated from: '  

  File "<string>", line 1, in <module>
  File "/usr/local/lib/python3.6/multiprocessing/spawn.py", line 105, in spawn_main
    exitcode = _main(fd)
  File "/usr/local/lib/python3.6/multiprocessing/spawn.py", line 118, in _main
    return self._bootstrap()
  File "/usr/local/lib/python3.6/multiprocessing/process.py", line 258, in _bootstrap
    self.run()
  File "/usr/local/lib/python3.6/multiprocessing/process.py", line 93, in run
    self._target(*self._args, **self._kwargs)
  File "/usr/local/lib/python3.6/site-packages/aiohttp_devtools/runserver/serve.py", line 115, in serve_main_app
    loop.run_forever()
  File "/usr/local/lib/python3.6/asyncio/base_events.py", line 422, in run_forever
    self._run_once()
  File "/usr/local/lib/python3.6/asyncio/base_events.py", line 1434, in _run_once
    handle._run()
  File "/usr/local/lib/python3.6/asyncio/events.py", line 145, in _run
    self._callback(*self._args)
  File "/usr/local/lib/python3.6/site-packages/aiohttp/web_protocol.py", line 390, in start
    resp = await self._request_handler(request)
  File "/usr/local/lib/python3.6/site-packages/newrelic/hooks/framework_aiohttp.py", line 61, in __next__
    return self.send(None)
  File "/usr/local/lib/python3.6/site-packages/newrelic/hooks/framework_aiohttp.py", line 67, in send
    txn = WebTransaction(app, self._nr_environ)
  File "/usr/local/lib/python3.6/site-packages/newrelic/api/web_transaction.py", line 100, in __init__
    super(WebTransaction, self).__init__(application, enabled)
  File "/usr/local/lib/python3.6/site-packages/newrelic/api/transaction.py", line 206, in __init__
    application.activate()
  File "/usr/local/lib/python3.6/site-packages/newrelic/api/application.py", line 88, in activate
    newrelic.api.import_hook._uninstrumented_modules)


#3

Hi @ylobanov , thanks for reporting this! I’ve reproduced this problem. For now the best way to handle this error is to disable the gunicorn automatic instrumentation by adding the following to your newrelic.ini file:

[import-hook:gunicorn.app.base]
enabled=false

The application should be able to start using the NEW_RELIC_CONFIG_FILE=newrelic.ini newrelic-admin run-program ... command after that!


#4

thanks A LOT! that’s just terrific! I would never find that option and already spent a lot of time digging into import-hook.
you’re a champion!


#5

Hi @ylobanov,

We think this has been fixed with the release of the latest Python agent 4.12.0. Could you check and let us know?


#6

thank you for the notification, I’ll give it a shot.


#7

it seems (!) to work, however i noticed two tracebacks:

DEBUG:newrelic.core.agent:Monitored application started using the newrelic-admin command with command line of [’/usr/local/bin/newrelic-admin’, ‘run-program’, ‘/usr/local/bin/gunicorn’, ‘websockets.app:websockets_app’, ‘-w’, ‘2’, ‘-b’, ‘0.0.0.0:9099’, ‘-k’, ‘aiohttp.GunicornWebWorker’, ‘–chdir=/code’].
DEBUG:newrelic.core.agent:Creating instance of Python agent in process 3174.
DEBUG:newrelic.core.agent:Agent was initialized from:

  File "/usr/local/bin/gunicorn", line 11, in <module>
    sys.exit(run())
  File "/usr/local/lib/python3.6/site-packages/gunicorn/app/wsgiapp.py", line 61, in run
    WSGIApplication("%(prog)s [OPTIONS] [APP_MODULE]").run()
  File "/usr/local/lib/python3.6/site-packages/gunicorn/app/base.py", line 223, in run
    super(Application, self).run()
  File "/usr/local/lib/python3.6/site-packages/gunicorn/app/base.py", line 72, in run
    Arbiter(self).run()
  File "/usr/local/lib/python3.6/site-packages/gunicorn/arbiter.py", line 203, in run
    self.manage_workers()
  File "/usr/local/lib/python3.6/site-packages/gunicorn/arbiter.py", line 545, in manage_workers
    self.spawn_workers()
  File "/usr/local/lib/python3.6/site-packages/gunicorn/arbiter.py", line 616, in spawn_workers
    self.spawn_worker()
  File "/usr/local/lib/python3.6/site-packages/gunicorn/arbiter.py", line 583, in spawn_worker
    worker.init_process()
  File "/usr/local/lib/python3.6/site-packages/aiohttp/worker.py", line 52, in init_process
    super().init_process()
  File "/usr/local/lib/python3.6/site-packages/gunicorn/workers/base.py", line 134, in init_process
    self.run()
  File "/usr/local/lib/python3.6/site-packages/aiohttp/worker.py", line 58, in run
    self.loop.run_until_complete(self._task)
  File "/usr/local/lib/python3.6/asyncio/base_events.py", line 455, in run_until_complete
    self.run_forever()
  File "/usr/local/lib/python3.6/asyncio/base_events.py", line 422, in run_forever
    self._run_once()
  File "/usr/local/lib/python3.6/asyncio/base_events.py", line 1434, in _run_once
    handle._run()
  File "/usr/local/lib/python3.6/asyncio/events.py", line 145, in _run
    self._callback(*self._args)
  File "/usr/local/lib/python3.6/site-packages/newrelic/hooks/framework_aiohttp.py", line 91, in send
    app = application_instance()
  File "/usr/local/lib/python3.6/site-packages/newrelic/api/application.py", line 138, in application_instance
    return Application._instance(name)
  File "/usr/local/lib/python3.6/site-packages/newrelic/api/application.py", line 27, in _instance
    agent = newrelic.core.agent.agent_instance()
  File "/usr/local/lib/python3.6/site-packages/newrelic/core/agent.py", line 729, in agent_instance
    return Agent.agent_singleton()

DEBUG:newrelic.core.agent:Initializing Python agent.
DEBUG:newrelic.core.agent:Activating agent instance.
DEBUG:newrelic.core.agent:Start Python Agent main thread.
DEBUG:newrelic.core.agent:Entering harvest loop.
DEBUG:newrelic.core.agent:Registering builtin data sources.
DEBUG:newrelic.core.agent:Register data source with agent (<function _CPUUsageDataSource at 0x7fdbdc7830d0>, None, None, None, {}).
DEBUG:newrelic.core.agent:Register data source with agent (<function memory_usage_data_source at 0x7fdbdc783488>, None, None, None, {}).
DEBUG:newrelic.core.agent:Register data source with agent (<function thread_utilization_data_source at 0x7fdbdc783840>, None, None, None, {}).
DEBUG:newrelic.core.agent:Creating application instance for ‘(Dev)’ in process 3174.

  File "/usr/local/bin/gunicorn", line 11, in <module>
    sys.exit(run())
  File "/usr/local/lib/python3.6/site-packages/gunicorn/app/wsgiapp.py", line 61, in run
    WSGIApplication("%(prog)s [OPTIONS] [APP_MODULE]").run()
  File "/usr/local/lib/python3.6/site-packages/gunicorn/app/base.py", line 223, in run
    super(Application, self).run()
  File "/usr/local/lib/python3.6/site-packages/gunicorn/app/base.py", line 72, in run
    Arbiter(self).run()
  File "/usr/local/lib/python3.6/site-packages/gunicorn/arbiter.py", line 203, in run
    self.manage_workers()
  File "/usr/local/lib/python3.6/site-packages/gunicorn/arbiter.py", line 545, in manage_workers
    self.spawn_workers()
  File "/usr/local/lib/python3.6/site-packages/gunicorn/arbiter.py", line 616, in spawn_workers
    self.spawn_worker()
  File "/usr/local/lib/python3.6/site-packages/gunicorn/arbiter.py", line 583, in spawn_worker
    worker.init_process()
  File "/usr/local/lib/python3.6/site-packages/aiohttp/worker.py", line 52, in init_process
    super().init_process()
  File "/usr/local/lib/python3.6/site-packages/gunicorn/workers/base.py", line 134, in init_process
    self.run()
  File "/usr/local/lib/python3.6/site-packages/aiohttp/worker.py", line 58, in run
    self.loop.run_until_complete(self._task)
  File "/usr/local/lib/python3.6/asyncio/base_events.py", line 455, in run_until_complete
    self.run_forever()
  File "/usr/local/lib/python3.6/asyncio/base_events.py", line 422, in run_forever
    self._run_once()
  File "/usr/local/lib/python3.6/asyncio/base_events.py", line 1434, in _run_once
    handle._run()
  File "/usr/local/lib/python3.6/asyncio/events.py", line 145, in _run
    self._callback(*self._args)
  File "/usr/local/lib/python3.6/site-packages/newrelic/hooks/framework_aiohttp.py", line 92, in send
    txn = WebTransaction(app, self._nr_environ)
  File "/usr/local/lib/python3.6/site-packages/newrelic/api/web_transaction.py", line 100, in __init__
    super(WebTransaction, self).__init__(application, enabled)
  File "/usr/local/lib/python3.6/site-packages/newrelic/api/transaction.py", line 206, in __init__
    application.activate()
  File "/usr/local/lib/python3.6/site-packages/newrelic/api/application.py", line 88, in activate
    newrelic.api.import_hook._uninstrumented_modules)

and then it goes further:

DEBUG:newrelic.core.application:Initializing application with name ‘(Dev)’ and linked applications of [].
DEBUG:newrelic.core.application:Register data source <function _CPUUsageDataSource at 0x7fdbdc7830d0> against application where application=’(Dev)’, name=None, settings=None and properties={}.


#8

Hi @ylobanov, that’s completely normal when logging with debug verbosity! Thanks for giving it a shot and reporting the results here!