מעשה בבאג שקרה לפעמים

כאילו שלא מספיקים לנו באגים רגילים שמתעלקים למערכת (מתעלקים מבחוץ, ברור. למה מה, אנחנו כותבים באגים??), קורה – לעתים רחוקות, אמנם – שיש באגים שלא רק צריך לטפל בהם, אלא צריך קודם כל למצוא אותם. אלה באגי ה"לפעמים".

ומעשה שהיה, כך היה.

אקדח במערכה הראשונה

באחד מאתרי המוודל שלנו (בתחום הננוטכנולוגיה, אם ממש חשוב לכם לדעת), יש כמה וכמה קורסים (מרחבים, בעגת המוודל). בניגוד לרוב הקורסים שלנו במוודל בהם הכניסה מותרת רק למי שנרשם לקורס, בתחום הדעת הזה רצינו לאפשר לכל תלמיד להכנס לכל הקורסים במערכת, גם ללא הרשמה. מהבחינה הזו אין בעיה במוודל: יש פונקציה שנקראת כניסת אורח המאפשרת לכל תלמיד להכנס לקורס. אבל במו"פ של אורט לא נוהגים להסתפק בפתרונות מובנים במערכת, אלא משתדלים לגוון בדרישות עד שלא תהיה ברירה אלא ליצור פתרונות מותאמים אישית. במקרה הזה, היתה בקשה להרחיב את יכולותיו של המשתמש האורח: בקורס משולבים בחנים (כמה שאלות קצרות שנועדו לבחון את הידע של התלמיד לפני לימוד החומר ואחריו). בד"כ, רק תלמיד רשום יכול לבצע בוחן, ואילו משתמש אורח מנוע מכך. בתחום הדעת הזה, מאחר שרוב התלמידים כנראה לא יירשמו אלא ישתמשו בכניסת האורח, התבקשנו לתת למשתמש אורח יכולת לגשת לבחנים.

לאחר התייעצות עם מומחה מוודל, הפתרון שהוחלט עליו היה יצירת משתמש מסוג חדש – סוּפֶּר-אורח – שיהיה מוטציה של משתמש רשום: הוא יווצר דינמית בעת לחיצה על כפתור "כניסה כאורח",  אך בעזרת שמירה נכונה במסד הנתונים, וביצוע עבודת CRON לעתים מזומנות – הוא יהיה משתמש רשום זמני בלבד.  כך הוא יוכל לגשת לבחנים (כמו משתמש רשום) אך יימחק מהמערכת בתום זמן קצוב. אותו מומחה סיפק לנו את הקוד, ובא לציון גואל.

באג הלפעמים (לא כל-כך) נעים להכיר

המערכת כבר עלתה לאוויר, ועמדה להיות מושקת, כשלפתע היו דיווחים מצד צוות הבדיקות על באג: מנסים להכנס לקורס כלשהו בכניסת סוּפֶּר-אורח, ומקבלים הודעה שלא ניתן להרשם לקורס הזה.
מבוכה.

מיד התחלנו לנסות למקד את הבאג: האם זה קורה בכל הקורסים? האם זה קורה במחשבים אחרים? בקיצור, הבדיקות הראשוניות הסטנדרטיות שמבצעים עם התקלות בבאג.
כאן העלילה התחילה להסתבך: התברר שזה לא קורה בכל הקורסים, וגם לא בכל המחשבים.
למעשה, היה קשה מאוד לשחזר את הבאג. הוא קרה רק למתי מעט, וגם להם – לא תמיד.

תפוס אותי אם תוכל

מכיוון שכך, החלטנו לשנות כיוון והתחלנו לעבור על הקוד. ניסינו למקד ולהבין איזה קטע קוד עשוי ליצור את הבאג. אחת המתכנתות הצליחה למקד אזור מסוים בפונקציית בדיקת הלוגאין, שבו עלולה אחת הבדיקות להניב תוצאה של חוסר רישום לקורס. כאן הגענו למבוי סתום, כי כדי להבין איך מגיעים לקטע הקוד הנ"ל, צריך להתקל בבאג ולהתבונן בו בדיבאג, מה שבעצם החזיר אותנו למרדף אחרי הבאג.

ישבנו כמה מתכנתים, כל אחד בעמדתו, ונכנסנו שוב ושוב למערכת בתור סוּפֶּר-אורח, כשמטרתנו היא להתקל בבאג הסורר.
אך ללא הועיל.
או שלא נתקלנו, או שכשנתקלנו – ברגע שהפעלנו את הבדיקות שלנו הבאג חמק-עבר.
זה היה מתסכל.

הלנצח נרדוף אחרי הבאג?

