Торнадо загадочно зависает после асинхронной операции - как мне отладить? - PullRequest
2 голосов
/ 25 января 2012

Наше приложение использует довольно мало сетевых вызовов (оно основано на стороннем REST API), поэтому мы используем множество асинхронных операций, чтобы система реагировала. (Использование Swirl, чтобы оставаться в здравом уме, поскольку приложение было написано до появления tornado.gen). Поэтому, когда возникла необходимость в небольшом геокодировании, мы подумали, что это будет тривиально - добавьте пару асинхронных вызовов к другому внешнему API, и мы будем великолепны.

Каким-то образом наш асинхронный код загадочным образом зависает в Tornado - процесс все еще выполняется, но он не будет отвечать на запросы и ничего выводить в журналы. Хуже того, когда мы извлекаем сторонний сервер из уравнения полностью, он все еще зависает - кажется, он блокирует некоторый произвольный период после возвращения асинхронного запроса.

Вот код заглушки, который повторяет проблему:

def async_geocode(lat, lon, callback, fields=('city', 'country')):
    '''Translates lat and lon into human-readable geographic info'''
    iol = IOLoop.instance()
    iol.add_timeout(time.time() + 1, lambda: callback("(unknown)"))

И вот тест, который обычно (но не всегда - именно так он и поступил в производство в первую очередь) ловит его:

class UtilTest(tornado.testing.AsyncTestCase):

    def get_new_ioloop(self):
        '''Ensure that any test code uses the right IOLoop, since the code
        it tests will use the singleton.'''
        return tornado.ioloop.IOLoop.instance()

    def test_async_geocode(self):
        # Yahoo gives (-122.419644, 37.777125) for SF, so we expect it to
        # reverse geocode to SF too...
        async_geocode(lat=37.777, lon=-122.419, callback=self.stop,
                      fields=('city', 'country'))
        result = self.wait(timeout=4)
        self.assertEquals(result, u"San Francisco, United States")
        # Now test if it's hanging (or has hung) the IOLoop on finding London
        async_geocode(lat=51.506, lon=-0.127, callback=self.stop,
                      fields=('city',))
        result = self.wait(timeout=5)
        self.assertEquals(result, u"London")
        # Test it fails gracefully
        async_geocode(lat=0.00, lon=0.00, callback=self.stop,
                      fields=('city',))
        result = self.wait(timeout=6)
        self.assertEquals(result, u"(unknown)")

    def test_async_geocode2(self):
        async_geocode(lat=37.777, lon=-122.419, callback=self.stop,
                      fields=('city', 'state', 'country'))
        result = self.wait(timeout=7)
        self.assertEquals(result, u"San Francisco, California, United States")
        async_geocode(lat=51.506325, lon=-0.127144, callback=self.stop,
                      fields=('city', 'state', 'country'))
        result = self.wait(timeout=8)
        self.io_loop.add_timeout(time.time() + 8, lambda: self.stop(True))
        still_running = self.wait(timeout=9)
        self.assert_(still_running)

Обратите внимание, что первый тест почти всегда проходит, а второй тест (и его вызов async_geocode) обычно не выполняется.

Отредактировано, чтобы добавить: Обратите также внимание, что у нас есть много аналогично асинхронных вызовов нашего другого стороннего API, которые работают абсолютно нормально.

(Для полноты вот полная реализация async_geocode и его вспомогательного класса (хотя заглушка выше повторяет проблему)):

def async_geocode(lat, lon, callback, fields=('city', 'country')):
    '''Use AsyncGeocoder to do the work.'''
    geo = AsyncGeocoder(lat, lon, callback, fields)
    geo.geocode()


class AsyncGeocoder(object):
    '''
    Reverse-geocode to as specific a level as possible

    Calls Yahoo! PlaceFinder for reverse geocoding. Takes a lat, lon, and
    callback function (to call with the result string when the request
    completes), and optionally a sequence of fields to return, in decreasing
    order of specificity (e.g. street, neighborhood, city, country)

    NB: Does not do anything intelligent with the geocoded data -- just returns
    the first result found.
    '''

    url = "http://where.yahooapis.com/geocode"

    def __init__(self, lat, lon, callback, fields, ioloop=None):
        self.lat, self.lon = lat, lon
        self.callback = callback
        self.fields = fields
        self.io_loop = ioloop or IOLoop.instance()
        self._client = AsyncHTTPClient(io_loop=self.io_loop)

    def geocode(self):
        params = urllib.urlencode({
            'q': '{0}, {1}'.format(self.lat, self.lon),
            'flags': 'J', 'gflags': 'R'
        })

        tgt_url = self.url + "?" + params
        self._client.fetch(tgt_url, self.geocode_cb)

    def geocode_cb(self, response):
        geodata = json_decode(response.body)
        try:
            geodata = geodata['ResultSet']['Results'][0]
        except IndexError:
            # Response didn't contain anything
            result_string = ""
        else:
            results = []
            for f in self.fields:
                val = geodata.get(f, None)
                if val:
                    results.append(val)
            result_string = ", ".join(results)

        if result_string == '':
            # This can happen if the response was empty _or_ if 
            # the requested fields weren't in it. Regardless, 
            # the user needs to see *something*
            result_string = "(unknown)"

        self.io_loop.add_callback(lambda: self.callback(result_string))

Редактировать : Итак, после довольно утомительной отладки и регистрации ситуаций, в которых система отказывает в течение нескольких дней, оказывается, что, как указывает принятый ответ, мой тест не удался для несвязанные причины. Также выясняется, что причина, по которой он зависал, была не связана с IOLoop, а скорее с тем, что одна из сопрограмм немедленно зависла в ожидании блокировки базы данных.

Извините за неверно заданный вопрос, и спасибо всем за терпение.

1 Ответ

3 голосов
/ 27 января 2012

Похоже, что ваш второй тест не прошел из-за этой части:

self.io_loop.add_timeout(time.time() + 8, lambda: self.stop(True))
still_running = self.wait(timeout=9)
self.assert_(still_running)

, когда вы добавляете тайм-аут в IOLoop через self.wait, этот тайм-аут не очищается, когда вызывается self.stopкак я могу сказать.То есть ваш первый тайм-аут сохраняется, и когда вы спите IOLoop в течение 8 секунд, он срабатывает.

Я сомневаюсь, что что-либо из этого связано с вашей первоначальной проблемой.

Добро пожаловать на сайт PullRequest, где вы можете задавать вопросы и получать ответы от других членов сообщества.
...