איתור באגים בפריסת תוכנה עם strace

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

• התוכנה הזו עובדת עבור המפתח, אבל לא עבורי. למה?
• אתמול התוכנה הזו עבדה בשבילי, אבל היום זה לא. למה?

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

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

מה זה סטראס?

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

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

$ strace echo Hello
...Snip lots of stuff...
write(1, "Hellon", 6)                  = 6
close(1)                                = 0
close(2)                                = 0
exit_group(0)                           = ?
+++ exited with 0 +++

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

ברמה הבינארית, קריאת מערכת שונה במקצת מקריאת פונקציה פשוטה, אך רוב התוכנות משתמשות במעטפת בספרייה הרגילה. הָהֵן. הספרייה הסטנדרטית של POSIX C מכילה קריאת פונקציה לִכתוֹב(), המכיל את כל הקוד הספציפי לארכיטקטורה עבור קריאת המערכת לכתוב.

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

• קלט/פלט מסוף
• קלט/פלט רשת
• גישה למערכת קבצים ו-I/O לקבצים
• ניהול משך החיים של חוט תהליך
• ניהול זיכרון ברמה נמוכה
• גישה למנהלי התקנים ספציפיים

מתי להשתמש ב-strace?

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

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

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

דוגמה פשוטה לניפוי באגים

נניח שאתה רוצה להפעיל את אפליקציית השרת המדהימה foo, וזה מה שאתה מוצא:

$ foo
Error opening configuration file: No such file or directory

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

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

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

