אבחון וניהול

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

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

קוראים את אירועי המערכת

בווינדוס יש channels וproviders של אירועים. הprovider מגדיר איזה אירוע נכתב ואילו שדות יש לו, והchannel הוא חלק ממסלול השמירה והקריאה. בממשק המודרני אפשר להגדיר manifest ולכתוב אירועים דרך ETW; נבנה provider משלנו בפרק החקירה. כאן נשתמש בממשק Windows Event Log כדי לקרוא את הראיות שכבר קיימות על שירות המעבדה.

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

$since = (Get-Date).AddMinutes(-15)
Get-WinEvent -FilterHashtable @{
    LogName = 'System'
    ProviderName = 'Service Control Manager'
    StartTime = $since
} -MaxEvents 40 | Select-Object TimeCreated, Id, RecordId, LevelDisplayName, Message

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

אותה קריאה מתוך C++

נכתוב כלי שמוציא עד עשרה אירועים מהסוף, בצורת XML. אנחנו בוחרים XML כדי לראות שדות מובנים ולא לבנות parser שתלוי בניסוח הודעה בעברית או באנגלית. שמרו בקובץ events.cpp.

#define WIN32_LEAN_AND_MEAN
#include <windows.h>
#include <winevt.h>
#include <iostream>
#include <stdexcept>
#include <string>
#include <vector>

#pragma comment(lib, "wevtapi.lib")

struct event_handle {
    EVT_HANDLE value = nullptr;
    explicit event_handle(EVT_HANDLE h = nullptr) : value(h) {}
    event_handle(const event_handle&) = delete;
    event_handle& operator=(const event_handle&) = delete;
    ~event_handle() { if (value) EvtClose(value); }
};
[[noreturn]] void fail(const char* call, DWORD error = GetLastError()) {
    throw std::runtime_error(std::string(call) + ": " + std::to_string(error));
}

int main() {
    try {
        event_handle query(EvtQuery(nullptr, L"System",
            L"*[System[Provider[@Name='Service Control Manager']]]",
            EvtQueryChannelPath | EvtQueryReverseDirection));
        if (!query.value) fail("query");
        for (unsigned count = 0; count < 10; ++count) {
            EVT_HANDLE raw = nullptr;
            DWORD returned = 0;
            if (!EvtNext(query.value, 1, &raw, 1000, 0, &returned)) {
                DWORD error = GetLastError();
                if (error == ERROR_NO_MORE_ITEMS) break;
                fail("next", error);
            }
            event_handle record(raw);
            DWORD bytes = 0;
            DWORD properties = 0;
            if (EvtRender(nullptr, record.value, EvtRenderEventXml,
                          0, nullptr, &bytes, &properties))
                throw std::runtime_error("unexpected empty XML");
            DWORD error = GetLastError();
            if (error != ERROR_INSUFFICIENT_BUFFER) fail("render size", error);
            std::vector<wchar_t> xml((static_cast<std::size_t>(bytes) + sizeof(wchar_t) - 1) / sizeof(wchar_t));
            if (!EvtRender(nullptr, record.value, EvtRenderEventXml,
                           bytes, xml.data(), &bytes, &properties)) fail("render");
            std::wcout << xml.data() << L"\n\n";
        }
    } catch (const std::exception& error) {
        std::cerr << error.what() << '\n';
        return 1;
    }
}

בנו והריצו עם אותם כלי פיתוח מהפרק.

cl /std:c++20 /EHsc /W4 events.cpp
.\events.exe

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

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

מתכננים אירוע שאפשר לחקור

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

{
  "event": "job_finished",
  "schema": 1,
  "service_run": "f7186b49-b40c-4c52-b76e-5bbd39ec8a19",
  "job_id": 41,
  "attempt": 2,
  "stage": "persist_result",
  "result": "failed",
  "error_domain": "win32",
  "error_code": 112,
  "duration_us": 4180
}

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

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

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

שאילתה ניהולית דרך CIM

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

Get-CimInstance -ClassName Win32_Service -Filter "Name='AmitTechLab'" |
    Select-Object Name, State, StartName, StartMode, ProcessId, PathName

הפלט הוא תמונת מצב דרך provider ניהולי. הוא אינו תחליף לtrace של בקשה, ואינו מבטיח ששתי שאילתות נפרדות ראו את אותה הרצה. אפשר לקרוא את חוזה Get-CimInstance ולשים לב להבדל בין קריאת instances לבין הפעלת method שמשנה מצב.

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

מתי לא צריך process קבוע

נניח שכל העבודה היא לייצר דוח פעם ביום ולצאת. ייתכן שמתאים יותר להפעיל תוכנית קצרה באמצעות Task Scheduler. נגדיר trigger, זהות, תנאי הפעלה וכלל למצב שבו הריצה הקודמת עוד פעילה. המתזמן מספק הפעלה לפי תנאים; הוא לא הופך את פעולת יצירת הדוח לidempotent. אפשר לקרוא על מודל המשימות המתוזמנות.

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