Новогодний детектив, или странный хайзенбаг в «питоньих» часах31.12.2021 00:02

hu70uxs_lpmfoav5c0gua3ba2tg.jpeg

Давненько я не писал на Хабр, да и тема интересная появилась, так что пора поправить это постыдное упущение.

Далее собственно детектив как оно есть, «расследование» которого ещё не окончено, можно присоединиться кстати… Пост будет обновляться, по окончанию (я надеюсь что баг таки найдётся) пост изменит название получив префикс »[SOLVED]»…

Постучался тут человечек на GH, с ошибкой типа «Fail2ban ведет себя как-будто он временами в будущем». Первой мыслью было — что опять! ну снова кто-то во временных зонах потерялся.
Но нет, всё оказалось несколько хуже — иногда, редко, Fail2ban пишет в логи дату из 2023-го года.
И не только пишет, а по всей видимости действительно начинает считать что он где-то в 2023-м, со всеми вытекающими — снятием бана для блокированных адресов по истечению срока действия и т.д. и т.п.
Причем делает это для всех потоков, а чуть позже возвращается в 2021-й, чтобы позднее снова на короткое время прыгнуть в 2023-й и так снова и снова.

Т.к. Fail2ban пишет в лог системное время, я ответил товарищу что оно вероятнее всего просто постоянно меняется, т.е. либо синхронизация времени NTP каким-то образом «нарушена», либо (что весьма вероятно) какой-то сервис или скрипт постоянно изменяет системные часы на короткое время. И на этом закрыл вопрос как 3rd party issue.

Ну и человек через некоторое время вернулся, попробовав мой тест-скрипт вида
while true; do date >> date.log && sleep 0.5 ; done (даже с sleep 0.001), и не обнаружил там временных аномалий (в то время как Fail2ban по его заявлению прыгал туда-сюда во времени), а также указал что дескать он, Fail2ban, единственный сервис что периодически так делает — всё остальное, вплоть до журналов syslog, остаётся в родном 2021-м.

На вопрос что же будет наблюдается для вот этого: 

python3 -c $'import time\nwhile True: t=time.time(); lt=time.localtime(t); print("%.3f\t%.3f\t%s" % (time.monotonic(), t, time.strftime("%Y-%m-%dT%H:%M:%S", lt))), time.sleep(0.5)'


в удобочитаемом, «питоньем» виде … 
import time
while True:
    t=time.time()
    lt=time.localtime(t)
    print("%.3f\t%.3f\t%s" % (
        time.monotonic(), t, time.strftime("%Y-%m-%dT%H:%M:%S", lt)
    ))
    time.sleep(0.5)

ответ был (короткий отрывок, diff синтаксис в качестве «ударения»): 

  18604.919       1640095233.438  2021-12-21T06:00:33
  18605.435       1640095233.955  2021-12-21T06:00:33
- 19119.627       1705034426.326  2023-01-14T10:03:00
  18606.468       1640095234.988  2021-12-21T06:00:34
  18606.984       1640095235.504  2021-12-21T06:00:35
  18607.501       1640095236.020  2021-12-21T06:00:36
- 19121.692       1705034428.642  2023-01-14T10:03:02
  18608.533       1640095237.053  2021-12-21T06:00:37
  18609.049       1640095237.569  2021-12-21T06:00:37

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

Что мы тут собственно видим — «голый» python тут прыгает во времени почем зря, при этом даже на monotonic time тот «прыжок» иногда заметен, однако там он как бы больше «дрейф» чем «прыжок», ибо разница составляет лишь 514 секунд, но пока не суть важно.
Внимательный читатель наверняка заметил еще одну странность — unix time 1705M находится в 2024-м году, а не в 2023-м как strftime нам заявляет (об этом подробнее ниже). О чем товарищу было сказано собственно, с прувом и описанием всех остальных странностей в том числе и некоторым сомнением что всё это прикол шутка юмора.


прув: strftime для 1705034426 … 
$ python3 -c 'import time; print(time.strftime("%Y-%m-%dT%H:%M:%S", time.gmtime(1705034426)))'
2024-01-12T04:40:26
$ python3 -c 'import time; print(time.strftime("%Y-%m-%dT%H:%M:%S", time.localtime(1705034426)))'
2024-01-12T05:40:26 (in CET)

Организованная им проверка на вшивость для syscall clock_gettime показывает, что оно дескать всегда возвращает корректное значение, т.е. подозрение пока на python (версия 3.9.2) собственно.

Проверка на возможные изменения /etc/localtime или чего-то в этом роде, определением TZ=UTC перед вызовом питона показала те же результаты (только со смещением GMT+0000 в локальном времени).

Тест того же в python 2.7 на той же самой машине показал, что 2-й питон не подвержен временной аномалии от слова совсем.

