Нерегулярные ошибки в импортах

Сегодня я поделюсь очередной болью в поддержке проекта на 0.7 милионов строчек кода на Python'е. Кажется, с этим багом в разных формах мы сталкиваемся уже несколько лет, и он приводит в совершенное замешательство даже опытных разработчиков.

Собственно ошибка

Симптомы бага просты: вылетает ошибка в иморте:

  File "/app/forms/some_form.py", line 9, in <module>
    from app.forms import form_util
ImportError: cannot import name form_util  

(т.к. это публичный блог, реальные имена модулей скрыты; для внутренних нужд есть PR-34989)

Конечно же при этом:

  1. Модуль совершенно спокойно импортится вручную
  2. Ошибка возникает не регулярно, возможно только в некоторых контейнерах, в некоторых сборках, и только в правильной фазе луны
  3. В самом модуле нет ничего от чего бы он мог перестать работать

Предпосылки

Нужно дать некоторые пояснения. Конкретно на этом проекте используется pylons, и у него есть одно очень сомнительное свойство: он импортирует модули в момент обработки клиентского HTTP-запроса, вместо того чтобы импортить их при старте. Этот факт важно понимать для дальнейшего расследования, но в остальном мы не будем тут обсужать правильно это или нет.

Что происходит?

Оказывается вплоть до python'а 3.5 питон не умел правильно обрабатывать ошибки при импорте, если этот иморт происходит из __init__.py. Чтобы было понятно, давайте покажем пример. Пусть у нас есть пакет, который импортирует два других модуля в __init__.py:

# package/__init__.py
from package import form_util  
from package import bad_module  

В form_util мы ничего особенного не будем делать, только положим переменную loaded чтобы проверить, что он нормально загрузился:

# package/form_util.py
loaded = True  

А вот bad_module будет случайным образом производить ошибку:

# package/bad_module.py
import random  
1 / random.randrange(2)  # деление на 0 каждый второй раз!  

Ну и давайте попробуем эту штуку проимпортировать:

# run.py
from package import form_util  
assert form_util.loaded  

Запускаем несколько раз, чтобы посмотреть что получится:

> python3 run.py
loaded True  
> python3 run.py
Traceback (most recent call last):  
  File "run.py", line 1, in <module>
    from package import form_util
  File "/work/package/__init__.py", line 2, in <module>
    from package import bad_module
  File "/work/package/bad_module.py", line 2, in <module>
    1 / random.randrange(2)
ZeroDivisionError: division by zero  

Пока всё ожидаемо.

Но теперь вспомним про pylons. Он делает импорт в обработчике запроса, а значит если импорт не прошел, то вместо того, чтобы остановить приложение, pylons перехватывает ошибку и отправляет ответ 500 Internal Server Error. Давайте это повторим:

# run.py
for i in range(5):  
    try:
        from package import form_util
        print("loaded", form_util.loaded)
    except Exception as e:
        print("exception", e)

Ну и теперь запускаем любым Python'ом версии 3.4 и ниже:

> python3 run.py
exception division by zero  
exception cannot import name 'form_util'  
exception cannot import name 'form_util'  
exception cannot import name 'form_util'  
exception cannot import name 'form_util'  

Давайте еще добавим traceback.print_exc() и посмотрим на первые две ошибки:

Traceback (most recent call last):  
  File "run.py", line 4, in <module>
    from package import form_util
  File "/work/package/__init__.py", line 2, in <module>
    from package import bad_module
  File "/work/package/bad_module.py", line 2, in <module>
    1/random.randrange(2)
ZeroDivisionError: division by zero  
exception division by zero  
Traceback (most recent call last):  
  File "run.py", line 4, in <module>
    from package import form_util
  File "/work/package/__init__.py", line 1, in <module>
    from package import form_util
ImportError: cannot import name 'form_util'  
exception cannot import name 'form_util'  

Обратите внимание, в двух логах приведенных выше, на следующее:

  1. Первая ошибка была в bad_module, и она указывает на точное место
  2. Последующие ошибки с импортом form_util, при этом в чем конкретно ошибка -- не понятно
  3. Ошибки с form_util повторяются всё время после первого поломанного импорта

Внутренности этой ошибки

Чтобы точнее понять в чём проблема, давайте посмотрим на sys.modules (фильтруем только нужные нам пакеты):

print([k for k in sys.modules if k.startswith('package')])  

В случае успешного импорта:

['package.bad_module', 'package.form_util', 'package']

В случае ошибки в импорте:

['package.form_util']

Т.е. базовый пакет package удалился из словаря, а вот модуль внутри package.form_util остался. И после этого при повторном импорте этого пакета и модуля возникает ошибка.

Как же найти настоящую ошибку?

Как вы уже поняли, если вы получаете traceback при импорте, в котором нет конкретного места ошибки, это скорее всего значит что ошибка в другом месте. Это должна быть ошибка в модуле, который импортируется после того который падает.

Как один из вариантов: словить все ошибки в импортах при первом импорте и отпечатать их каким-то специфическим сообщением, например:

try:  
    from package import form_util
    from package import bad_module
except Exception as e:  
    import __main__
    if not getattr(__main__, '__package_already_imported', False):
        __main__.__package_already_imported = True
        log.exception("Real import error for package")
    raise

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

Неужели было так сложно?

Если у вас логи не большие, вы, наверное могли бы просто найти первую ошибку. Но в старом питоне есть несколько случаев, когда ошибки просто скрываются вообще. Например, баг в isinstance.

Также в логах мы видим очень много ошибок, и сложно понять какая из них первая. На машине разработчика почти никогда не получается повторить такие баги.

Ну и главное на самом деле то, что сообщение от Python'а вводит в замешательсво и проблему ищут в другом месте.

Вместо выводов

Теперь, когда вы знаете в чём проблема, такие ошибки будут вам казаться простыми и очевидными. В этом и была цель этой статьи.

А еще, это очередной камень в огород старых версий python'а. В том числе и старых версий из линейки 3.x.

Paul Colomiets

Read more posts by this author.