sometimes format=json requests return png's

[Dieterbe]

sometimes a /render request with format=json returns png data.
it seems to happen arbitrarily, sometimes it retuns the json data just fine, sometimes not. and it happens for different metrics.
screenshots of the request:
http://i.imgur.com/od7bL1I.png
screenshot of the response:
http://i.imgur.com/JXte4kb.png

note that all params are submitted via post instead of get, which is a little atypical, but I believe should not matter since graphite-web just gets the params irrespective of get/post. (https://github.com/graphite-project/graphite-web/blob/master/webapp/graphite/render/views.py#L220)

[davewongillies]

Adding a "me too" to this, thought I was going quietly insane. I'm seeing this on 0.9.12.

[jippi]

👍 ditto

[abhinav-upadhyay]

Is there any progress on this bug? For me this behavior doesn't seem to be arbitrary, it is happening for all the metrics, all the time.

[Dieterbe]

the other day i went over all commits from 0.9.10 to 0.9.12 but couldn't find what caused it. @abhinav-upadhyay is your graphite machine heavily loaded? (can you check iowait & cpu idle on your graphite machine). i wonder if the issues appears more often is a machine is heavily loaded.

[abhinav-upadhyay]

The cpu idle is between 60-80% and iowait is mostly 0-5%.

[brutasse]

@abhinav-upadhyay would you be able to provide a complete example of HTTP request that fails for you? Including headers, body (if any), params… everything.

[jippi]

I experience the same, my box is also idle without any disk io or activity worth anything. It's running on RAID 10 SSD with 16G of memory and 8 core Xeon 5

In my experience this happens randomly, and a simple refresh of the same request (with same headers etc) yield the correct result

The png response always says 'no data' while the json response have plenty of data - so wonder if it's a read / exception issue somewhere

They error usually happens at once in grafana, it's very rarely just one request that fails, but all of them at the same time. Could it be something with request/response workers or uwsgi throttle timeout that causes some default response to be sent to the client?

[brutasse]

Hah, it happened to me as well.

I tried replacing the gunicorn process with a straight django-admin.py runserver and I cannot reproduce the problem anymore. Switching back to gunicorn, getting mixed pngs/json again. Is everyone here using gunicorn? If so, please post versions / proxy info (nginx?). Try running it with runserver (only for trying this obviously), see if the problem disappears and please post some information about your web stack.

[jippi]

I use gunicorn too :)

I actually use uwsgi on the graphite server

-> uwsgi --version
1.2.3-debian

-> python --version
Python 2.7.3

-> nginx -v
nginx version: nginx/1.4.4

-> lsb_release -a
No LSB modules are available.
Distributor ID: Debian
Description:    Debian GNU/Linux 7.2 (wheezy)
Release:    7.2
Codename:   wheezy

-> cat /etc/nginx/sites-enabled/graphite.conf
server {
    listen 80 default_server;
    server_name _;
    rewrite ^ https://$host$request_uri? permanent;
}

# HTTPS server
server {
    listen 443 ssl spdy;
    server_name _;

    root /opt/graphite/webapp;

    # ssl
    ssl on;
    ssl_certificate /etc/nginx/ssl/STAR_bownty_net.crt;
    ssl_certificate_key /etc/nginx/ssl/STAR_bownty_net.key;
    ssl_session_timeout 5m;
    ssl_protocols SSLv3 TLSv1;
    ssl_ciphers ALL:!ADH:!EXPORT56:RC4+RSA:+HIGH:+MEDIUM:+LOW:+SSLv3:+EXP;
    ssl_prefer_server_ciphers on;

    # Django admin media.
    location /media/admin/ {
            alias /usr/share/pyshared/django/contrib/admin/static/admin/;
        }

        # Your project's static media.
        location /content/ {

        }

        # Finally, send all non-media requests to the Django server.
    location  / {
        add_header Access-Control-Allow-Origin "*";
        add_header Access-Control-Allow-Methods "GET, OPTIONS, POST, HEAD, PUT, DELETE";
        add_header Access-Control-Allow-Headers "X-Requested-With, X-Requested-By, Origin, Authorization, Accept, Content-Type, Pragma";
        add_header Access-Control-Allow-Credentials "true";

        include uwsgi_params;
        uwsgi_pass unix:/run/uwsgi/app/graphite/socket;
    }
}

-> cat /etc/uwsgi/apps-enabled/graphite.ini
[uwsgi]
plugins = python
chdir = /opt/graphite/conf
module = wsgi:application
uid = root
gid = root
chmod-socket = 777

[brutasse]

Correction, it seems to be a caching issue. I managed to reproduce the issue reliably :)

A workaround for now is to disable caching completely (django uses local memory by default). Add to local_settings.py:

CACHES = {
    'default': {
        'BACKEND': 'django.core.cache.backends.dummy.DummyCache',
    },
}

The issue most likely lies in the way graph cache keys are derived from incoming requests. I'll work on a fix for this but not until next week though.

[Dieterbe]

I run it in apache, I enabled your CACHES setting in /webapp/graphite/local_settings.py, now let's see whether I don't see the bug for a few days.

[rodriguezsergio]

I'm also running graphite on Apache and the addition to local_settings.py seems to have done the trick for me.

[brutasse]

I found something.

https://github.com/graphite-project/graphite-web/blob/master/webapp/graphite/render/hashing.py#L24

Change request.GET to request.REQUEST. POST parameters are basically ignored at the moment when computing the cache key. I don't know if request.REQUEST.lists() is a thing but that could be a start if anyone wants to try.

[adrienbrault]

Having the same issue

[rmca]

I'm an employee of Hosted Graphite. Some of our customers were affected by this issue, so we spent some time fixing it. We now have this fix in production for our customers. Additionally we have a pull request open with our fix.

@brutasse was correct, the hashRequest function was always choosing to hash the GET parameters, which means that requests of other method types would hash to the same cache key.

[rmca]

For those that are interested here's some code to reproduce this reliably: https://gist.github.com/rmca/5fc7feb596d7b4e579ff

[esc]

We can close this one soon, then I take it.

[esc]

#764 fixes this for 0.9.x and #765 for master

[esc]

Thanks for everyone who worked on this one!