כ-3 ימים לאחר שהבאג התגלה לראשונה נותרתי בודדה במערכה – היה חורף, ושני המתכנתים האחרים נעדרו מפאת מחלה. עם זאת היתה לי תקווה – ביום הקודם גילינו שיש מחשב מסוים שבו זה קורה. לכן באותו יום חמסתי אותו מהבעלים שלו, וניסיתי לשחזר בו את הבאג. אך כמובן שכשהבאג ראה זאת, הוא הפסיק להופיע גם במחשב הזה!
משאפסה תקוותי להתקל בבאג, עברתי לטקטיקה הפוכה: לצלול לעומק הקוד – לאותו קטע שכבר צומצם ע"י אחת המתכנתות האחרות – ולנסות להבין, מקריאה בלבד, בדיוק איפה קורה השיבוש. נעצתי סכין בין השיניים ויצאתי לדרך.
[אזהרה: בקטעים הבאים יש חפירה קדחנית במיוחד בקוד. מי שרוצה לדלג לסוף, שילחץ כאן]

תביאו את האתים, הולכים לחפור

כאמור, ידענו למקד שזה קורה בפונקציה שבודקת את הלוגאין של המשתמש. הפונקציה הזו נקראת require_login, והיא נמצאת בקובץ  lib/moodlelib.php. הפונקציה משתרעת משורה 2771 עד 3101 (פוקנציה קטנטונת, כולה 330 שורות…). הודעת השגיאה מתקבלת כשהפונקציה עושה redirect לקובץ /enrol/index.php. ראינו שה-redirect הזה קורה בשורה 3073 כשהתנאי if (!$access) הוא חיובי. מאחר ש-$access מוגדר לראשונה בשורה 2987, הרי שהיה ברור שאיפשהו בין השורות 2987 ל-3073, הוא מקבל false שלא כהוגן, וזה יוצר את הבעיה.

ניתחתי את הקוד וראיתי שזה מהלך העניינים:

1. $access מוגדר בשורה 2987
2. ה-if הראשון (is_role_switched($course->id) לא רלוונטי – אנחנו לא בחילופי תפקידים (שורה 2989)
3. גם ה-if השני (is_viewing($coursecontext, $USER)) לא רלוונטי, כי זה לסוגי משתמשים admins, managers (aka small admins), inspectors, וכד' (שורה 2993).
4. לכן נכנסים ל-else (שורה 2997)
5. בודקים את המשתנה $USER->enrol['enrolled'][$course->id]. במשתנה הזה אמור להיות הזמן שבו מסתיים הרישום שלו לקורס. בפעם הראשונה שנכנסים לקורס, זה עדיין לא מוגדר, לכן לא נכנסים ל-if (שורות 2998 – 3009).
6. ה-if שאחריו (isset($USER->enrol['tempguest'][$course->id])) נראה שבודק אם המשתמש הוא guest. זה לא המקרה שלנו (שורות 3010-3020).
7. אחרי זה בודקים את $access, שמא הוא כבר אמתי בשלב הזה (שורה 3022). במקרה שלנו – שזו הפעם הראשונה – הוא לא, ולכן נכנסים ל-else (שורה 3024).
8. כאן קוראים לפונקציה enrol_get_enrolment_end שמחזירה מתי סוף הזמן של הרישום (שורה 3025). אם היא מחזירה ערך אמתי (לא false), מכניסים את זה למשתנה $USER->enrol['enrolled'][$course->id], ו-$access מקבל true (שורה 3033).

כאן גיליתי שהפונקציה enrol_get_enrolment_end היא המפתח: כי אם היא מחזירה false אז לא נכנסים למקום הזה שבו $access אמור לקבל true.

מתקרבים…

הפונקציה enrol_get_enrolment_end שוכנת בוקבץ lib/enrollib.php ומשתרעת משורה 964 עד 1039 (פונקציות זעירות כותבים שם במוודל…)

1. היא שולחת ל-DB את השאילתה הבאה (שורה 969):

   SELECT ue.* FROM mdl_user_enrolments ue 
   JOIN mdl_enrol e ON (e.id = ue.enrolid AND e.courseid = :courseid) 
   JOIN mdl_user u ON u.id = ue.userid
   WHERE ue.userid = :userid AND ue.status = 0 AND e.status = 0 AND u.deleted = 0
   -- כאשר <code> status = 0  /*:active*/, e.status = 0 /* :enabled */

2. אחרי כן היא בודקת שתאריך התחילה והסיום הם תאריכים תקפים (שורות 982-1001)
3. לבסוף היא בודקת (שורות 1005-1031):
   1. שהסיום חל אחרי ההתחלה
   2. שתאריך ההתחלה הגיע
   3. שתאריך הסיום טרם עבר

אם כל שלושת התנאים הללו מתקיימים – היא מחזירה את תאריך הסיום,
אחרת מחזירה false. במקרה של הסוּפֶּר-אורח, זמן ההתחלה הוגדר להיות הזמן הנוכחי – כלומר הרגע שבו המשתמש לחץ על כפתור הכניסה ונכנס למערכת. זמן הסיום הוגדר להיות כמה שעות אחרי כן. אבל ברור שמשהו משתבש וגרם לפונקציה להחזיר ערך false שמנע מהמשתמש להרשם. לכן פה קבור הבאג..

קדימה באג, בוא נראה אותך

עכשיו שידעתי בדיוק איפה הבאג אמור לקרות ופרשתי את הרשת, הייתי מוכנה למקרה שהבאג יתקוף. במהלך היום המשכתי לחפש את הבאג, כשפתאום בחסדי שמים נתקלתי בו. מיד ביצעתי על התלמיד בקורס הזה את הבדיקות המתבצעות בקוד – שליפת נתונים מה-DB והשוואת השעות.

אז מבחינת שליפת הנתונים הכל היה אחלה – היו לו נתונים בכל הטבלאות הרלוונטית. אבל כשבאתי להשוות את השעות, ראיתי לתדהמתי שזמן תחילת הרישום הוא בעוד שתי דקות מהזמן שבו מתבצעת הבדיקה: נכנסתי בשעה 11:09, אבל שעת ההתחלה היתה 11:11… כלומר, הבדיקה שתאריך ההתחלה הגיע (בסעיף 3.2 לעיל) היא זו שנכשלת, ושבגללה $access מקבל false. כנראה שתהליך שיצירה של המשתמש הזמני יוצר תאריך התחלה עתידי, במקום תאריך התחלה עכשווי! אבל למה??? ומדוע לפעמים וכן ולפעמים לא – הרי רוב הזמן המשתמש הזמני מצליח להרשם לקורס ולהכנס אליו ללא בעיה! המשכתי לנסות להכנס כמשתמש זמני, ועקבתי אחרי זמני ההתחלה. להפתעתי הרבה ראיתי שזמן ההתחלה אינו משתנה: במשך כחצי שעה נכנסתי כמשתמש זמני, וכל הזמן שעת ההתחלה היתה אותו דבר – 11:11.

הבנתי שהבעיה היא בקוד של יצירת זמני ההתחלה והסיום של רישום המשתמש הזמני  והלכתי לראות הכצעקתה:

$today = time();
$startdate = make_timestamp(date('Y', $today), date('m', $today), date('d', $today), date('H', $today), date('G', $today), 0);

$enddate   = make_timestamp(date('Y', $today), date('m', $today), date('d', $today), date('H', $today) + 2, date('G', $today), 0);

 

כפי שניתן לראות, הקוד משתמש בפונקציה make_timestamp שהיא פונקציה של מוודל. הסתכלתי על החתימה של הפונקציה (הנמצאת גם היא ב-lib/moodlelib.php):

 

function make_timestamp($year, $month=1, $day=1, $hour=0, $minute=0, $second=0, $timezone=99, $applydst=true)

 

עברתי על הפרמטרים שאנו שולחים לפונקציה זאת, כדי לוודא שהם אכן מתאימים למה שהפונקציה מצפה לקבל:

1. במשתנה הראשון אנחנו שולחים שנה: date('Y', $today)
2. במשתנה השני אנחנו שולחים חודש: date('m', $today)
3. במשתנה השלישי אנחנו שולחים יום: date('d', $today)
4. במשתנה הרביעי אנחנו שולחים שעה: date('H', $today)
5. כשהגעתי למשתנה האחרון, נפל האסימון. הפונקציה מצפה לקבל דקות. אבל אנחנו שולחים את הערך הבא: date('<strong>G</strong>', $today):. המשתנה G איננו דקות כפי שהיה מתבקש לפי החתימה, אלא שעות! זה יכול להסביר כמה דברים…

אז מדוע הבאג קרה בחלק מהמחשבים בלבד, ולמה הוא קרה רק מדי פעם. איך זה שלפעמים התאריך שנוצר היה בסדר ולפעמים לא?

התשובה טמונה במה שמחזירה הפונקציה date('G', $today). הפונקציה הזו מחזירה את השעה בפורמט של 24 שעות (24-hour format of an hour without leading zeros). כלומר, בשעה 11 היא מחזירה 11, בשעה 6 בערב היא מחזירה 18. וזהו הפרמטר המועבר לפונקציה make_timestamp בתור דקות! לכן, משתמש שנרשם מתישהו בין 11 ל-12 בבוקר, תאריך ההתחלה שלו נרשם כ-11:11 דקות, לא משנה כמה דקות באמת היו אחרי 11 בעת שהוא נרשם. וזה אומר, שאם הוא נכנס ונרשם ב-10 הדקות הראשונות שלאחר השעה 11, הוא לא יצליח להכנס לקורס משום שתאריך ההתחלה שלו הוא בעתיד. וככל שמתקדמים בשעות היום, זה נהיה גרוע יותר, כשהכי גרוע זה ב-11 בלילה, שם ב-22 הדקות הראשונות של השעה, המשתמש ייתקל בבאג הזה!
(מסקנה: הכי טוב להרשם ב-1 בלילה…)

נקודת האור היחידה בכל המאבק המתיש היתה פשטותו של הפתרון: החלפנו את G ב-i, ובא לציון גואל.

וככה בא על פתרונו הבאג החמקמק ולסוּפֶּר אורח שלום 🙂

יולי 2020: תרגמתי את הפוסט לאנגלית במדיום ושמו The Chase After a Sometimes-Bug. הוא התפרסם תחת הפבליקיישן The Startup.