Log exceptions

[kirillk77]

Fixes #22

[Dieterbe]

seems to work, minus some quoting issues
on exception i get a log msg like:

{"exception": "AttributeError(\"'NoneType' object has no attribute 'step'\",)", "event": "Exception"}

would be great if we could log the stack trace as well though

[Dieterbe]

here's how to also print stacktrace:

~/w/e/graphite-api ❯❯❯ git diff
diff --git a/graphite_api/config.py b/graphite_api/config.py
index 40e7c66..40f2482 100644
--- a/graphite_api/config.py
+++ b/graphite_api/config.py
@@ -1,8 +1,10 @@
 import logging
 import os
 import structlog
+import sys
 import warnings
 import yaml
+import traceback

 from tzlocal import get_localzone
 from importlib import import_module
@@ -76,6 +78,10 @@ def load_by_path(path):

 def log_exception(sender, exception, **extra):
     logger.error('Exception', exception=exception)
+    exc_info = sys.exc_info()
+    tb = traceback.format_exception(*exc_info)
+    for line in tb:
+        logger.error(line)


 def configure(app):

output:

{"exception": "AttributeError(\"'NoneType' object has no attribute 'step'\",)", "event": "Exception"}
{"event": "Traceback (most recent call last):\n"}
{"event": "  File \"/usr/local/lib/python2.7/dist-packages/flask/app.py\", line 1817, in wsgi_app\n    response = self.full_dispatch_request()\n"}
{"event": "  File \"/usr/local/lib/python2.7/dist-packages/flask/app.py\", line 1477, in full_dispatch_request\n    rv = self.handle_user_exception(e)\n"}
{"event": "  File \"/usr/local/lib/python2.7/dist-packages/newrelic-2.40.0.34/newrelic/hooks/framework_flask.py\", line 86, in _nr_wrapper_Flask_handle_exception_\n    return wrapped(*args, **kwargs)\n"}
{"event": "  File \"/usr/local/lib/python2.7/dist-packages/flask/app.py\", line 1381, in handle_user_exception\n    reraise(exc_type, exc_value, tb)\n"}
{"event": "  File \"/usr/local/lib/python2.7/dist-packages/flask/app.py\", line 1475, in full_dispatch_request\n    rv = self.dispatch_request()\n"}
{"event": "  File \"/usr/local/lib/python2.7/dist-packages/flask/app.py\", line 1461, in dispatch_request\n    return self.view_functions[rule.endpoint](**req.view_args)\n"}
{"event": "  File \"/usr/local/lib/python2.7/dist-packages/newrelic-2.40.0.34/newrelic/hooks/framework_flask.py\", line 30, in _nr_wrapper_handler_\n    return wrapped(*args, **kwargs)\n"}
{"event": "  File \"/usr/local/lib/python2.7/dist-packages/graphite_api/app.py\", line 394, in render\n    series_list = evaluateTarget(context, target)\n"}
{"event": "  File \"/usr/local/lib/python2.7/dist-packages/graphite_api/app.py\", line 470, in evaluateTarget\n    result = evaluateTokens(requestContext, tokens)\n"}
{"event": "  File \"/usr/local/lib/python2.7/dist-packages/graphite_api/app.py\", line 480, in evaluateTokens\n    return evaluateTokens(requestContext, tokens.expression)\n"}
{"event": "  File \"/usr/local/lib/python2.7/dist-packages/graphite_api/app.py\", line 488, in evaluateTokens\n    arg) for arg in tokens.call.args]\n"}
{"event": "  File \"/usr/local/lib/python2.7/dist-packages/graphite_api/app.py\", line 480, in evaluateTokens\n    return evaluateTokens(requestContext, tokens.expression)\n"}
{"event": "  File \"/usr/local/lib/python2.7/dist-packages/graphite_api/app.py\", line 488, in evaluateTokens\n    arg) for arg in tokens.call.args]\n"}
{"event": "  File \"/usr/local/lib/python2.7/dist-packages/graphite_api/app.py\", line 480, in evaluateTokens\n    return evaluateTokens(requestContext, tokens.expression)\n"}
{"event": "  File \"/usr/local/lib/python2.7/dist-packages/graphite_api/app.py\", line 492, in evaluateTokens\n    return func(requestContext, *args, **kwargs)\n"}
{"event": "  File \"/usr/local/lib/python2.7/dist-packages/graphite_api/functions.py\", line 867, in movingAverage\n    seconds=bootstrapSeconds)\n"}
{"event": "  File \"/usr/local/lib/python2.7/dist-packages/graphite_api/functions.py\", line 2024, in _fetchWithBootstrap\n    if bootstrap.step != original.step:\n"}
{"event": "AttributeError: 'NoneType' object has no attribute 'step'\n"}

[mahmoudimus]

+1

[jtyr]

This patch is definitely needed. Please merge it ASAP.

[brutasse]

Actually since dfa272e exceptions should already be logged. Is any of you using a custom logging configuration? If so, can I see it?

[jtyr]

There is still missing the stacktrace patch from @Dieterbe . @Dieterbe please could you create a PR for that?

[brutasse]

Actually just passing exc_info=True to the logger.error call is enough.

@jtyr can I have your logging config? I see exceptions properly logged without this patch applied.

[jtyr]

I'm using this patch for logging:

