מה קרה
ב-CI של #3485, בג'וב Unit Tests (3.12), כל 7 הטסטים ב-tests/test_get_db_publishes_after_connect.py נפלו ב-setup עם Failed: Timeout >60.0s, בשורה 108: ה-with lock: בפיקסצ'ר _drain_the_background_db_pollers. באותה ריצה Unit Tests (3.11) עבר, ובריצה של 27.09 (ריצה 36339011447) אותו פיקסצ'ר לקח 6.00 שניות, גם ב-3.11 וגם ב-3.12.
ה-PR לא נוגע ב-get_db, בשולח הפוש או ב-freezegun. הוא הוסיף קובץ טסטים, וזה שינה את חלוקת הקבצים בין שני ה-workers של xdist ואת התזמון שלהם.
ציר הזמן
מהלוג של הג'וב ומהארטיפקט unit-durations-3.12-36524499522, שבו לכל טסט נשמרו רשומות הלוג שנכתבו בזמן שרץ (כולל threadName ו-created). הכול על worker gw0. שולח רץ רק בתהליך אחד בכל מכונה, בזכות flock על /tmp/codebot-push-sender.lock, ורשומות של push-sender מופיעות רק בטסטים של gw0.
| שעה (UTC) |
מה קרה |
מקור |
| 05:09:59.894 |
push-sender רושם Failed to connect to MongoDB, עם ServerSelectionTimeoutError: mongodb:27017: [Errno -3] Temporary failure in name resolution ... Timeout: 5.0s |
רשומת לוג בארטיפקט |
| בערך 05:10:59.9 |
השולח מתעורר וקורא שוב ל-get_db(). חלון הצינון (30 שניות) כבר עבר |
חישוב, לא לוג: 05:09:59.894 ועוד 60 שניות שינה (ברירת המחדל של PUSH_SEND_INTERVAL_SECONDS). הסבב השני, _send_due_events_once, חוזר מיד, כי get_db() מחזיר None בחלון הצינון |
| 05:10:59.760–05:10:59.985 |
על אותו worker רץ tests/test_israel_timezone_display.py::test_day_hhmm_decides_today_by_israel_date, שמעוטר ב-@freeze_time("2026-08-13 22:30:00") |
שורות [gw0] PASSED בלוג: הטסט הקודם הסתיים ב-05:10:59.760, והזה ב-05:10:59.985 |
| 05:11:13–05:12:13 |
הפיקסצ'ר של test_get_db_publishes_after_connect.py ממתין ל-_DB_INIT_LOCK 60 שניות, ו-pytest-timeout מפיל את כל 7 הטסטים |
60.00s setup בלוג |
המחסנית של push-sender ברגע ה-timeout, מהלוג:
webapp/push_api.py, _send_due_once: db = get_db()
webapp/app.py, get_db: _new_client.server_info()
pymongo/synchronous/topology.py, _select_servers_loop: _cond_wait(self._condition, common.MIN_HEARTBEAT_INTERVAL)
המנגנון
- freezegun מחליף את השעון של כל התהליך. freezegun 1.5.5 (נעוץ ב-
requirements/development.txt, וזו הגרסה שהותקנה ב-CI) מציב time.monotonic = fake_monotonic בתחילת ההקפאה (freezegun/api.py, _freeze_time.start). fake_monotonic מחזיר את התאריך המוקפא כשניות מאז 1970 (_get_fake_monotonic, עם calendar.timegm), כלומר בערך 1.786 מיליארד עבור 2026-08-13. ברשימת ההתעלמות של freezegun יש threading (freezegun/config.py, DEFAULT_IGNORE_LIST), אבל _should_use_real_time בודק רק 5 מסגרות מעל הקורא (call_stack_inspection_limit = 5). לכן קריאה מתוך pymongo, בתהליכון רקע, מקבלת את הערך המוקפא.
- pymongo מחשב את הדדליין מהשעון הזה. ב-pymongo 4.15.3,
pymongo/synchronous/topology.py, _select_servers_loop: now = time.monotonic() ו-end_time = now + timeout, ואז לולאה שממתינה עד now > end_time.
- השולח מחזיק את הנעילה בזמן ההמתנה.
get_db() ב-webapp/app.py קורא ל-server_info() בתוך _DB_INIT_LOCK. ב-CI של PR המארח mongodb אינו נפתר (מתועד ב-docs/testing.rst, "בדיקות מול מונגו אמיתי"), ולכן בחירת השרת לא מוצאת שרת וממתינה לדדליין. דדליין שחושב בתוך ההקפאה הוא בערך 1.786 מיליארד ועוד 5. השעון האמיתי ב-Linux סופר מאז שהמכונה עלתה, כלומר כמה מאות שניות. יוצא שההמתנה ארוכה בערך 57 שנה, והנעילה כל הזמן ביד.
- הפיקסצ'ר ממתין בלי דדליין משלו.
with lock: בשורה 108 חוסם עד ש-pytest-timeout מפיל אותו.
כשהמסד נגיש, כמו ב-deploy.yml אחרי מיזוג, זה לא קורה: pymongo בודק את הדדליין רק כל עוד לא נמצא שרת, ושרת נגיש נמצא כבר בסבב הראשון.
שחזור מקומי, על הקוד האמיתי
- ישיר: סבב אחד של
push_api._send_due_once() בתהליכון, מול אותה כתובת שב-CI. בלי הקפאה הנעילה השתחררה אחרי 4.9 שניות. כשהסבב התחיל בתוך freeze_time("2026-08-13 22:30:00"), הנעילה עדיין הייתה תפוסה אחרי 20 שניות, ולדדליין של pymongo נותרו 1,786,659,223 שניות.
- מקצה לקצה: קובץ עם סבב מוקפא אחד, שרץ לפני
tests/test_get_db_publishes_after_connect.py, נותן בדיוק את 7 השגיאות בשורה 108. אותו קובץ עם סבב על שעון אמיתי: כל 8 הטסטים עוברים.
קוד השחזור מקצה לקצה
# test_aaa_frozen_round.py — קובץ זמני מחוץ לריפו
import threading
import time
from freezegun import freeze_time
# כמו tests/test_israel_timezone_display.py: webapp.app נטען כבר באיסוף
from webapp import app as webapp_app # noqa: F401
def _one_round():
import webapp.push_api as push_api
try:
push_api._send_due_once()
except Exception: # כמו push_api._loop_send_due_reminders
pass
def test_a_sender_round_frozen():
thread = threading.Thread(target=_one_round, name="push-sender-sim", daemon=True)
with freeze_time("2026-08-13 22:30:00"):
thread.start()
time.sleep(0.3)
PUSH_NOTIFICATIONS_ENABLED=false \
MONGODB_URL='mongodb://test:test123@mongodb:27017/test_db?authSource=admin' \
python -m pytest -o addopts="" /path/to/test_aaa_frozen_round.py tests/test_get_db_publishes_after_connect.py
PUSH_NOTIFICATIONS_ENABLED=false מכבה את השולח האמיתי, כדי שהסבב היחיד יתחיל ברגע ידוע. time.sleep אינו מוחלף על ידי freezegun, ולכן ההמתנה של 0.3 שניות אמיתית.
השורש
השולח לא אמור לרוץ בתהליך הטסטים בכלל. docs/deployment/workers.rst, בסעיף "מי שולח את התזכורות, ומתי", אומר "thread בתוך תהליך ה-WebApp". בפועל webapp/app.py קורא ל-start_sender_if_enabled() בזמן import (שורה 1556), ולכן השולח עולה בכל תהליך שמייבא את webapp.app: workers של pytest, סקריפטים, וגם main.py, שמייבא מ-webapp.app מתוך פונקציות (שורות 7133, 7276, 7349). לא בדקתי אם המסלולים האלה ב-main.py רצים בפרודקשן. זה הדפוס import-time-side-effects ב-amir-bug-patterns, וגם סתירה בין הקוד לתיעוד.
הפיקסצ'ר _drain_the_background_db_pollers נלחם בתסמין. ה-docstring שלו כבר מתעד תקרית קודמת של אותו שולח, והוא עצמו ממתין לנעילה בלי דדליין משלו (הדפוס wait-without-own-deadline).
הצעת תיקון (לא מומש)
אפשרות א' (מומלצת): להפעיל את השולח רק כש-_is_webapp_runtime() מחזיר אמת (webapp/app.py, שורה 977). זה אותו שומר שכבר מגן על ה-backup scheduler בזמן import (שורות 997–1008). הוא מזהה gunicorn לפי sys.argv[0], והוובאפ עולה דרך scripts/start_webapp.sh, שמריץ gunicorn.
- טסט שנופל על הקוד הנוכחי: טעינה של
webapp.app בתהליך שאינו הוובאפ (למשל pytest) לא מרימה תהליכון push-sender.
- להחליף את הפיקסצ'ר המנקז בבדיקה שנכשלת מיד, בהודעה ברורה, אם שולח רץ בתהליך. במקום להמתין לנעילה.
- לעדכן את "מי שולח את התזכורות, ומתי" ב-
workers.rst.
- לאמת לפני מיזוג: לא בדקתי ש-
_is_webapp_runtime() מחזיר אמת בתוך worker של gunicorn בפרודקשן. אם הוא מחזיר שקר, בלוג של הוובאפ תופיע השורה Skipping backup scheduler: webapp.app imported from non-webapp process, כי ה-backup scheduler כבר נשען עליו.
- להכריע: ל-
_is_webapp_runtime() יש override בשם FORCE_BACKUP_SCHEDULER. אם השולח ישתמש באותו שומר, השם הזה יפעיל גם אותו, וזה רחב יותר ממה שהשם אומר.
- השפעה על פרודקשן: תהליך שאינו הוובאפ ומייבא את
webapp.app יפסיק להריץ שולח משלו. לפי התיעוד זו הכוונה, ולפי אותו תיעוד מניעת הכפילות נשענת על _claim_reminder ועל needs_push. זו החלטה של בעל הריפו. מי שכתב את הפיקסצ'ר השאיר אותה בכוונה לסבב נפרד.
אפשרות ב' (רק טסטים): למנוע מהשולח לעלות בתהליך הטסטים דרך tests/conftest.py. פרודקשן לא משתנה, אבל הסתירה עם התיעוד נשארת, והפתרון נשען על מנגנון פנימי. PUSH_NOTIFICATIONS_ENABLED=false לא מתאים לזה: הוא קובע גם מה מוצג בממשק (_build_push_card ב-webapp/app.py, ועמודי ההגדרות ב-webapp/routes/settings_routes.py).
למה זה נדיר
השולח מתעורר פעם בכ-60 שניות, החלון המוקפא נמשך בערך 0.2 שניות, וקובץ שממתין לנעילה צריך לרוץ אחר כך על אותו worker. לכן זה שקט רוב הזמן, ומופיע כשחלוקת הקבצים בין ה-workers משתנה.
קשור
מה קרה
ב-CI של #3485, בג'וב
Unit Tests (3.12), כל 7 הטסטים ב-tests/test_get_db_publishes_after_connect.pyנפלו ב-setup עםFailed: Timeout >60.0s, בשורה 108: ה-with lock:בפיקסצ'ר_drain_the_background_db_pollers. באותה ריצהUnit Tests (3.11)עבר, ובריצה של 27.09 (ריצה 36339011447) אותו פיקסצ'ר לקח 6.00 שניות, גם ב-3.11 וגם ב-3.12.ה-PR לא נוגע ב-
get_db, בשולח הפוש או ב-freezegun. הוא הוסיף קובץ טסטים, וזה שינה את חלוקת הקבצים בין שני ה-workers של xdist ואת התזמון שלהם.ציר הזמן
מהלוג של הג'וב ומהארטיפקט
unit-durations-3.12-36524499522, שבו לכל טסט נשמרו רשומות הלוג שנכתבו בזמן שרץ (כוללthreadNameו-created). הכול על workergw0. שולח רץ רק בתהליך אחד בכל מכונה, בזכותflockעל/tmp/codebot-push-sender.lock, ורשומות שלpush-senderמופיעות רק בטסטים שלgw0.push-senderרושםFailed to connect to MongoDB, עםServerSelectionTimeoutError: mongodb:27017: [Errno -3] Temporary failure in name resolution ... Timeout: 5.0sget_db(). חלון הצינון (30 שניות) כבר עברPUSH_SEND_INTERVAL_SECONDS). הסבב השני,_send_due_events_once, חוזר מיד, כיget_db()מחזירNoneבחלון הצינוןtests/test_israel_timezone_display.py::test_day_hhmm_decides_today_by_israel_date, שמעוטר ב-@freeze_time("2026-08-13 22:30:00")[gw0] PASSEDבלוג: הטסט הקודם הסתיים ב-05:10:59.760, והזה ב-05:10:59.985test_get_db_publishes_after_connect.pyממתין ל-_DB_INIT_LOCK60 שניות, ו-pytest-timeout מפיל את כל 7 הטסטים60.00s setupבלוגהמחסנית של
push-senderברגע ה-timeout, מהלוג:המנגנון
requirements/development.txt, וזו הגרסה שהותקנה ב-CI) מציבtime.monotonic = fake_monotonicבתחילת ההקפאה (freezegun/api.py,_freeze_time.start).fake_monotonicמחזיר את התאריך המוקפא כשניות מאז 1970 (_get_fake_monotonic, עםcalendar.timegm), כלומר בערך 1.786 מיליארד עבור 2026-08-13. ברשימת ההתעלמות של freezegun ישthreading(freezegun/config.py,DEFAULT_IGNORE_LIST), אבל_should_use_real_timeבודק רק 5 מסגרות מעל הקורא (call_stack_inspection_limit = 5). לכן קריאה מתוך pymongo, בתהליכון רקע, מקבלת את הערך המוקפא.pymongo/synchronous/topology.py,_select_servers_loop:now = time.monotonic()ו-end_time = now + timeout, ואז לולאה שממתינה עדnow > end_time.get_db()ב-webapp/app.pyקורא ל-server_info()בתוך_DB_INIT_LOCK. ב-CI של PR המארחmongodbאינו נפתר (מתועד ב-docs/testing.rst, "בדיקות מול מונגו אמיתי"), ולכן בחירת השרת לא מוצאת שרת וממתינה לדדליין. דדליין שחושב בתוך ההקפאה הוא בערך 1.786 מיליארד ועוד 5. השעון האמיתי ב-Linux סופר מאז שהמכונה עלתה, כלומר כמה מאות שניות. יוצא שההמתנה ארוכה בערך 57 שנה, והנעילה כל הזמן ביד.with lock:בשורה 108 חוסם עד ש-pytest-timeout מפיל אותו.כשהמסד נגיש, כמו ב-
deploy.ymlאחרי מיזוג, זה לא קורה: pymongo בודק את הדדליין רק כל עוד לא נמצא שרת, ושרת נגיש נמצא כבר בסבב הראשון.שחזור מקומי, על הקוד האמיתי
push_api._send_due_once()בתהליכון, מול אותה כתובת שב-CI. בלי הקפאה הנעילה השתחררה אחרי 4.9 שניות. כשהסבב התחיל בתוךfreeze_time("2026-08-13 22:30:00"), הנעילה עדיין הייתה תפוסה אחרי 20 שניות, ולדדליין של pymongo נותרו 1,786,659,223 שניות.tests/test_get_db_publishes_after_connect.py, נותן בדיוק את 7 השגיאות בשורה 108. אותו קובץ עם סבב על שעון אמיתי: כל 8 הטסטים עוברים.קוד השחזור מקצה לקצה
PUSH_NOTIFICATIONS_ENABLED=falseמכבה את השולח האמיתי, כדי שהסבב היחיד יתחיל ברגע ידוע.time.sleepאינו מוחלף על ידי freezegun, ולכן ההמתנה של 0.3 שניות אמיתית.השורש
השולח לא אמור לרוץ בתהליך הטסטים בכלל.
docs/deployment/workers.rst, בסעיף "מי שולח את התזכורות, ומתי", אומר "thread בתוך תהליך ה-WebApp". בפועלwebapp/app.pyקורא ל-start_sender_if_enabled()בזמן import (שורה 1556), ולכן השולח עולה בכל תהליך שמייבא אתwebapp.app: workers של pytest, סקריפטים, וגםmain.py, שמייבא מ-webapp.appמתוך פונקציות (שורות 7133, 7276, 7349). לא בדקתי אם המסלולים האלה ב-main.pyרצים בפרודקשן. זה הדפוסimport-time-side-effectsב-amir-bug-patterns, וגם סתירה בין הקוד לתיעוד.הפיקסצ'ר
_drain_the_background_db_pollersנלחם בתסמין. ה-docstring שלו כבר מתעד תקרית קודמת של אותו שולח, והוא עצמו ממתין לנעילה בלי דדליין משלו (הדפוסwait-without-own-deadline).הצעת תיקון (לא מומש)
אפשרות א' (מומלצת): להפעיל את השולח רק כש-
_is_webapp_runtime()מחזיר אמת (webapp/app.py, שורה 977). זה אותו שומר שכבר מגן על ה-backup scheduler בזמן import (שורות 997–1008). הוא מזהה gunicorn לפיsys.argv[0], והוובאפ עולה דרךscripts/start_webapp.sh, שמריץ gunicorn.webapp.appבתהליך שאינו הוובאפ (למשל pytest) לא מרימה תהליכוןpush-sender.workers.rst._is_webapp_runtime()מחזיר אמת בתוך worker של gunicorn בפרודקשן. אם הוא מחזיר שקר, בלוג של הוובאפ תופיע השורהSkipping backup scheduler: webapp.app imported from non-webapp process, כי ה-backup scheduler כבר נשען עליו._is_webapp_runtime()יש override בשםFORCE_BACKUP_SCHEDULER. אם השולח ישתמש באותו שומר, השם הזה יפעיל גם אותו, וזה רחב יותר ממה שהשם אומר.webapp.appיפסיק להריץ שולח משלו. לפי התיעוד זו הכוונה, ולפי אותו תיעוד מניעת הכפילות נשענת על_claim_reminderועלneeds_push. זו החלטה של בעל הריפו. מי שכתב את הפיקסצ'ר השאיר אותה בכוונה לסבב נפרד.אפשרות ב' (רק טסטים): למנוע מהשולח לעלות בתהליך הטסטים דרך
tests/conftest.py. פרודקשן לא משתנה, אבל הסתירה עם התיעוד נשארת, והפתרון נשען על מנגנון פנימי.PUSH_NOTIFICATIONS_ENABLED=falseלא מתאים לזה: הוא קובע גם מה מוצג בממשק (_build_push_cardב-webapp/app.py, ועמודי ההגדרות ב-webapp/routes/settings_routes.py).למה זה נדיר
השולח מתעורר פעם בכ-60 שניות, החלון המוקפא נמשך בערך 0.2 שניות, וקובץ שממתין לנעילה צריך לרוץ אחר כך על אותו worker. לכן זה שקט רוב הזמן, ומופיע כשחלוקת הקבצים בין ה-workers משתנה.
קשור