Twisted Klein: Synchronous behavior

Question

I am using Twisted Klein because one of the promise of the framework is it is Asynchronous, but i tested that app i develop and a little code for testing and the framework behavior seems to be synchronous.

The test server code is:

# -*- encoding: utf-8 -*-
import json
import time
from datetime import datetime

from klein import Klein

app = Klein()

def setHeader(request, content_type):

    request.setHeader('Access-Control-Allow-Origin', '*')
    request.setHeader('Access-Control-Allow-Methods', 'GET')
    request.setHeader('Access-Control-Allow-Headers', 'x-prototype-version,x-requested-with')
    request.setHeader('Access-Control-Max-Age', 2520)
    request.setHeader('Content-type', content_type)


def cleanParams(params):

    for key in params.keys():

        param = params[key]
        params[key] = param[0]

    return params


@app.route('/test/', methods=["GET"])
def test(request):

    setHeader(request,'application/json')

    time.sleep(5)

    return json.dumps([str(datetime.now())])

if __name__ == "__main__":
    app.run(host='0.0.0.0',port=12030)

And the request for testing is:

# -*- encoding: utf-8 -*-
import requests
from datetime import datetime

if __name__ == "__main__":

    url = "http://192.168.50.205:12030"

    params = {
    }

    print datetime.now()
    for i in xrange(6):
        result = requests.get(url + "/test/", params)

        print datetime.now(), result.json()

With the server up, if i run the second code alone:

2016-07-19 12:50:53.530000
2016-07-19 12:50:58.570000 [u'2016-07-19 12:50:58.548000']
2016-07-19 12:51:03.604000 [u'2016-07-19 12:51:03.589000']
2016-07-19 12:51:08.634000 [u'2016-07-19 12:51:08.625000']
2016-07-19 12:51:13.670000 [u'2016-07-19 12:51:13.654000']
2016-07-19 12:51:18.717000 [u'2016-07-19 12:51:18.708000']
2016-07-19 12:51:23.764000 [u'2016-07-19 12:51:23.748000']

Perfect, but if i run at the same time two instances:

Instance 1:

2016-07-19 12:53:05.025000
2016-07-19 12:53:10.057000 [u'2016-07-19 12:53:10.042000']
2016-07-19 12:53:20.113000 [u'2016-07-19 12:53:20.097000']
2016-07-19 12:53:30.181000 [u'2016-07-19 12:53:30.166000']
2016-07-19 12:53:40.236000 [u'2016-07-19 12:53:40.219000']
2016-07-19 12:53:50.316000 [u'2016-07-19 12:53:50.294000']
2016-07-19 12:54:00.381000 [u'2016-07-19 12:54:00.366000']

Instance 2:

2016-07-19 12:53:05.282000
2016-07-19 12:53:15.074000 [u'2016-07-19 12:53:15.059000']
2016-07-19 12:53:25.141000 [u'2016-07-19 12:53:25.125000']
2016-07-19 12:53:35.214000 [u'2016-07-19 12:53:35.210000']
2016-07-19 12:53:45.270000 [u'2016-07-19 12:53:45.255000']
2016-07-19 12:53:55.362000 [u'2016-07-19 12:53:55.346000']
2016-07-19 12:54:05.402000 [u'2016-07-19 12:54:05.387000']

And the server output:

2016-07-19 12:53:10-0400 [-] "192.168.50.205" - - [19/Jul/2016:16:53:04 +0000] "GET /test/ HTTP/1.1" 200 30 "-" "python-requests/2.9.1"
2016-07-19 12:53:15-0400 [-] "192.168.50.205" - - [19/Jul/2016:16:53:10 +0000] "GET /test/ HTTP/1.1" 200 30 "-" "python-requests/2.9.1"
2016-07-19 12:53:20-0400 [-] "192.168.50.205" - - [19/Jul/2016:16:53:15 +0000] "GET /test/ HTTP/1.1" 200 30 "-" "python-requests/2.9.1"
2016-07-19 12:53:25-0400 [-] "192.168.50.205" - - [19/Jul/2016:16:53:20 +0000] "GET /test/ HTTP/1.1" 200 30 "-" "python-requests/2.9.1"
2016-07-19 12:53:30-0400 [-] "192.168.50.205" - - [19/Jul/2016:16:53:25 +0000] "GET /test/ HTTP/1.1" 200 30 "-" "python-requests/2.9.1"
2016-07-19 12:53:35-0400 [-] "192.168.50.205" - - [19/Jul/2016:16:53:30 +0000] "GET /test/ HTTP/1.1" 200 30 "-" "python-requests/2.9.1"
2016-07-19 12:53:40-0400 [-] "192.168.50.205" - - [19/Jul/2016:16:53:35 +0000] "GET /test/ HTTP/1.1" 200 30 "-" "python-requests/2.9.1"
2016-07-19 12:53:45-0400 [-] "192.168.50.205" - - [19/Jul/2016:16:53:40 +0000] "GET /test/ HTTP/1.1" 200 30 "-" "python-requests/2.9.1"
2016-07-19 12:53:50-0400 [-] "192.168.50.205" - - [19/Jul/2016:16:53:45 +0000] "GET /test/ HTTP/1.1" 200 30 "-" "python-requests/2.9.1"
2016-07-19 12:53:55-0400 [-] "192.168.50.205" - - [19/Jul/2016:16:53:50 +0000] "GET /test/ HTTP/1.1" 200 30 "-" "python-requests/2.9.1"
2016-07-19 12:54:00-0400 [-] "192.168.50.205" - - [19/Jul/2016:16:53:55 +0000] "GET /test/ HTTP/1.1" 200 30 "-" "python-requests/2.9.1"
2016-07-19 12:54:05-0400 [-] "192.168.50.205" - - [19/Jul/2016:16:54:00 +0000] "GET /test/ HTTP/1.1" 200 30 "-" "python-requests/2.9.1"

