2

I am pulling my hair out over this. I'm developing a webapp in Django 1.3 (recently upgraded from 1.2.5 in a feeble hope that this might solve my error) and I've come across a bizzare bug in one of my views.

The view is called as an AJAX request from the client. If I call the view as a GET request, all is fine and dandy. If I call it as a POST request with no data, all is fine and dandy. But, if I call it as POST and actually include data (no matter what that data is) Django returns a blank page.

Being the kind to tinker, I discovered that I can print from my view and get output in the debug console, so I went to work, and discovered this strange oddity:

c = Character.objects.get(id=int(character))

This is the first line of code in that view that deals with a model. Printing shows that not only is character a sane value (it's the ID passed in by the request) but c is actually ending up with the correct database record. Regardless, if that line is called, Django's output for the request is zilch. Nada. Nothing.

If I return early before doing anything with my Models, Django correctly renders the rest of the request. Doing something with the Models causes a response 200 to be sent, but the content seems to be omitted.

This only seems to happen when POST data is sent, regardless of whether that post data is read or used in any way. I'm completely and utterly baffled by this. I'm going to post my code here and hope that someone here has some clue as to what black magic might be going on behind the scenes.

This is the view itself, which is called straight from urls.py:

@csrf_exempt
def ajax_update(request, character):
    #determine the timestamp to send the client *before* polling
    #the database

    update_time = int(time.time())

    #grab each update... thingy as json, and put it all together
    output = {
        "events": current_events(request, character, "default"),
        "character": character,
        "update_time": update_time,
    }

    return HttpResponse(json.dumps(output), mimetype = "application/json")

This is the current_events code, which contains the mentioned line:

def current_events(request, character, type = "default", timestamp = 0):
    '''
    purpose: grab the last 3 days worth of events, or the last 10 events,
    whichever is a larger list.
    '''

    #TODO: actually do something with timestamp
    c = Character.objects.get(id=int(character))

    #DEBUG: What on earth is going on here?
    print c

    #TODO: See if this can be optimized into a single query
    event_links = EventLink.objects.filter(viewer=c)
    events = Event.objects.filter(id__in=event_links.values('event')).order_by('timestamp')

    t = loader.get_template('ajax/world-events.html')

    output = []

    for event in events:
        revisions = Event.objects.filter(original_event=event.id).order_by('timestamp')

        display_message = event.message

        history = []
        if len(revisions):
            history.append(event) #first item in the history is the original event
            history.extend(revisions)   
            display_message = history[-1].message

        output.append({
            "id": event.id,
            "writer": event.writer.id,
            "type": event.type,
            "timestamp": int(time.mktime(event.timestamp.timetuple())),
            "message": t.render(RequestContext(request, {"event_text": display_message, "event": event, "history": history}))
        })

    return output

And finally, this is the CoffeeScript which calls the code, using jQuery, from the client:

auto_refresh_abort = 0
last_server_timestamp = 0
window.update_display = ->  
    #ajax call to grab events from the server
    $.ajax 
        type: 'POST'
        url: "/ajax/update/"+window.active_character
        data: 
            "last_update": last_server_timestamp
        dataType: "json"
        success: (output) ->
            auto_refresh_abort = 0
            update_character_log output.events
        error: (XMLHttpRequest, textStatus, errorThrown) ->
            auto_refresh_abort += 1
            console.log XMLHttpRequest

    return null

If you think it would help (this is a LOT already) I can post any other code samples needed, like the model code itself. I can confirm that the Character which is being looked up in my test cases does exist, and it's just a standard Django ID, I'm not doing anything weird with it.

Thanks in advance.

Update: As requested, here is a sample of what output should contain:

{'update_time': 1305984080, 'character': u'1', 'events': /*snip*/}

I've verified that code execution is making it all the way through, and that the output passed to HttpResponse does contain this data. For giggles, I inserted a return "TASTY" after the line where I poll Character, so that output's data should be:

{'update_time': 1305984080, 'character': u'1', 'events': 'TASTY'}

and confirmed that this is working. I can "print output" to the debug console right before HttpRequest and this is displayed.

If I comment out the line dealing with Character, my browser receives this data as the content of the request. Also, if I leave the code as-is and simply do not send POST data, the browser receives the correct data. The specific case where it fails is when I manipulate models after having sent in POST data from the client-- in this case the browser receives exactly the same HTTP headers, but no content. The headers that it receives are:

Content-Type:application/json
Date:Sat, 21 May 2011 13:29:38 GMT
Server:WSGIServer/0.1 Python/2.6

but no actual content is delivered.

Blank
  • 7,088
  • 12
  • 49
  • 69
  • Oh: I'm new to Django, but it's been mostly painless until this. I'm also ... well, not completely new, but not particularly experienced with Python, so I apologize if my style isn't perfect. I'm still learning the tricks. – Blank May 21 '11 at 12:03
  • Add "import pdb; pdb.set_trace()" as the first line in your view. That will start pdb (the debugger) in your console. You can use pdb to inspect your objects and go step by step. It's easier to track the problem that way than using print. :) – ibz May 21 '11 at 12:11
  • Not that it matters - but why do you do a POST when you don't even use the posted data? – ibz May 21 '11 at 12:14
  • I fully *intend* to use the POSTed data. I just happened to discover this strange error before I wrote that code. I wrote the clientside code first. The POST data is the client's most recent timestamp, which I'll use to omit changes that it should already have. – Blank May 21 '11 at 12:16
  • *sigh*. The only thing I figure is that something else is sending out the HTTP headers before HttpResponse has a chance to. That doesn't make very much sense though, because my browser *is* getting headers back and they have the application/json mimetype, which I set in ajax_update. Just... no content. I've verified that output contains valid data, and that json.dumps(output) is producing valid data. I'm just stumped as to why HttpResponse seems to eat it, and why it only does so after manipulating Models. – Blank May 21 '11 at 13:27

2 Answers2

1

This is going to be sort of an answer. It is rather a methodology so that you don't have this problem in the first place, but you can also use it to debug a problem if it happens.

  1. start out by creating your requests using curl or with the firefox REST client plugin:

  2. Then you write your response code returning hardcoded dummy object responses, covering a couple of cases (or all use cases). So your character and current_events functions return only "dummy" objects that you know are correct.

  3. You verify with the REST client (or with more formal testing) that the response works correctly.

  4. You write your clientside ajax code and verify it works with the dummy output.

  5. You refactor your dummy object calls into functions that call the objects themselves (you can shortly verifiy if they are returning objects in the way the should.

You can use this to effectively debug your program, otherwise, you are just guessing what part of your program is working and it can soooo easily fail in so many places.

ashwoods
  • 2,209
  • 1
  • 22
  • 36
  • While this is a nice idea in practice, the specific issue I'm having here wouldn't have been solved. I've already confirmed that everything is working with dummy objects-- specifically your step 5 is where I'm having issues. The database code itself seems to be causing the problem. – Blank May 21 '11 at 13:05
  • Printing and checking if it has sane values is not the same thing as working with dummy objects. Nothing in the post says you have used dummy objects. Paste an example of what json.dumps(output) should look like, and paste an example of what you are getting. (and confirm your code works with the example of json.dumps(output) that you are expecting. – ashwoods May 21 '11 at 13:26
  • That's just it-- I'm getting sane objects back. The exact output that is supposed to be there is *there*, HttpRequest just... eats it. I have no other way to explain it. The output is being generated correctly. Giving it dummy default values doesn't help-- I can verify that a plan string containing "dummy" will be sent to the browser as "". I'll see if I can reproduce the exact issue outside of my code if that helps. – Blank May 21 '11 at 13:43
  • and return HttpResponse(some_json_data, mimetype = "application/json") doesn't work either? In the paragraph above you said about "returning" early, does that also include returning early with non-model json data. If so, try the same view with something that returns text/html response using curl or rest-client – ashwoods May 21 '11 at 13:51
  • ...OK, more weirdness. I opened up Firefox to try to find this addon, and there's my properly parsed data staring at me. Curious, I opened up IE9 and got mixed results, about one in 4 times it updates correctly, all the rest do nothing. Super weird, but it's a hint. Something clearly up with the headers. I wonder if maybe this is a bug in the development server? I'll try hooking it up to Apache and see if that fixes it. I suppose a better question is whether or not Django's Database Model framework responds to HTTP headers-- if it does, that might be exactly where it's going south. – Blank May 21 '11 at 14:03
  • django's ORM has nothing to do with http at all. – ashwoods May 21 '11 at 14:21
  • Wow. Lo and behold, the bizzare bug disappears. – Blank May 21 '11 at 14:46
1

I think I may have found my issue. As soon as I hooked my app up to Apache and stopped using Django's development server, the bizzare bug disappeared. Responses are now always getting sent.

I still don't know if the cause is a bug in my own code, or if this is just a weird quirk of the development server, so I'm posting this answer in the hopes that if anyone else runs into a similar error during development, this might shine some light on the subject.

It seems that the development server is picky about what HTTP headers it does and doesn't like to accept for POST data. I'll edit this with more details if I can ever narrow down what exactly causes the issue, and in what circumstances. A temporary fix for me was to develop using Firefox, whose headers Django seems to like. The production environment under Apache isn't affected by this bug.

Blank
  • 7,088
  • 12
  • 49
  • 69
  • Thanks for reporting back. My issue was very similar to yours, only I could get responses to my POSTs in certain sections of my code but not others. Very weird. I was using nginx/uwsgi for my test environment but it started working when I moved to the Django development server. At least now I know where to start debugging. – freb Mar 08 '12 at 21:44
  • I figured out the problem to my specific issue with the help of this question: http://stackoverflow.com/questions/3970495/nginx-connection-reset-response-from-uwsgi-lost. The problem was the POST data wasn't being read. If you put request.POST to consume the POST data at the beginning of your view, does it solve your problem? I had to add "--pep3333-input" --post-buffering 4096" parameters to uwsgi to fix my environment. – freb Mar 08 '12 at 22:45