Попытка оттрейсить это с помощью strace провалилась (clock_gettime не наблюдается вовсе), ибо ванильный python 3.9.2 (в Debian 11) или скомпилирован как-то со статически слинкованой libc (и оно там в юзерспейсе) или что-то в этом духе, т.е. имеем такой результат (в сравнении с тем же 3.9 собранным из исходниках на моём Debian 10 или ванильным 3.7 для него же): 

$ strace python3 -c $'import time\nwhile True: t=time.time(); lt=time.localtime(t); print("%.3f\t%.3f\t%s" % (time.monotonic(), t, time.strftime("%Y-%m-%dT%H:%M:%S", lt))), time.sleep(0.5)'
...
- clock_gettime(CLOCK_REALTIME, {tv_sec=1640104296, tv_nsec=784712193}) = 0
- clock_gettime(CLOCK_MONOTONIC, {tv_sec=22780079, tv_nsec=358645597}) = 0
  write(1, "22780079.359\t1640104296.785\t2021"..., 4822780079.359        1640104296.785  2021-12-21T17:31:36
...

(хотя согласно исходникам он однозначно вызывает clock_gettime и в 3.9.2).

Ну на нет и суда нет, в сторону strace, заряжаем ltrace…

И… многочисленные попытки уточнить что это за свинство такое с помощью ltrace (с собственным конфигом, чтобы оттрейсить локальный clock_gettime и т.п.) показывают совершенно ненормальные результаты — что-то внутри python «арифметики» ломает верные значения clock_gettime почём зря, при этом по видимому многократно.

В результате для: 

# пишем конфиг:
printf 'typedef clockid_t = enum (CLOCK_REALTIME=0, CLOCK_MONOTONIC=1);\ntypedef timespec = struct(long, long);\ntypedef tm = struct(int, int, int, int, int, int, int, int, int);\nint clock_gettime(clockid_t, +timespec*);\ndouble floor(void*, double);\ntm* localtime_r(long*, +tm*);\n' > /tmp/ltrace.conf
# л-трейсим только *gettime, floor, localtime_r и write:
ltrace -e '*gettime+floor+localtime_r+write' -F /tmp/ltrace.conf python3 -c $'import time\nwhile True: t=time.time(); lt=time.localtime(t); print("%.3f\t%.3f\t%s" % (time.monotonic(), t, time.strftime("%Y-%m-%dT%H:%M:%S", lt))), time.sleep(0.5)'

имеем следующее (снова короткий отрывок, diff синтаксис в качестве «ударения»): 

...
+ python3->clock_gettime(CLOCK_REALTIME, { 1640803034, 720044189 })                                 = 0
+ python3->floor(0, 1640803034.720044)                                                              = 1640803034.000000
+ python3->localtime_r(1640803034, { 14, 37, 10, 29, 11, 121, 3, 362, 0 })                          = { 14, 37, 10, 29, 11, 121, 3, 362, 0 }
+ python3->clock_gettime(CLOCK_MONOTONIC, { 726625, 727901583 })                                    = 0
+ python3->write(1, 0x24c2cc0, 46, 0726625.728    1640803034.720  2021-12-29T10:37:14
  )                                                               = 46
  python3->clock_gettime(CLOCK_MONOTONIC, { 726625, 728323139 })                                    = 0
- python3->clock_gettime(CLOCK_REALTIME, { 1640803035, 222419463 })                                 = 0
- python3->floor(0, 1674361765.555368)                                                              = 1674361765.000000
- python3->localtime_r(1674361765, { 25, 29, 20, 21, 0, 123, 6, 20, 0 })                            = { 25, 29, 20, 21, 0, 123, 6, 20, 0 }
- python3->clock_gettime(CLOCK_MONOTONIC, { 726626, 230566667 })                                    = 0
- python3->write(1, 0x24c2cc0, 46, 0755543.594    1705615768.690  2023-01-21T20:29:25
  )                                                               = 46
  python3->clock_gettime(CLOCK_MONOTONIC, { 726626, 231242085 })                                    = 0
+ python3->clock_gettime(CLOCK_REALTIME, { 1640803035, 725428043 })                                 = 0
+ python3->floor(0, 1640803035.725428)                                                              = 1640803035.000000
+ python3->localtime_r(1640803035, { 15, 37, 10, 29, 11, 121, 3, 362, 0 })                          = { 15, 37, 10, 29, 11, 121, 3, 362, 0 }
+ python3->clock_gettime(CLOCK_MONOTONIC, { 726626, 733596674 })                                    = 0
+ python3->write(1, 0x24c2cc0, 46, 0726626.734    1640803035.725  2021-12-29T10:37:15
  )                                                               = 46
  python3->clock_gettime(CLOCK_MONOTONIC, { 726626, 734181225 })                                    = 0
- python3->clock_gettime(CLOCK_REALTIME, { 1640803036, 228679952 })                                 = 0
- python3->floor(0, 1674361766.562118)                                                              = 1674361766.000000
- python3->localtime_r(1674361766, { 26, 29, 20, 21, 0, 123, 6, 20, 0 })                            = { 26, 29, 20, 21, 0, 123, 6, 20, 0 }
- python3->clock_gettime(CLOCK_MONOTONIC, { 726627, 237223939 })                                    = 0
- python3->write(1, 0x24c2cc0, 46, 0755544.600    1705615769.697  2023-01-21T20:29:26
  )                                                               = 46
...

По поводу ненормальности результатов, как это выглядит: 

t=time.time();        # 1640M retrieved, 1705M stored in t
lt=time.localtime(t); # lt is built from 1674M base

Т.е. time.time вызывая clock_gettime(CLOCK_REALTIME) получает {1640803035, 222419463}, преобразуя это в double (если смотреть в исходники, это происходит через long long) оно возвращает 1705615768.690 (сохраняется в t). А затем при вычислении time.localtime(t) наше время (в качестве локального базиса) становится вдруг 1674361765.555368 и в результате имеем { 25 сек., 29 мин., 20 час., 21 день, 0 + 1 мес., 123 + 1900 год., ... } что и соответствует 2023-01-21T20:29:25 в итоге при выводе в консоль через strftime.
Как это объяснить кроме как магией, сломанной математикой double, перемешиванием инструкций byte-code питона на лету (в результате какой-то непонятной оптимизации) или вообще UB (удивительно стабильным, ну как — относительно стабильным) я не очень пока понимаю.
Возможно это какая-либо проблема синхронизации, но в простейшем тесте то всё работает однопоточно…
Ошибки в железе? Тогда почему это проявляется исключительно в питоне.

Кроме того при прыжках наблюдается еще более странное поведение — эти «непонятные» значения t (те что 1705M) иногда отличаются на 120 и более секунд (иррегулярно), притом что исходные значения (те что 1640M) и значения lt (и промежуточной арифметики, те что 1674M) отличаются (как и положено) на 1 секунду, например: 

743604.531      1705616185.204  2023-01-21T20:38:21 // *185
727162.487      1640803571.480  2021-12-29T10:46:11
727163.004      1640803571.997  2021-12-29T10:46:11
743606.036      1705616305.981  2023-01-21T20:38:22 // nix time changes to *305; the time in the date string changing to next second compared to 1st value.
743606.554      1705616306.498  2023-01-21T20:38:23

Я постучался с этим в IRC#python, там люди поудивлялись немного, но конкретных предложений не поступало.
Анализ исходников, кроме того, что оно там переворачивалось сто раз между до 3.10 (не говоря уже про master), ничего не дал (пока во всяком случае, т.к. времени очень мало свободного).


Машина товарища (информация о системе где оно сломано) … 
System:    Host: localhost Kernel: 5.10.0-9-amd64 x86_64 bits: 64 Console: tty 0 Distro: Debian GNU/Linux 11 (bullseye)
Machine:   Type: Kvm System: QEMU product: Standard PC (i440FX + PIIX, 1996) v: pc-i440fx-3.1 serial: N/A
           Mobo: N/A model: N/A serial: N/A BIOS: SeaBIOS v: 1.12.0-1 date: 04/01/2014
CPU:       Info: Single Core model: AMD Ryzen 9 3900X bits: 64 type: UP L2 cache: 512 KiB
           Speed: 3793 MHz min/max: N/A Core speed (MHz): 1: 3793
Info:      Processes: 92 Uptime: 2d 13h 08m Memory: 976.4 MiB used: 397 MiB (40.7%) Init: systemd runlevel: 5 Shell: Bash

Промежуточные результаты расследования иcследования или как issue видится мне в виде краткой выжимки:


  1. python 3.9.2 периодически возвращает странные значения для time.time() и time.localtime(), лежащие в будущем, при этом ни один процесс кроме python3 не показывает такого поведения… включая python 2.7, который тоже не подвержен этим временным сдвигам.
  2. это не воспроизводится пока нигде кроме конкретной виртуалки товарища, сообщившего об ошибке.
  3. трейсинг показывает что clock_gettime(CLOCK_REALTIME) возвращает корректные значения, при этом временами внутренняя «математика» питона полностью сходит с ума (см. выше).
  4. Значения t = time.time() и lt = time.localtime(t) могут отличаться на год, при том, что дрейф не зависит от выбранной временной зоны (т.е. верно и для UTC/GMT).
  5. Во время временного «прыжка» значения t могут быть иррегулярны (могут отличаться от предыдущих на минуты), при том что значения lt (что есть time.localtime(t)) стабильны, т.е. инкрементируются и выглядят регулярно.
  6. Во время «прыжка» нередко (однако не всегда) наблюдается временной сдвиг и в time.monotonic(), при этом сдвиг много меньше сдвига для time.time().

Пока на этом всё. Всех с наступающим, и если есть идеи, предложения и желание поучаствовать, добро пожаловать в комменты или на github.

© Habrahabr.ru