טריקים פשוטים לשיפור תחזוקת האפליקציה שלך (חלק 3): מזהי קורלציה ועקיבות מקצה לקצה

מזהי קורלציה ועקיבות מקצה לקצה

TL;DR: כאשר הביצוע חוצה תהליכונים, תורים וזמן, מזהי מתאם הם הדרך האמינה היחידה לשמור על שלמות סיפורי הלוגים.

בחלק 1 (→ מדוע לוגים מפסיקים להיות שימושיים במערכות אמיתיות), ראינו כיצד תבניות logging בסיסיות נכשלות תחת מקביליות ועומס.

בחלק 2 (→ הקשר משתמש מבלי לשבור את העיצוב שלך), הוספנו הקשר משתמש באמצעות MDC, מבלי לזהם את הלוגיקה העסקית.

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

מזהה מתאם

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

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

קיימים גם תרחישים אחרים שבהם זהות המשתמש אינה קיימת או אינה שימושית:

• משתמשי אורח,
• משימות רקע,
• משימות מתוזמנות,
• עיבוד אסינכרוני.

הבה נבחן דוגמה קונקרטית.

❌ בעיה: ביצוע אסינכרוני שובר את הרצף

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

הלוגים נראים כך:

2025-10-25 19:32:25,446 INFO 305188 [t=Thread-2] demo.PrintingDemo Guest used coupon code = ***** : [u=] 2025-10-25 19:32:25,451 INFO 305188 [t=Thread-2] demo.PrintingDemo Guest started payment process : [u=] 2025-10-25 19:32:25,454 INFO 305188 [t=Thread-1] demo.PrintingDemo Guest skipped coupon code : [u=] 2025-10-25 19:32:25,461 INFO 305188 [t=Thread-3] demo.PrintingDemo Guest skipped coupon code : [u=] 2025-10-25 19:32:25,548 INFO 305188 [t=Thread-1] demo.PrintingDemo Guest started payment process : [u=] 2025-10-25 19:32:25,567 INFO 305188 [t=Thread-3] demo.PrintingDemo Guest started payment process : [u=] 2025-10-25 19:32:25,772 INFO 305188 [t=Async--6] demo.PrintingDemo Guest aborted payment : [u=] 2025-10-25 19:32:25,967 INFO 305188 [t=Async--7] demo.PrintingDemo Guest finished payment : [u=] 2025-10-25 19:32:26,231 INFO 305188 [t=Async--8] demo.PrintingDemo Guest finished payment : [u=]

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

מהלוגים אלה בלבד, בלתי אפשרי לקבוע. Thread ID לא יעזור כאן, מכיוון שהשלמת התשלום פועלת על מאגר threads שונה. PID גם לא יעזור. User ID לא קיים.

יש לנו את כל האירועים, אך אין דרך מהימנה לדעת אילו מהם שייכים יחד.

✅ פתרון: המצא מזהה ביצוע

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

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

מזהה מתאם מייצג הרצה בודדת, ללא תלות ב:

• כמה תהליכונים מעורבים,
• האם הביצוע סינכרוני או אסינכרוני,
• או כמה זמן זה לוקח.

בטיחות מול קריאות

בחירת פורמט correlation ID מתאים כרוכה באיזון בין ייחודיות (בטיחות) לקריאות (שמישות תפעולית).

UUID סטנדרטי הוא האפשרות הבטוחה ביותר:

4d2108d1-35a6-41a3-9ed2-1b146c78bb9c

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

TSEI0TWmQaOe0hsUbHi7nA==

עם זאת, Base64 מציג עמימות חזותית (0, O, l, I) והוא מועד לשגיאות בעת העתקה ידנית.

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

אסטרטגיית מזהה כפול

אם יש צורך גם בבטיחות וגם בשימושיות טובה, גישה מעשית היא לתעד שני מזהים:

• מזהה קצר וקריא לאדם (לחיפוש ולתקשורת),
• UUID מלא (לוודאות פורנזית).

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

שילוב correlation ID ב-MDC

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

%d{ISO8601} %-5level ${PID} [t=%thread] %-48logger{48} [c=%X{correlationId}] %msg : [u=%X{userId}] %n%throwable | +--- correlation ID …מציג את הקשר בין שורות הלוג

Here:

• %X{correlationId} קורא את הערך מ-MDC,
• כל שורת לוג נושאת כעת זהות ביצוע.

דוגמה מלאה של async

כאשר מזהי קורלציה קיימים, הדוגמה האסינכרונית הקודמת הופכת לקריאה:

2025-10-25 21:05:49,293 INFO 317606 [t=Thread-1] demo.PrintingDemo [c=FB6bA3f] אורח השתמש בקוד קופון = ***** : [u=] 2025-10-25 21:05:49,375 INFO 317606 [t=Thread-1] demo.PrintingDemo [c=FB6bA3f] אורח החל תהליך תשלום : [u=] 2025-10-25 21:05:51,203 INFO 317606 [t=Async--5] demo.PrintingDemo [c=FB6bA3f] אורח ביטל תשלום : [u=]

סינון לוגים לפי מזהה מתאם עונה מיד על השאלה המקורית שלנו: האורח שהשתמש בקופון ביטל את התשלום.