As you can see, the server is blocking the current execution and it seems to be working in synchronous instead asynchronous.

What i am missing?

Best Regards.

Answer 1

You're missing many significant concepts of Twisted. In regards to synchronous behavior, you're absolutely correct, Klein behaves like synchronous frameworks, like Flask or Bottle, if you don't explicitly use async functions (ie. Deferreds). In your example, you're not using any asynchronous functionality so you're code executes sequentially. Check out https://github.com/notoriousno/klein-basics/blob/intro/nonblocking.rst this should help you understand the basics of async in Klein and Twisted. As a reminder to readers Deferreds don't make your code magically async! You must design carefully to achieve concurrent execution.

Making your code async

Lets try to make fix your code so that it runs asynchronously. I'll go over the concepts in sections. If more information is needed, please comment and I'll address it. Let's start with the imports required:

from klein import Klein
from twisted.internet import defer, reactor

setHeader()

Next let's look to change the setHeader() function. The request.setHeader function is rather fast so it can be run multiple times without severe blocking. Therefore, a function that generates a Deferred object with callbacks that will set the various header key/value pairs can be used:

def setHeader(request, content_type):

    def _setHeader(previous_result, header, value):
        request.setHeader(header, value)

    d = defer.Deferred()
    d.addCallback(_setHeader, 'Access-Control-Allow-Origin', '*')
    d.addCallback(_setHeader, 'Access-Control-Allow-Methods', 'GET')
    d.addCallback(_setHeader, 'Access-Control-Allow-Headers', 'x-prototype-version,x-requested-with')
    d.addCallback(_setHeader, 'Access-Control-Max-Age', '2520')
    d.addCallback(_setHeader, 'Content-type', content_type)
    return d

Without going into great detail, we're using Deferred.addCallback() to chain callbacks together. In this case, the callback function is the local _setHeader() and it simply sets the header. Finally, the function will return the Deferred. If you noticed, the _setHeader() takes an argument previous_result, let's ignore them for now.

cleanParams()

If a loop is being used (for or while) it's generally best to use inlineCallbacks to yield results. Using this method allows you to run things in a synchronous fashion without blocking the main ioloop.

@defer.inlineCallbacks
def cleanParams(params):
    for key in sorted(params):
        param = params[key]
        params[key] = yield param[0]

    defer.returnValue(str(params))    # if py3 then use ``return params``

This is kind of a bad example, but it should illustrate how to use yield to wait for a value. As a side note, the setHeader() function could've also used inlineCallbacks and yields. I wanted to demonstrate multiple async styles.

Klein Routes

Finally, lets actually use the async functions in the routes:

app = Klein()

@app.route('/test/', methods=["GET"])
def test(request):
    asyncClean = cleanParams(request.args)
    asyncClean.addCallback(request.write)

    asyncSetHeader = setHeader(request,'application/json')
    reactor.callLater(5, asyncSetHeader.callback, None)

    def render(results, req):
        req.write(json.dumps([str(datetime.now())]))

    finalResults = defer.gatherResults([asyncClean, asyncSetHeader])
    finalResults.addCallback(render, request)
    return finalResults

DON'T FREAK OUT! First we call cleanParams() which returns a Deferred and when it finishes, the returnValue will be written to the response body. Next the headers will be set via our setHeader() which explicitly returns a Deferred. You were using time.sleep(5) and you inadvertently were blocking the entire reactor loop. In Klein/Twisted, you generally would use callLater() if you want to do something at a later time. Finally we wait for the results from the deferreds asyncClean and asyncSetHeader via gatherResults() and write the timestamp to the response body.

Final Code

server.py

import json
from datetime import datetime

from klein import Klein
from twisted.internet import defer, reactor


app = Klein()

def setHeader(request, content_type):

    def _setHeader(previous_result, header, value):
        request.setHeader(header, value)

    d = defer.Deferred()
    d.addCallback(_setHeader, 'Access-Control-Allow-Origin', '*')
    d.addCallback(_setHeader, 'Access-Control-Allow-Methods', 'GET')
    d.addCallback(_setHeader, 'Access-Control-Allow-Headers', 'x-prototype-version,x-requested-with')
    d.addCallback(_setHeader, 'Access-Control-Max-Age', '2520')
    d.addCallback(_setHeader, 'Content-type', content_type)
    return d


@defer.inlineCallbacks
def cleanParams(params):
    for key in sorted(params):
        param = params[key]
        params[key] = yield param[0]

    defer.returnValue(str(params))


@app.route('/test/', methods=["GET"])
def test(request):
    asyncClean = cleanParams(request.args)
    asyncClean.addCallback(request.write)       # write the result from cleanParams() to the response

    asyncSetHeader = setHeader(request,'application/json')
    reactor.callLater(5, asyncSetHeader.callback, None)

    def render(results, req):
        req.write(json.dumps([str(datetime.now())]))

    finalResults = defer.gatherResults([asyncClean, asyncSetHeader])
    finalResults.addCallback(render, request)
    return finalResults

if __name__ == "__main__":
    app.run(host='0.0.0.0',port=12030)

test.sh

curl -v -X GET http://localhost:12030/test/?hello=world\&foo=bar\&fizz=buzz