diff -u -r ./a/graphite_api/config.py ./b/graphite_api/config.py
--- ./a/graphite_api/config.py  2014-12-04 02:15:52.000000000 -0600
+++ ./b/graphite_api/config.py  2015-01-06 09:46:44.690078253 -0600
@@ -1,8 +1,10 @@
 import logging
 import os
 import structlog
+import sys
 import warnings
 import yaml
+import traceback

 from tzlocal import get_localzone
 from importlib import import_module
@@ -13,6 +15,7 @@
 from .search import IndexSearcher
 from .storage import Store
 from . import DEBUG
+from flask.signals import got_request_exception

 try:
     from logging.config import dictConfig
@@ -73,6 +76,13 @@
     return getattr(finder, klass)


+def log_exception(sender, exception, **extra):
+    logger.error('Exception', exception=exception)
+    exc_info = sys.exc_info()
+    tb = traceback.format_exception(*exc_info)
+    for line in tb:
+        logger.error(line)
+
 def configure(app):
     config_file = os.environ.get('GRAPHITE_API_CONFIG',
                                  '/etc/graphite-api.yaml')
@@ -87,6 +97,8 @@

     configure_logging(config)

+    got_request_exception.connect(log_exception, app)
+
     for key, value in list(default_conf.items()):
         config.setdefault(key, value)

diff -u -r ./a/setup.py ./b/setup.py
--- ./a/setup.py    2014-12-04 02:15:52.000000000 -0600
+++ ./b/setup.py    2015-01-06 09:45:40.219074840 -0600
@@ -12,6 +12,7 @@
     'six',
     'structlog',
     'tzlocal',
+    'blinker',
 ]

 if sys.version_info < (2, 7):

Apart of this patch, I'm using no extra logging setting.

[brutasse]

I just reverted the merge. From a clean install from master, I'd be interested to see a case where exceptions are not logged.

[kirillk77]

I think you have confused exceptions and their stacktraces. My PR adds logging exceptions, and @Dieterbe's PR adds logging exceptions with stacktraces.

[brutasse]

No, I am already seeing exceptions with stacktraces in my logs. This has been the case since dfa272e.

[jtyr]

Well, I did not see any exceptions in the log (stdout from gunicorn - see https://github.com/picotrading/ansible-graphite_api/blob/master/contrib/graphite-api.sh#L25) without the patch I sent above when I was testing it like 2 months ago. So I'm sure the functionality provided by the commit dfa272e did not work for me.

[brutasse]

The issue is, I'm unable to reproduce a setup that hides exceptions… I'd love to see this issue happen in a reproduceable way.

[jtyr]

If you want to make the exception logging optional, you should allow to set the logging level. The exceptions are logged only in the "error" log level. Or change the log level for exception to "debug".

[Dieterbe]

@brutasse can you share your config? i've been trying master with various config settings (debug vs warn, propagate true vs false, disable_existing_loggers true/false, version 1 or removing the line, with and without sentry_dsn line, templates/cache/statsd settings on/of, etc) and every time i request /render?width=aoeu&target=foo i get an http 500 but no exception in log (stdout)
in fact nothing appears in the log :(

i run like so:
gunicorn -b 0.0.0.0:8000 -w 24 --log-level debug graphite_api.app:app

root@e85f1b2d1687:~# cat /etc/graphite-api.yaml 
search_index: /srv/graphite/index
functions:
  - graphite_api.functions.SeriesFunctions
  - graphite_api.functions.PieFunctions

whisper:
  directories:
    - /srv/graphite/whisper
time_zone: America/New_York
logging:
  handlers:
    file:
      class: logging.FileHandler
      filename: /var/log/graphite-api.log
    stdout:
      class: logging.StreamHandler
  loggers:
    graphite_api:
      handlers:
        - stdout
      propagate: false
      level: DEBUG
    root:
      handlers:
        - stdout
      propagate: false
      level: DEBUG

[Dieterbe]

since Bruno commented higher up Is any of you using a custom logging configuration? If so, can I see it? i took out all logging config, and have it like:

search_index: /srv/graphite/index
functions:
  - graphite_api.functions.SeriesFunctions
  - graphite_api.functions.PieFunctions

whisper:
  directories:
    - /srv/graphite/whisper
time_zone: America/New_York

same result, http 500 but no exception

[jtyr]

I run gunicorn like this:

gunicorn graphite_api.app:app -b ${BIND_ADDRESS:-127.0.0.1}:${PORT:-8888} $GUNICORN_OPTIONS 1>/var/log/$NAME.log 2>&1 &

So basically redirect the STDOUT/STDERR into a file.

And my graphite-api.yaml looks like this:

allowed_origins:
  - "*"
cache:
  dir: "/tmp/graphite-api-cache"
  type: "filesystem"
finders:
  - "graphite_influxdb.InfluxdbFinder"
functions:
  - "graphite_api.functions.SeriesFunctions"
  - "graphite_api.functions.PieFunctions"
influxdb:
  db: "graphite"
  host: "192.168.56.104"
  pass: "root"
  port: 8086
  schema:
    -
      - ""
      - 10
    -
      - "high-res-metrics"
      - 1
  user: "root"
search_index: "/var/lib/graphite-api/index"
time_zone: "US/Central"

[jtyr]

Any further comments on this issue? Any example how to setup logging which would show exceptions with stacktrace? It only works for me when using the above patch (#73 (comment)).