ללא ניחושים וללא שחזור ידני.

מזהה מתאם מעבר ליומנים

מזהי קורלציה הופכים לעוצמתיים אף יותר כאשר הם יוצאים ממערכת הלוגים.

אם נכלול את מזהה המתאם (correlation ID) בתגובות שגיאה של API, דיווח באג של משתמש עשוי להכיל משהו כזה:

{ "timestamp": "2025-10-25T21:43:56Z", "message": "Unable to process order with negative price: -64", "userId": "ferdynand@oo.pl", "error": "Bad request", "status": 400, "method": "POST", "path": "/api/orders", "correlationId": "pHVAVwv" }

אז איתור באגים הופך לפשוט. אנחנו פשוט מחפשים ביומנים את pHVAVwv ורואים מיד את הביצוע המלא:

2025-10-25 21:43:56,210 INFO 326565 [t=Thread-1] demo.PrintingDemo [c=pHVAVwv] Price of item = 64 : [u=ferdynand@oo.pl] 2025-10-25 21:43:56,234 INFO 326565 [t=Thread-1] demo.PrintingDemo [c=pHVAVwv] Due to shortages, quantity lowered by 3 items : [u=ferdynand@oo.pl] 2025-10-25 21:43:56,234 INFO 326565 [t=Thread-1] demo.PrintingDemo [c=pHVAVwv] Items in order = -1 : [u=ferdynand@oo.pl] 2025-10-25 21:43:56,249 ERROR 326565 [t=Thread-1] demo.PrintingDemo [c=pHVAVwv] Malformed request : [u=ferdynand@oo.pljava.lang.IllegalStateException: Unable to process order with negative price: -64 at demo.PrintingDemo.runSequence(PrintingDemo.java:92) at demo.PrintingDemo.lambda$onApplicationReady$0(PrintingDemo.java:66) at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:545) at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:328) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1095) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:619) at java.base/java.lang.Thread.run(Thread.java:1447) 2025-10-25 21:43:56,252 INFO 326565 [t=Thread-1] demo.PrintingDemo [c=pHVAVwv] Request body: {"quantity":2} : [u=ferdynand@oo.pl]

בשלב זה, אין צורך בעבודת בלשים.

הגעה מעבר למשתמשים טכניים

משתמשים לא-טכניים מדווחים לעיתים קרובות על בעיות באמצעות שליחת צילומי מסך. הם עשויים לצלם הודעת שגיאה קופצת (snackbar) במקום תגובת HTTP.

יהיה די קשה למצוא את שורש הבעיה, שלא לומר לעשות זאת במהירות. כבר הרחבנו את הודעות התגובה עם correlation ID. אנו יכולים להוסיף מידע זה לתגובה, מכיוון שהוא אינו סוד. ואם הוא אינו סוד בתגובה, הוא אינו סוד בשום מקום אחר. לכן, מדוע לא לשים אותו ישירות ב-error snackbar?

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

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

מזהה Base58 קצר כגון WpJ9ZWr קל לקרוא, להעתיק ולחפש – שלא כמו מזהה ארוך ועמום חזותית.

על ידי לקיחת מזהה המתאם (correlation ID) מצילום המסך של ה-snackbar הברור (WpJ9ZWr) ובחיפוש במערכת הלוגים שלנו, אנו יכולים למצוא במהירות את פרטי הבקשה הרלוונטיים:

2025-10-25 22:19:52,938 INFO 338180 [t=Thread-1] demo.PrintingDemo [c=WpJ9ZWr] Price of item = 3 : [u=mr.1337@pwnd.it] 2025-10-25 22:19:52,961 INFO 338180 [t=Thread-1] demo.PrintingDemo [c=WpJ9ZWr] Due to shortages, quantity lowered by 3 items : [u=mr.1337@pwnd.it] 2025-10-25 22:19:52,961 INFO 338180 [t=Thread-1] demo.PrintingDemo [c=WpJ9ZWr] Items in order = -1 : [u=mr.1337@pwnd.it] 2025-10-25 22:19:53,150 ERROR 338180 [t=Thread-1] demo.PrintingDemo [c=WpJ9ZWr] Malformed request : [u=mr.1337@pwnd.itjava.lang.IllegalStateException: Unable to process order with negative price: -36 at demo.PrintingDemo.runSequence(PrintingDemo.java:92) at demo.PrintingDemo.lambda$onApplicationReady$0(PrintingDemo.java:66) at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:545) at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:328) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1095) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:619) at java.base/java.lang.Thread.run(Thread.java:1447) 2025-10-25 22:19:53,153 INFO 338180 [t=Thread-1] demo.PrintingDemo [c=WpJ9ZWr] Request body: {"quantity":2} : [u=mr.1337@pwnd.it]

מה אם איש לא ראה את הכשל?

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

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

מסקנה

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

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

עם זאת, הניסיון מלמד כי הרוב המכריע של מערכות הייצור הן עדיין שירותים בודדים או פריסות פשוטות. במקרים אלה, מספר שיפורים קטנים וממוקדים היטב – הקשר משתמש, MDC ומזהי קורלציה – יכולים לצמצם באופן דרמטי את הזמן המושקע בהבנת כשלים.

לפעמים, טריקים פשוטים באמת מספיקים.