$ strace -o /tmp/trace foo
Error opening configuration file: No such file or directory
$ cat /tmp/trace
execve("foo", ["foo"], 0x7ffce98dc010 /* 16 vars */) = 0
brk(NULL)                               = 0x56363b3fb000
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=25186, ...}) = 0
mmap(NULL, 25186, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f2f12cf1000
close(3)                                = 0
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
read(3, "177ELF2113 3 > 1 260A2 "..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=1824496, ...}) = 0
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f2f12cef000
mmap(NULL, 1837056, PROT_READ, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f2f12b2e000
mprotect(0x7f2f12b50000, 1658880, PROT_NONE) = 0
mmap(0x7f2f12b50000, 1343488, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x22000) = 0x7f2f12b50000
mmap(0x7f2f12c98000, 311296, PROT_READ, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x16a000) = 0x7f2f12c98000
mmap(0x7f2f12ce5000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1b6000) = 0x7f2f12ce5000
mmap(0x7f2f12ceb000, 14336, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f2f12ceb000
close(3)                                = 0
arch_prctl(ARCH_SET_FS, 0x7f2f12cf0500) = 0
mprotect(0x7f2f12ce5000, 16384, PROT_READ) = 0
mprotect(0x56363b08b000, 4096, PROT_READ) = 0
mprotect(0x7f2f12d1f000, 4096, PROT_READ) = 0
munmap(0x7f2f12cf1000, 25186)           = 0
openat(AT_FDCWD, "/etc/foo/config.json", O_RDONLY) = -1 ENOENT (No such file or directory)
dup(2)                                  = 3
fcntl(3, F_GETFL)                       = 0x2 (flags O_RDWR)
brk(NULL)                               = 0x56363b3fb000
brk(0x56363b41c000)                     = 0x56363b41c000
fstat(3, {st_mode=S_IFCHR|0620, st_rdev=makedev(0x88, 0x8), ...}) = 0
write(3, "Error opening configuration file"..., 60) = 60
close(3)                                = 0
exit_group(1)                           = ?
+++ exited with 1 +++

בערך כל העמוד הראשון של הפלט שטרס - בדרך כלל מדובר בהכנה ברמה נמוכה להשקה. (הרבה שיחות mmap, mpprotect, BRK לדברים כמו זיהוי זיכרון ברמה נמוכה והצגת ספריות דינמיות.) למעשה, במהלך איתור באגים בפלט שטרס עדיף לקרוא מהסוף. יהיה אתגר למטה לכתוב, שמציגה הודעת שגיאה. אנו מסתכלים למעלה ורואים את קריאת המערכת השגויה הראשונה - הקריאה openat, מה שזורק שגיאה ENOENT ("קובץ או ספרייה לא נמצאו") מנסה להיפתח /etc/foo/config.json. כאן צריך להיות קובץ התצורה.

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

• תתעצבן בגלל הודעה מעורפלת על שגיאת system-y מתוכנית
• הפעל מחדש את התוכנית עם שטרס
• מצא את הודעת השגיאה בתוצאות המעקב
• עלה גבוה יותר עד שתפגע בשיחת המערכת שנכשלה הראשונה

סביר מאוד שהקריאה למערכת בשלב 4 תגלה מה השתבש.

טיפים

לפני שאראה לך דוגמה לניפוי באגים מורכב יותר, אראה לך כמה טריקים לשימוש יעיל שטרס:

גבר הוא חבר שלך

במערכות *nix רבות, ניתן לקבל רשימה מלאה של קריאות מערכת לקרנל על ידי הפעלה גבר מתקשר. אתה תראה דברים כמו brk(2), כלומר ניתן לקבל מידע נוסף על ידי הפעלה גבר 2 ברק.

מגרפה קטנה: מזלג גבר 2 מראה לי את הדף של הקליפה מזלג() в GNU libc, אשר, מסתבר, מיושם על ידי קריאה שיבוט (). התקשר לסמנטיקה מזלג נשאר זהה אם אתה כותב תוכנית באמצעות מזלג(), והפעל מעקב - לא אמצא שיחות מזלג, במקומם יהיו שיבוט (). מגרפות כאלה רק מבלבלות אותך אם אתה מתחיל להשוות את המקור עם הפלט שטרס.

השתמש ב-o כדי לשמור את הפלט לקובץ

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

השתמש ב-s כדי להציג יותר נתוני ארגומנטים

אולי שמתם לב שהחצי השני של הודעת השגיאה אינו מוצג במעקב לדוגמה שלמעלה. זה בגלל שטרס ברירת המחדל מציגה רק את 32 הבתים הראשונים של ארגומנט המחרוזת. אם אתה רוצה לראות עוד, הוסף משהו כמו -ש 128 לשיחה שטרס.

-y מקל על מעקב אחר קבצים, שקעים וכו'.

"הכל הוא קובץ" פירושו שמערכות *nix עושות את כל ה-I/O באמצעות מתארי קבצים, בין אם זה חל על קובץ או רשת או צינורות בין-תהליכים. זה נוח לתכנות, אבל מקשה לעקוב אחר מה באמת קורה כשאתה רואה משותף לקרוא и לכתוב בתוצאות מעקב שיחות המערכת.

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

צרף לתהליך שכבר פועל באמצעות -p**

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

$ strace -p 1337
...system call trace output...

ייתכן שתצטרך זכויות שורש.

השתמש ב-f כדי לפקח על תהליכי צאצא

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

אם אתה חושב שהשגיאה היא בתהליך צאצא, השתמש בהצהרה -f, זה יאפשר את המעקב שלו. החיסרון בכך הוא שהפלט יבלבל אותך עוד יותר. מתי שטרס עוקב אחר תהליך אחד או שרשור אחד, הוא מציג זרם יחיד של אירועי שיחה. כאשר הוא עוקב אחר תהליכים מרובים בו-זמנית, ייתכן שתראה את תחילתה של שיחה מופרעת על ידי הודעה , ואז - צרור קריאות לענפי הוצאה לפועל אחרים, ורק אז - סוף הראשון <...שיחת פוקל התחדשה>. או לפצל את כל תוצאות המעקב לקבצים שונים, גם באמצעות האופרטור -ff (פרטים ב מדריך על שטרס).

סנן עקבות באמצעות -e

כפי שאתה יכול לראות, התוצאה של המעקב היא ערימה אמיתית של כל קריאות המערכת האפשריות. דֶגֶל -e אתה יכול לסנן את המעקב (ראה מַנהִיגוּת על שטרס). היתרון העיקרי הוא שיותר מהר להפעיל מעקב מסונן מאשר לבצע מעקב מלא ואז grep`ב. למען האמת, כמעט תמיד לא אכפת לי.

לא כל הטעויות רעות

דוגמה פשוטה ונפוצה היא תוכנה שמחפשת קובץ בכמה מקומות בו-זמנית, כמו מעטפת שמחפשת ספרייה המכילה קובץ הפעלה:

$ strace sh -c uname
...
stat("/home/user/bin/uname", 0x7ffceb817820) = -1 ENOENT (No such file or directory)
stat("/usr/local/bin/uname", 0x7ffceb817820) = -1 ENOENT (No such file or directory)
stat("/usr/bin/uname", {st_mode=S_IFREG|0755, st_size=39584, ...}) = 0
...

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

הדרכות לתכנות C יכולות לעזור לך להבין קריאות מערכת.

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

דוגמה יותר מורכבת לניפוי באגים

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

bcron - מתזמן עיבוד משימות, יישום נוסף של דמון *nix cron. זה מותקן בשרת, אבל כשמישהו מנסה לערוך את לוח הזמנים, זה מה שקורה:

# crontab -e -u logs
bcrontab: Fatal: Could not create temporary file

בסדר, זה אומר bcron ניסה לכתוב קובץ מסוים, אבל זה לא הלך, והוא לא יודה למה. חֲשִׂיפָה שטרס:

# strace -o /tmp/trace crontab -e -u logs
bcrontab: Fatal: Could not create temporary file
# cat /tmp/trace
...
openat(AT_FDCWD, "bcrontab.14779.1573691864.847933", O_RDONLY) = 3
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f82049b4000
read(3, "#Ansible: logsaggn20 14 * * * lo"..., 8192) = 150
read(3, "", 8192)                       = 0
munmap(0x7f82049b4000, 8192)            = 0
close(3)                                = 0
socket(AF_UNIX, SOCK_STREAM, 0)         = 3
connect(3, {sa_family=AF_UNIX, sun_path="/var/run/bcron-spool"}, 110) = 0
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f82049b4000
write(3, "156:Slogs #Ansible: logsaggn20 1"..., 161) = 161
read(3, "32:ZCould not create temporary f"..., 8192) = 36
munmap(0x7f82049b4000, 8192)            = 0
close(3)                                = 0
write(2, "bcrontab: Fatal: Could not creat"..., 49) = 49
unlink("bcrontab.14779.1573691864.847933") = 0
exit_group(111)                         = ?
+++ exited with 111 +++

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

אם אתה מסתכל על גבר 2 קרא, אתה יכול לראות שהארגומנט הראשון (3) הוא מתאר קובץ, ש-*nix משתמש בו עבור כל עיבודי I/O. כיצד אוכל לגלות מה מייצג מתאר קובץ 3? במקרה הספציפי הזה, אתה יכול לרוץ שטרס עם מפעיל כן (ראה למעלה) וזה יספר לך באופן אוטומטי, אבל כדי להבין דברים כאלה, כדאי לדעת איך לקרוא ולנתח תוצאות מעקב.

המקור של מתאר קובץ יכול להיות קריאות מערכת אחת מיני רבות (הכל תלוי למה מיועד המתאר - קונסולה, שקע רשת, הקובץ עצמו או משהו אחר), אבל בין אם זה יהיה, אנחנו מחפשים שיחות על ידי החזרת 3 (כלומר, אנו מחפשים "= 3" בתוצאות המעקב). בתוצאה זו יש 2 מהם: openat בחלק העליון ו שקע באמצע. openat פותח את הקובץ אבל close(3) אז יראה שהוא נסגר שוב. (גרפה: ניתן לעשות שימוש חוזר בתיאורי קבצים כאשר הם נפתחים וסגורים). שִׂיחָה שקע () מתאים כי זה האחרון לפני לקרוא(), ומסתבר ש-bcrontab עובד עם משהו דרך שקע. השורה הבאה מראה שמתאר הקובץ משויך אליו שקע דומיין של יוניקס בדרך /var/run/bcron-spool.

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

# ss -pl | grep /var/run/bcron-spool
u_str LISTEN 0   128   /var/run/bcron-spool 1466637   * 0   users:(("unixserver",pid=20629,fd=3))

זה מרמז שהמאזין הוא הפקודה inixserver, פועל עם מזהה תהליך 20629. (ובמקרה, הוא משתמש במתאר קובץ 3 בתור השקע.)

הכלי השני באמת שימושי למציאת אותו מידע נקרא לסוף. זה מפרט את כל הקבצים הפתוחים (או מתארי הקבצים) במערכת. או שאתה יכול לקבל מידע על קובץ ספציפי אחד:

# lsof /var/run/bcron-spool
COMMAND   PID   USER  FD  TYPE  DEVICE              SIZE/OFF  NODE    NAME
unixserve 20629 cron  3u  unix  0x000000005ac4bd83  0t0       1466637 /var/run/bcron-spool type=STREAM

תהליך 20629 הוא שרת ארוך חיים, כך שתוכל לצרף אותו אליו שטרס באמצעות משהו כמו strace -o /tmp/trace -p 20629. אם תערוך עבודת cron במסוף אחר, תקבל פלט מעקב עם שגיאה. והנה התוצאה:

accept(3, NULL, NULL)                   = 4
clone(child_stack=NULL, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7faa47c44810) = 21181
close(4)                                = 0
accept(3, NULL, NULL)                   = ? ERESTARTSYS (To be restarted if SA_RESTART is set)
--- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=21181, si_uid=998, si_status=0, si_utime=0, si_stime=0} ---
wait4(0, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], WNOHANG|WSTOPPED, NULL) = 21181
wait4(0, 0x7ffe6bc36764, WNOHANG|WSTOPPED, NULL) = -1 ECHILD (No child processes)
rt_sigaction(SIGCHLD, {sa_handler=0x55d244bdb690, sa_mask=[CHLD], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7faa47ab9840}, {sa_handler=0x55d244bdb690, sa_mask=[CHLD], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7faa47ab9840}, 8) = 0
rt_sigreturn({mask=[]})                 = 43
accept(3, NULL, NULL)                   = 4
clone(child_stack=NULL, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7faa47c44810) = 21200
close(4)                                = 0
accept(3, NULL, NULL)                   = ? ERESTARTSYS (To be restarted if SA_RESTART is set)
--- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=21200, si_uid=998, si_status=111, si_utime=0, si_stime=0} ---
wait4(0, [{WIFEXITED(s) && WEXITSTATUS(s) == 111}], WNOHANG|WSTOPPED, NULL) = 21200
wait4(0, 0x7ffe6bc36764, WNOHANG|WSTOPPED, NULL) = -1 ECHILD (No child processes)
rt_sigaction(SIGCHLD, {sa_handler=0x55d244bdb690, sa_mask=[CHLD], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7faa47ab9840}, {sa_handler=0x55d244bdb690, sa_mask=[CHLD], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7faa47ab9840}, 8) = 0
rt_sigreturn({mask=[]})                 = 43
accept(3, NULL, NULL

(אחרון לְקַבֵּל() לא יושלם בעת המעקב.) שוב, למרבה הצער, תוצאה זו אינה מכילה את השגיאה שאנו מחפשים. אנחנו לא רואים הודעות ש-bcrontag שולח או מקבל מהשקע. במקום זאת, שליטה מלאה בתהליך (לשבט, 4, SIGCHLD וכו') תהליך זה מוליד תהליך ילד, שכפי שניתן לנחש, עושה את העבודה האמיתית. ואם אתה צריך לתפוס את עקבותיה, הוסיפו לשיחה strace -f. זה מה שנגלה כשנחפש את הודעת השגיאה בתוצאה החדשה עם strace -f -o /tmp/trace -p 20629:

21470 openat(AT_FDCWD, "tmp/spool.21470.1573692319.854640", O_RDWR|O_CREAT|O_EXCL, 0600) = -1 EACCES (Permission denied) 
21470 write(1, "32:ZCould not create temporary f"..., 36) = 36
21470 write(2, "bcron-spool[21470]: Fatal: logs:"..., 84) = 84
21470 unlink("tmp/spool.21470.1573692319.854640") = -1 ENOENT (No such file or directory)
21470 exit_group(111)                   = ?
21470 +++ exited with 111 +++

עכשיו, זה משהו. תהליך 21470 מקבל שגיאת "גישה נדחתה" בעת ניסיון ליצור קובץ בנתיב tmp/spool.21470.1573692319.854640 (הנוגע לספריית העבודה הנוכחית). אם רק היינו יודעים את ספריית העבודה הנוכחית, היינו יודעים גם את הנתיב המלא ונוכל להבין מדוע התהליך לא יכול ליצור בה את הקובץ הזמני שלו. למרבה הצער, התהליך כבר יצא, אז אתה לא יכול פשוט להשתמש lsof -p 21470 כדי למצוא את הספרייה הנוכחית, אבל אתה יכול לעבוד בכיוון ההפוך - חפש קריאות מערכת PID 21470 שמשנות את הספרייה. (אם אין כאלה, PID 21470 חייב ירש אותם מההורה שלו, וזה כבר דרך lsof -p לא ניתן לברר.) קריאת מערכת זו היא chdir (מה שקל לברר בעזרת מנועי חיפוש מקוונים מודרניים). והנה התוצאה של חיפושים הפוכים המבוססים על תוצאות המעקב, כל הדרך לשרת PID 20629:

20629 clone(child_stack=NULL, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7faa47c44810) = 21470
...
21470 execve("/usr/sbin/bcron-spool", ["bcron-spool"], 0x55d2460807e0 /* 27 vars */) = 0
...
21470 chdir("/var/spool/cron")          = 0
...
21470 openat(AT_FDCWD, "tmp/spool.21470.1573692319.854640", O_RDWR|O_CREAT|O_EXCL, 0600) = -1 EACCES (Permission denied) 
21470 write(1, "32:ZCould not create temporary f"..., 36) = 36
21470 write(2, "bcron-spool[21470]: Fatal: logs:"..., 84) = 84
21470 unlink("tmp/spool.21470.1573692319.854640") = -1 ENOENT (No such file or directory)
21470 exit_group(111)                   = ?
21470 +++ exited with 111 +++

(אם אתה אבוד, אולי תרצה לקרוא את הפוסט הקודם שלי על *ניהול תהליכים וקונכיות של nix.) לכן, השרת PID 20629 לא קיבל הרשאה ליצור קובץ בנתיב /var/spool/cron/tmp/spool.21470.1573692319.854640. סביר להניח שהסיבה לכך היא הגדרות ההרשאה הקלאסיות של מערכת הקבצים. בוא נבדוק:

# ls -ld /var/spool/cron/tmp/
drwxr-xr-x 2 root root 4096 Nov  6 05:33 /var/spool/cron/tmp/
# ps u -p 20629
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
cron     20629  0.0  0.0   2276   752 ?        Ss   Nov14   0:00 unixserver -U /var/run/bcron-spool -- bcron-spool

שם קבור הכלב! השרת פועל כקרון משתמש, אך רק לשורש יש הרשאה לכתוב לספרייה /var/spool/cron/tmp/. פקודה פשוטה chown cron /var/spool/cron/tmp/ יאלץ bcron לעבוד נכון. (אם זו לא הייתה הבעיה, אז החשוד הבא בסבירות גבוהה הוא מודול אבטחת ליבה כמו SELinux או AppArmor, אז הייתי בודק את יומן הודעות הליבה עם dmesg.)

בסך הכל

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

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

מקור: www.habr.com