POST request returns 200 response but does nothing in the handler

[Chris]

I have a handler which only handles POST requests, for which it logs at various stages of the request, and writes to db.

I noticed in the log today that a recent POST request to this handler returns a 200 response, didn't throw any exception but also didn't log anything. A quick check in the database for this request reveals that nothing is written there. How is this possible? 

The handler is like the following:

class MyHandler(tornado.web.RequestHandler):

    def post(self, arg1, arg2):

        var1 = self.get_argument('param1', None)

        var2 = self.get_argument('param2', None)

        var3 = self.get_argument('param3', None)

        ip = self.request.headers.get('X-Forwarded-For', self.request.remote_ip).split(',')[0]

        logger.info('[MyHandler] - request received from: %s' % ip)

        if blah blah blah:

            try:

                with self.application.sql:

                    # just update the session status based on mode

                    if var3 == 'a':

                        self.application.sql.execute('UPDATE MyTable SET fieldA=?, fieldB=? WHERE fieldC=? AND \

                            fieldD=?', (1,  int(var1), game, int(var2)))

                    elif var3 == 'b':

                        pass

                self.finish()

            except ValueError as e:

                logger.exception('[MyHandler] - casting error occurred when updating %s: %s' % (var1, e.args[0]))

                raise tornado.web.HTTPError(500)

            except sqlite.Error as e:

                logger.exception('[MyHandler] - SQLite error occurred when updating %s: %s' % (var1, e.args[0]))

                raise tornado.web.HTTPError(500)

        else:

            logger.warning('[MyHandler] - invalid request received: (%s, %s, %s)' % (var1, var2, var3))

            raise tornado.web.HTTPError(404)

And in the log, all I see is:

200 POST /handler/path/3d34b79f53e0cc821/1 (127.0.0.1) 0.49ms

So for example, why logger.info('[MyHandler] - request received from: %s' % ip) is not recorded in the log while the POST request returns 200?

[Lysander Trischler]

Hi Chris,

here some ideas.

> […]

> ip = self.request.headers.get('X-Forwarded-For',
> self.request.remote_ip).split(',')[0]

A note: If you pass xheaders=True to the Application constructor
self.request.remote_ip will have the X-Forwarded-For HTTP header set if
present. It also will check for X-Real-IP HTTP header. If there is none of the
two headers the socket's remote address is used instead.

> logger.info('[MyHandler] - request received from: %s' % ip)

What logger are you using? And is logging for INFO level configured or will
the logging mechanism only consider levels such as WARNING or ERROR?

> if blah blah blah:
> try:
> with self.application.sql:
> # just update the session status based on mode
> if var3 == 'a':
> self.application.sql.execute('UPDATE MyTable SET
> fieldA=?, fieldB=? WHERE fieldC=? AND \
> fieldD=?', (1, int(var1), game, int(var2)))
> elif var3 == 'b':

Maybe your code flow will take this path.


> pass

Or perhaps this one?


> self.finish()
>
> […]

>
> And in the log, all I see is:
>
> 200 POST /handler/path/3d34b79f53e0cc821/1 (127.0.0.1) 0.49ms
>
> So for example, why logger.info('[MyHandler] - request received from: %s' %
> ip) is not recorded in the log while the POST request returns 200?

Have you checked your routes setup? Maybe another registered handler matches
the regular expression for this URL and your expected handler gets not used.
This is a common mistake as the order of adding the URL specs matters.

Regards,
Lyse

[Chris]

Hi Lyse,

Thanks a lot for all the suggestions.

I am seeing all the other INFO level logging msgs for the same tornado process, so the logger itself should be OK. I am also sure of the code path and the routes setup, as I've double-checked. In fact, the same handler has worked correctly before. Some more background info - I'm POSTing to this handler from another tornado process running on the same server like this:

response = yield tornado.gen.Task(client.fetch, ''.join(('http://127.0.0.1:8080/handler/path/', var_arg1, '/', var_arg2)), method='POST', body=urlencode({'param1': 'blahblahblah', 'param2': 'blah', 'param3': 'blah'}), connect_timeout=3.0)

if response.error:

    logger.warn('[MyClass] - update failed for %s' % self.my_session)

On the same server, I'm running all my tornado processes behind Nginx, but I think in this case that shouldn't matter because I'm calling from one tornado process directly to another. The fact that I'm seeing 200 POST /handler/path/3d34b79f53e0cc821/1 (127.0.0.1) 0.49ms in the log for the particular process where the problematic handler lies also suggests that at least the request is correctly routed.

Is there any other possible reason(s) that will make the handler almost immediately returns a 200 response for a POST request, but without doing what lies inside its post method? I'm puzzled.

[L-R]

I had an issue yesterday with multiple Tornado instances running behind nginx - all of them would, on one particular request, return a 200 OK but gave an empty response. It was actually a permission issue with some files of nginx. I'd suggest checking the error log (/var/log/nginx/error.log) while you make the request, just to see if it's related. 

[Ben Darnell]

On Tue, Apr 9, 2013 at 6:55 PM, Chris <bhp...@gmail.com> wrote:

Is there any other possible reason(s) that will make the handler almost immediately returns a 200 response for a POST request, but without doing what lies inside its post method? I'm puzzled.

If the post method contains a "yield" expression (even if that expression is never reached) but does not have one of the @gen.coroutine or @gen.engine decorators, this will happen.

-Ben

 

--
You received this message because you are subscribed to the Google Groups "Tornado Web Server" group.
To unsubscribe from this group and stop receiving emails from it, send an email to python-tornad...@googlegroups.com.
For more options, visit https://groups.google.com/groups/opt_out.
 
 

[Chris]

That's it!! But why?

[Ben Darnell]

This is just how generators work.  When a function contains "yield", it becomes a generator instead of a regular function.  A generator is really a kind of iterator factory: each time it's called, a new iterator is created.  As that iterator advances, the function is run one yield step at a time.  If nothing receives the iterator and iterates over it, the code in the function never actually gets run.

-Ben