We've had a report that Scout breaks Django Channels.

1. Don't break apps using Django Channels
2. Investigate supporting tracing for Django Channels (potentially as a separate issue)

Right now, directory permissions are set with:

https://github.com/scoutapp/scout_apm_python/blob/cab4f2218cfada275a45c355269e61a8945fa581/src/scout_apm/core/core_agent_manager.py#L144

Which obviously results in 700 perms on /tmp/scout_apm_core/*.

In my setup, this ends up requiring root to clear these files. If I could set the perms to 770 from a configuration option, it would make it a lot easier to clear these files out.

Performing ES search in a Django view raise an exception with Scout APM v2.0.0. Same code with Scout v1.3.8 worked as expected. Disabling the instrumentation with SCOUT_DISABLED_INSTRUMENTS='elasticsearch' circumvents the issue.

Project dependencies

• Django==2.0.9
• django-elasticsearch-dsl==0.5.0
• elasticsearch==6.2.0
• elasticsearch-dsl==6.1.0

Stack trace

Traceback (most recent call last):
  File "/usr/local/lib/python3.6/site-packages/django/core/handlers/exception.py", line 35, in inner
    response = get_response(request)
  File "/usr/local/lib/python3.6/site-packages/django/core/handlers/base.py", line 128, in _get_response
    response = self.process_exception_by_middleware(e, request)
  File "/usr/local/lib/python3.6/site-packages/django/core/handlers/base.py", line 126, in _get_response
    response = wrapped_callback(request, *callback_args, **callback_kwargs)
  File "/usr/local/lib/python3.6/contextlib.py", line 52, in inner
    return func(*args, **kwds)
  File "/usr/local/lib/python3.6/site-packages/django/views/decorators/csrf.py", line 54, in wrapped_view
    return view_func(*args, **kwargs)
  File "/usr/local/lib/python3.6/site-packages/rest_framework/viewsets.py", line 103, in view
    return self.dispatch(request, *args, **kwargs)
  File "/usr/local/lib/python3.6/site-packages/rest_framework/views.py", line 483, in dispatch
    response = self.handle_exception(exc)
  File "/usr/local/lib/python3.6/site-packages/rest_framework/views.py", line 443, in handle_exception
    self.raise_uncaught_exception(exc)
  File "/usr/local/lib/python3.6/site-packages/rest_framework/views.py", line 480, in dispatch
    response = handler(request, *args, **kwargs)
  File "/usr/local/lib/python3.6/site-packages/rest_framework/mixins.py", line 40, in list
    queryset = self.filter_queryset(self.get_queryset())
  File "/usr/src/app/prose/backoffice/views/salon.py", line 56, in get_queryset
    queryset = search.to_queryset()
  File "/usr/local/lib/python3.6/site-packages/django_elasticsearch_dsl/search.py", line 28, in to_queryset
    pks = [result._id for result in s]
  File "/usr/local/lib/python3.6/site-packages/elasticsearch_dsl/search.py", line 306, in __iter__
    return iter(self.execute())
  File "/usr/local/lib/python3.6/site-packages/elasticsearch_dsl/search.py", line 679, in execute
    **self._params
  File "/usr/local/lib/python3.6/site-packages/scout_apm/core/monkey.py", line 243, in __call__
    self.__subject__, self._eop_instance_, *args, **kwargs
  File "<string>", line 5, in search
AttributeError: 'list' object has no attribute 'title'

In some of the exceptions that were thrown due to #73, I also saw this exception:

  File "flask/app.py", line 1982, in wsgi_app
    response = self.full_dispatch_request()
  File "flask/app.py", line 1614, in full_dispatch_request
    rv = self.handle_user_exception(e)
  File "flask/app.py", line 1517, in handle_user_exception
    reraise(exc_type, exc_value, tb)
  File "flask/_compat.py", line 33, in reraise
    raise value
  File "flask/app.py", line 1612, in full_dispatch_request
    rv = self.dispatch_request()
  File "scout_apm/flask/__init__.py", line 72, in dispatch_request
    return view_func(**req.view_args)
  File "scout_apm/core/monkey.py", line 212, in __call__
    return self._eop_wrapper_(self.__subject__, *args, **kwargs)
  File "scout_apm/flask/__init__.py", line 115, in tracing_function
    TrackedRequest.instance().tag('error', 'true')
  File "scout_apm/core/tracked_request.py", line 42, in tag
  TypeError: not enough arguments for format string

The problem is:

https://github.com/scoutapp/scout_apm_python/blob/1dd5b76f9b4fd65d707111d78a4445254b219e7f/src/scout_apm/core/tracked_request.py#L42

It looks like you want to pass in a tuple to the string formatter, but because you are in a function call, the implicit tuple is not being parsed as you anticipate. You probably want:

logger.debug('Overwriting previously set tag for request %s: %s' % (self.req_id, key)) 

Although, the Python logger will handle string formatting for you automatically, so I believe this will also work and feels a bit "cleaner" to me.

logger.debug('Overwriting previously set tag for request %s: %s', self.req_id, key) 

Using celery-batches 0.2.0, celery 4.4.7, python 3.10, redis backend

What happens: Request with missing delivery_info raises error. This bubbles up to sentry, another tool.

Expected behavior: Drop the trace is unless error reporting is enabled on scout-apm.

AttributeError: 'NoneType' object has no attribute 'get'
  File "celery/utils/dispatch/signal.py", line 288, in send
    response = receiver(signal=self, sender=sender, **named)
  File "scout_apm/celery.py", line 60, in task_prerun_callback
    tracked_request.tag("is_eager", delivery_info.get("is_eager", False))

{
args: [
[
<celery_batches.SimpleRequest object at 0x7fbd1f2f9720>, 
<celery_batches.SimpleRequest object at 0x7fcd15dd65e0>, 
<celery_batches.SimpleRequest object at 0x7fad18d6fa30>, 
<celery_batches.SimpleRequest object at 0x7fed14d6e1a0>, 
<celery_batches.SimpleRequest object at 0x7fad13d6e230>
]
], 
kwargs: {}, 
sender: <@task: project.app.jobs.track_happening of project at 0x2faa2c2713f0 (v2 compatible)>, 
signal: <Signal: task_prerun providing_args={'args', 'kwargs', 'task', 'task_id'}>, 
task_id: '684c6b14-4349-42e7-bc8d-4d410bceb1c9'
}

Hi Team,

This regards an issue we've encountered deploying Scout onto Heroku. We use Heroku config vars (environment variables) to control features within our Django app.

We found that by having the SCOUT_MONITOR variable set to True the compile never finished. We discovered that having Scout disabled and then enabling it after the build worked.

My thinking is that the Scout application runs and then maintains a lock so the compile process waits until it times out.

We overcame this by adding some logic to detect if the app is in the build step and adjusting SCOUT_MONITOR accordingly.

We are not using the Heroku integred Scout (yet!- evaluating the trial)

This is the tail-end of the Heroku build log.

2019-07-16T16:04:22+0000 DEBUG Configuration Loaded:
2019-07-16T16:04:22+0000 DEBUG Defaults : app_server = 
2019-07-16T16:04:22+0000 DEBUG Python   : application_root = /tmp/build_4f11ea1302cf7a6244dc110fc3785e7a/housekeep
2019-07-16T16:04:22+0000 DEBUG Defaults : core_agent_dir = /tmp/scout_apm_core
2019-07-16T16:04:22+0000 DEBUG Defaults : core_agent_download = True
2019-07-16T16:04:22+0000 DEBUG Defaults : core_agent_launch = True
2019-07-16T16:04:22+0000 DEBUG Defaults : core_agent_permissions = 700
2019-07-16T16:04:22+0000 DEBUG Defaults : core_agent_version = v1.1.8
2019-07-16T16:04:22+0000 DEBUG Defaults : disabled_instruments = []
2019-07-16T16:04:22+0000 DEBUG Defaults : download_url = https://s3-us-west-1.amazonaws.com/scout-public-downloads/apm_core_agent/release
2019-07-16T16:04:22+0000 DEBUG Defaults : framework = 
2019-07-16T16:04:22+0000 DEBUG Defaults : framework_version = 
2019-07-16T16:04:22+0000 DEBUG Defaults : hostname = 
2019-07-16T16:04:22+0000 DEBUG Null     : ignore = None
2019-07-16T16:04:22+0000 DEBUG ENV      : key = #MANUALLY_REDACTED#
2019-07-16T16:04:22+0000 DEBUG Defaults : log_level = info
2019-07-16T16:04:22+0000 DEBUG Python   : monitor = TRUE
2019-07-16T16:04:22+0000 DEBUG ENV      : name = housekeep-staging
2019-07-16T16:04:22+0000 DEBUG Defaults : revision_sha = 
2019-07-16T16:04:22+0000 DEBUG Defaults : scm_subdirectory = 
2019-07-16T16:04:22+0000 DEBUG Derived  : socket_path = /tmp/scout_apm_core/scout_apm_core-v1.1.8-x86_64-unknown-linux-gnu/core-agent.sock
2019-07-16T16:04:22+0000 INFO Unable to import for Jinja2 instruments
2019-07-16T16:04:22+0000 INFO Jinja2 instruments are not installable. Skipping.
2019-07-16T16:04:22+0000 INFO Unable to import for PyMongo instruments
2019-07-16T16:04:22+0000 INFO PyMongo instruments are not installable. Skipping.
2019-07-16T16:04:22+0000 INFO Instrumented Redis
2019-07-16T16:04:22+0000 INFO Instrumented Urllib3
2019-07-16T16:04:22+0000 INFO Unable to import for Elasticsearch instruments
2019-07-16T16:04:22+0000 INFO Elasticsearch instruments are not installable. Skipping.
2019-07-16T16:04:22+0000 DEBUG APM Launching on PID: 13839
2019-07-16T16:04:22+0000 DEBUG Parsing Core Agent manifest path: /tmp/scout_apm_core/scout_apm_core-v1.1.8-x86_64-unknown-linux-gnu/manifest.json
2019-07-16T16:04:22+0000 DEBUG Core Agent manifest json: {u'core_agent_version': u'1.1.8', u'core_agent_binary': u'core-agent', u'version': u'1.1.8', u'core_agent_binary_sha256': u'e2b93a7075a195755dc46fcee05096c27bcbfae92b8586b794541c529c16b1f2'}
[2019-07-16T15:04:22][core_agent][INFO] Initializing logger with log level: Info
2019-07-16T16:04:22+0000 DEBUG CoreAgentSocket attempt 1, connecting to /tmp/scout_apm_core/scout_apm_core-v1.1.8-x86_64-unknown-linux-gnu/core-agent.sock, PID: 13839, Thread: <CoreAgentSocket(Thread-1, started daemon 140086430947072)>
2019-07-16T16:04:22+0000 DEBUG CoreAgentSocket is connected
2019-07-16T16:04:22+0000 INFO Registering with app=housekeep-staging key=#MANUALLY_REDACTED#
2019-07-16T16:04:22+0000 DEBUG CoreAgentSocket thread stopping.
2019-07-16T16:04:22+0000 DEBUG CoreAgentSocket thread stopped.
2019-07-16T16:04:22+0000 DEBUG Monkey patched SQL
2019-07-16T16:04:22+0000 DEBUG Monkey patched Templates
2019-07-16T16:04:23+0000 DEBUG Converted retries value: 3 -> Retry(total=3, connect=None, read=None, redirect=None, status=None)
2019-07-16T16:04:23+0000 DEBUG Starting request: req-05e13e23-8260-44eb-af26-02cde19c6570
2019-07-16T16:04:23+0000 DEBUG Stopping request: req-05e13e23-8260-44eb-af26-02cde19c6570
2019-07-16T16:04:23+0000 DEBUG Starting request: req-249fdfd2-a8f6-42c5-9119-8b164625ee62
2019-07-16T16:04:23+0000 DEBUG Stopping request: req-249fdfd2-a8f6-42c5-9119-8b164625ee62
2019-07-16T16:04:23+0000 DEBUG Starting request: req-70b8b033-46aa-4c7a-b3e6-46efe3730620
2019-07-16T16:04:23+0000 DEBUG Stopping request: req-70b8b033-46aa-4c7a-b3e6-46efe3730620
Cache "default" has been cleared!

After the last line is printed it refuses to budge. At this point it has registered the app name with scoutapm.com

I feel our workaround is a bit janky, should ideally be seamless.

Hope this helps!

Hi there,

So, we are looking for ways to reduce the total number of transactions in scout... and the sampling solution for ruby was neat and clever. So, any chance of this coming? At least for flask :-).

While testing with some fairly large context objects, I was not seeing any requests on the web interface. I did not see any errors from the agent, and it appeared that the python library was sending the span to the agent.

Flattening the dict objects into strings seems to solve the issue. This wasn't mentioned as a limitation in the docs and I would have liked to see an error message somewhere.

I can try to provide an example if you have any issues reproducing this.

The Python agent instruments database queries, adds tracebacks to slow queries, and identifies N+1s but does not have the dedicated database query view that's available in the Ruby agent.

Add the required functionality to the agent to support the database addon functionality within Scout.

Hi,

I've been trying out scout with a django app deployed to heroku. Thus far I've been really enjoying it!

One thing I've noticed on both a staging app and the main app is that shortly after deploying and enabling scout for the first time a number of different views would throw errors, with the stack trace:

IndexError: pop from empty list
  File "django/core/handlers/exception.py", line 35, in inner
    response = get_response(request)
  File "django/core/handlers/base.py", line 119, in _get_response
    response = middleware_method(request, callback, callback_args, callback_kwargs)
  File "scout_apm/core/monkey.py", line 212, in __call__
    return self._eop_wrapper_(self.__subject__, *args, **kwargs)
  File "scout_apm/core/stacktracer.py", line 61, in tracing_function
    TrackedRequest.instance().stop_span()
  File "scout_apm/core/tracked_request.py", line 58, in stop_span
    stopping_span = self.active_spans.pop()

These errors don't persist after refresh, and don't seem to be triggered after re-visiting the page. Nor is there any pattern to when they are thrown, except that they no longer seem to throw once the page has refreshed and loaded successfully. So apologies if this is raising an issue that can't be reproduced; I'm happy for this to be closed until/if I can find a means of triggering it reliably.

One complicating factor might be that the app uses channels and thus the daphne webserver and ASGI. Other complicating factors might be that we are using Sentry and Redis for caching.

Looks like it was related to this change: https://github.com/scoutapp/scout_apm_python/pull/668/files

I'm not entirely sure what causes this. We're also using a custom integration, incase thats a factor.

The particular module it is trying to load (when we get the exception) is repoze.who.middleware

We've not made changes to our integration, and has been breaking since, 2.21, but is also happening on 2.23.2

Below is a stack trace, starting from when we run .install()

Please let me know if theres anything else I can provide, I'm not sure how to debug this further

scout_apm.api.install(config=scout_config)
File "/usr/local/lib/python3.7/site-packages/scout_apm/compat.py", line 142, in wrapper
 return func(*args, **kwargs)
File "/usr/local/lib/python3.7/site-packages/scout_apm/core/__init__.py", line 45, in install
 launched = CoreAgentManager().launch()
File "/usr/local/lib/python3.7/site-packages/scout_apm/core/agent/manager.py", line 49, in launch
 self.download()
File "/usr/local/lib/python3.7/site-packages/scout_apm/core/agent/manager.py", line 58, in download
 self.downloader.download()
File "/usr/local/lib/python3.7/site-packages/scout_apm/core/agent/manager.py", line 161, in download
 downloaded = self.download_package()
File "/usr/local/lib/python3.7/site-packages/scout_apm/core/agent/manager.py", line 209, in download_package
 "GET", full_url, preload_content=False, timeout=10.0, retries=3
File "/usr/local/lib/python3.7/site-packages/urllib3/request.py", line 75, in request
 method, url, fields=fields, headers=headers, **urlopen_kw
File "/usr/local/lib/python3.7/site-packages/urllib3/request.py", line 96, in request_encode_url
 return self.urlopen(method, url, **extra_kw)
File "/usr/local/lib/python3.7/site-packages/urllib3/poolmanager.py", line 375, in urlopen
 response = conn.urlopen(method, u.request_uri, **kw)
File "/usr/local/lib/python3.7/site-packages/scout_apm/instruments/urllib3.py", line 68, in wrapped_urlopen
 return wrapped(*args, **kwargs)
File "/usr/local/lib/python3.7/contextlib.py", line 119, in __exit__
 next(self.gen)
File "/usr/local/lib/python3.7/site-packages/scout_apm/core/tracked_request.py", line 134, in span
 self.stop_span()
File "/usr/local/lib/python3.7/site-packages/scout_apm/core/tracked_request.py", line 122, in stop_span
 stopping_span.annotate()
File "/usr/local/lib/python3.7/site-packages/scout_apm/core/tracked_request.py", line 258, in annotate
 self.capture_backtrace()
File "/usr/local/lib/python3.7/site-packages/scout_apm/core/tracked_request.py", line 293, in capture_backtrace
 self.tag("stack", backtrace.capture_backtrace())
File "/usr/local/lib/python3.7/site-packages/scout_apm/core/backtrace.py", line 122, in capture_backtrace
 return list(itertools.islice(walker, LIMIT))
File "/usr/local/lib/python3.7/site-packages/scout_apm/core/backtrace.py", line 24, in filter_frames
 for frame in frames:
File "/usr/local/lib/python3.7/site-packages/scout_apm/core/backtrace.py", line 84, in backtrace_walker
 yield {"file": filepath(frame), "line": lineno, "function": name}
File "/usr/local/lib/python3.7/site-packages/scout_apm/core/backtrace.py", line 63, in filepath
 return module_filepath(module, filepath)
File "/usr/local/lib/python3.7/site-packages/scout_apm/core/backtrace.py", line 40, in module_filepath
 module_dir = root_module.__path__[0].rsplit(os.sep, 1)[0]
TypeError: '_NamespacePath' object is not subscriptable

updates:

• github.com/pre-commit/pre-commit-hooks: v4.1.0 → v4.4.0
• github.com/psf/black: 21.12b0 → 22.12.0
• github.com/pycqa/isort: 5.10.1 → 5.11.4
• github.com/PyCQA/flake8: 4.0.1 → 6.0.0
• github.com/mgedmin/check-manifest: 0.47 → 0.49

We're using a modified version of the Starlette middleware at the moment, primarily to support asyncio better.

Assuming asyncio support is added in future, there are a couple of other features we've added which it would be nice to see too:

• An optional list of routes to monitor which can be passed in.
  • Allows us to monitor the specific endpoints we want without health checks / documentation endpoints etc.
  • This can be accomplished manually, but I think being able to set it in config / on the middleware would be a nice addition
  • This requires getting the templated route name from the FastAPI router in our case, I think the same applies to Starlette.
• Request sampling
  • To reduce the number of events we send, I've added the ability to sample requests
  • i.e monitor 50% of requests.

If I've missed a better way / place to implement these, then please let me know.

Django (StreamingHttpResponse) and other frameworks support streaming HTTP responses. Currently our middleware-based instrumentation will not capture all the time sent streaming the response out, but instead prematurely close the TrackedRequest.

To correctly capture such responses we'd want to detect them and change behaviour to only close the TrackedRequest once their iteration has completed.

It seems feasible to trace the rendering of individual Jinja2 blocks. This could help users determine which parts of their templates are slow.

In our interception of Template.render(), we could iterate over the template's blocks attribute and somehow patch the blocks to be instrumented.

This test occasionally fails with an error on the line assert mock_send.call_count == 1 . The value is 3 rather than 1. Unfortunately I can't find any examples on GitHub Actions runs because I've hit "retry" on all of them, however whilst working yesterday I hit this flake on several runs.

I think the failure is due to the CoreAgentSocketThread continuing to run from a previous test, although the pytest fixture stop_and_empty_core_agent_socket should be stopping it between tests.