تنقيح الأخطاء والتسجيل

المشكلة التي نقوم بحلها

هذا ما يفعله الجميع عندما تسوء الأمور في الكود:

def discount(price, rate):
    print("price:", price)
    print("rate:", rate)
    result = price * (1 - rate)
    print("result:", result)
    return result


print(discount(100.0, 0.1))

price: 100.0
rate: 0.1
result: 90.0
90.0

هذا الأسلوب يفي بالغرض مؤقتاً. لكن المشكلة تبدأ فيما يلي ذلك.

إذا حذفت أسطر الطباعة تلك، فستضطر لإعادة كتابتها في المرة القادمة التي تحدث فيها مشكلة. وإن تركتها، فستبقى تشوه الكود البرمجي، وقد تُطبع يوماً ما على شاشة مستخدم حقيقي في بيئة العمل. كما أن البرامج التي تعمل على خوادم السحاب لا تملك شاشات أو طرفيات أصلاً — ولا أحد يدري أين تذهب تلك النصوص المطبوعة عبر print.

يتناول هذا الفصل أمرين أساسيين: كيف يحتفظ البرنامج بسجل رسمي لأعماله وأحداثه، وكيف تتسلل إلى داخل الكود وهو يعمل لاستكشاف ما يجري أثناء حدوث الخلل.

في نهاية هذا الدرس ستكون قادراً على

• قراءة تقرير تتبع الخطأ (Traceback) بالترتيب الصحيح وتحديد الموقع الحقيقي للمشكلة
• كتابة رسائل المتابعة باستخدام وحدة logging والاختيار المناسب بين مستوياتها
• شرح سبب كتابة logging.getLogger(__name__) بهذه الطريقة تحديداً
• الاحتفاظ بكامل تتبع الاستثناء الملتقط في السجلات عبر log.exception
• توضيح سبب كتابة رسائل التسجيل باستخدام %s بدلاً من نصوص f-strings
• إيقاف البرنامج مؤقتاً أثناء تشغيله والتجول في داخله باستخدام breakpoint()

المتطلبات السابقة: كتابة الاختبارات باستخدام pytest.

تتبع الأخطاء يُقرأ من الأسفل إلى الأعلى!

def parse(text):
    return int(text)


def total(rows):
    return sum(parse(row) for row in rows)


print(total(["1", "2", "x"]))

Traceback (most recent call last):
  File "main.py", line 9, in <module>
    print(total(["1", "2", "x"]))
          ^^^^^^^^^^^^^^^^^^^^^^
  File "main.py", line 6, in total
    return sum(parse(row) for row in rows)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "main.py", line 6, in <genexpr>
    return sum(parse(row) for row in rows)
               ^^^^^^^^^^
  File "main.py", line 2, in parse
    return int(text)
           ^^^^^^^^^
ValueError: invalid literal for int() with base 10: 'x'

يصاب الكثير من المبرمجين بالذعر عند رؤية هذا السيل من النصوص الحمراء، ويبدأون القراءة من أعلى سطر. لكن الترتيب الصحيح هو العكس تماماً.

السطر الأخير هو الأهم على الإطلاق — يخبرك بما حدث، ومع أي قيمة تحديداً: فالرمز 'x' ليس رقماً صالحاً.

الكتلة الواقعة فوقه مباشرة تأتي في المرتبة الثانية — توضح أين حدث الخطأ: داخل دالة parse، في السطر الثاني.

الجزء العلوي يوضح المسار الذي قاد إلى هناك، وتتم قراءته من الأعلى نزولاً: الاستدعاء الرئيسي في الملف استدعى total، و total استدعت المولد التكراري، والمولد استدعى parse. ونحتاج هذا الجزء عندما يكون السؤال: "أي استدعاء هو الذي مرر القيمة الفاسدة؟".

وعلامات ^^^^ توضح بدقة أي جزء محدد من السطر انكسر — وهو أمر بالغ الفائدة في الأسطر الطويلة.

ابحث دائماً عن أدنى إطار (Frame) يمثل كودك أنت. حتى لو كان نصف التقرير مليئاً بملفات المكتبات الخارجية، فإن الخلل يكمن دائماً تقريباً في آخر سطر من كودك الخاص.

استخدام logging بدلاً من print

import logging

logging.basicConfig(level=logging.INFO, format="%(levelname)s %(name)s - %(message)s")

log = logging.getLogger("shop")

log.debug("this is not shown")
log.info("starting")
log.warning("price is unusually high: %s", 9999)
log.error("could not read the file")

INFO shop - starting
WARNING shop - price is unusually high: 9999
ERROR shop - could not read the file

رسالة debug غابت تماماً عن المخرجات، لأن مستوى التسجيل محدد بـ INFO. وهذا هو الفارق الجوهري عن print: تبقى رسائل التسجيل محفوظة في الكود، وأنت وحدك من يقرر متى تظهر وأيها يُعرض.

هناك خمسة مستويات قياسية، وترتيبها هو تعريفها ذاته:

import logging

logging.basicConfig(level=logging.WARNING, format="%(levelname)s - %(message)s")

log = logging.getLogger("shop")

log.debug("debug")
log.info("info")
log.warning("warning")
log.error("error")
log.critical("critical")

WARNING - warning
ERROR - error
CRITICAL - critical

متى نستخدم كل مستوى منها؟ سطر واحد لكل منها:

• debug — تفاصيل داخلية دقيقة، لا نحتاجها إلا أثناء البحث عن علة خفية
• info — أحداث طبيعية روتينية: بدأ البرنامج، قُرئ 500 سطر، اكتملت المهمة
• warning — أمر غير معتاد حدث، لكن البرنامج قادر على مواصلة عمله
• error — فشلت مهمة أو عملية واحدة محددة، دون أن ينهار البرنامج بأكمله
• critical — حدث انهيار كارثي لا يمكن للبرنامج الاستمرار بعده

تكتب وحدة logging في مجرى stderr بينما تكتب print في stdout. يظهر كلاهما في شاشة الطرفية عادة دون تفريق — لكن عند تشغيل python main.py > out.txt، تذهب مخرجات print فقط إلى الملف بينما تبقى رسائل السجل ظاهرة على الشاشة. ولهذا السبب تفصل الأمثلة أدناه بين مجريي المخرجات لتوضيح الفرق؛ وعلى جهازك ستتداخل الأسطر بترتيبها الزمني الطبيعي.

__name__ — اسم الوحدة النمطية هو اسم المسجل

import logging

log = logging.getLogger(__name__)


def line_total(price, quantity):
    log.debug("line_total(%s, %s)", price, quantity)
    return round(price * quantity * 1.15, 2)

وفي ملف main.py:

import logging

import pricing

logging.basicConfig(level=logging.DEBUG, format="%(levelname)s %(name)s - %(message)s")

log = logging.getLogger(__name__)

log.info("starting")
print(pricing.line_total(15.0, 3))

51.75

INFO __main__ - starting
DEBUG pricing - line_total(15.0, 3)

المتغير __name__ من الفصل الثاني والعشرين يعود هنا بنفس القاعدة تماماً: الملف الذي تشغله مباشرة يحمل الاسم __main__، والوحدة المستوردة تحمل اسمها الفعلي.

وتظهر الفائدة مباشرة في السجل — فكل رسالة تعلن صراحة عن مصدرها والملف الذي أطلقها. وفي مشروع يتكون من عشرين ملفاً، هذا هو الفارق بين الوضوح التام والضياع.

وهناك ميزة خفية إضافية: تشكل الأسماء شجرة هرمية مفصولة بنقاط، بحيث يمكن رفع مستوى التفاصيل لوحدة shop.pricing وحدها بينما تظل بقية أجزاء النظام هادئة.

إياك أن تستدعي basicConfig داخل مكتبة برمجية. تكتفي كل وحدة فرعية بكتابة getLogger(__name__) وإرسال الرسائل؛ أما تحديد مكان حفظ السجلات ومستواها فهو قرار حصري يخص الملف الرئيسي main. وبما أن الاستيراد يعني تشغيل الملف، فإن استدعاء مكتبة ما لـ basicConfig يصادر ويفسد إعدادات التسجيل لكل من يستوردها.

حفظ كامل تقرير الخطأ للاستثناءات الملتقطة

تعلمنا في الفصل الرابع والعشرين كيفية التقاط الأخطاء. لكن التقاط الخطأ لا ينبغي أن يعني فقدان تفاصيله الثمينة.

import logging

logging.basicConfig(level=logging.INFO, format="%(levelname)s - %(message)s")

log = logging.getLogger("shop")


def parse(text):
    return int(text)


for value in ["1", "x"]:
    try:
        print(parse(value))
    except ValueError:
        log.exception("could not parse %r", value)

print("still running")

1
still running

ERROR - could not parse 'x'
Traceback (most recent call last):
  File "main.py", line 14, in <module>
    print(parse(value))
          ^^^^^^^^^^^^
  File "main.py", line 9, in parse
    return int(text)
           ^^^^^^^^^
ValueError: invalid literal for int() with base 10: 'x'

الأمر log.exception يحتفظ بكامل تقرير تتبع الخطأ في السجل — ويواصل البرنامج عمله بسلاسة دون توقف.

هذا يحل المعضلة الكبرى من الفصل الرابع والعشرين: فكتابة except ... : pass تضيع المعلومات بصمت؛ وعدم استخدام except يوقف البرنامج تماماً. أما log.exception فتجمع أفضل ما في الأمرين: يستمر العمل، ويُحفظ سجل كامل ودقيق لما انكسر.

وعندما تريد تسجيل رسالة خطأ فقط دون التتبع الكامل، استخدم log.error:

import logging

logging.basicConfig(level=logging.INFO, format="%(levelname)s - %(message)s")

log = logging.getLogger("shop")

try:
    int("x")
except ValueError as err:
    log.error("could not parse: %s", err)

print("done")

done

ERROR - could not parse: invalid literal for int() with base 10: 'x'

القاعدة واضحة: استخدم log.exception داخل كتلة except، واستخدم log.error خارجها. فالأمر exception لا يقدم أي معنى إلا أثناء معالجة استثناء نشط.

استخدام %s في الرسائل بدلاً من f-strings

تبدو الطريقة المعتادة لكتابة الرسائل في نظام التسجيل غريبة للوهلة الأولى:

log.debug("line_total(%s, %s)", price, quantity)

السبب وراء ذلك هو التقييم الكسول (Lazy evaluation): إذا كان مستوى التسجيل الحالي يتجاهل رسائل debug، فلن يتم تجميع ودمج النصوص في الذاكرة على الإطلاق. أما لو كُتبت بصيغة f-string، فسيتم تجميع النص أولاً وبذل الجهد الحسابي، ثم يُرمى الناتج بعد ذلك في سلة المهملات.

ولكن يجدر بك معرفة حدود هذا السلوك أيضاً:

import logging

logging.basicConfig(level=logging.WARNING, format="%(levelname)s - %(message)s")

log = logging.getLogger("shop")


def expensive():
    print("expensive() was called")
    return 42


log.debug("value is %s", expensive())
log.debug("value is %s", "cheap")
print("done")

expensive() was called
done

الرسالة لم تُطبع في السجل، ومع ذلك تم استدعاء دالة expensive() وتنفيذها! الشيء "الكسول" هنا هو عملية تنسيق ودمج النصوص فقط، وليس تقييم وسائط الدالة — فالوسائط تُحسب دائماً قبل استدعاء log.debug، لأن هذه هي الطريقة التي تعمل بها كل استدعاءات الدوال في لغة بايثون.

لذا، عندما تكون لديك عمليات ثقيلة لا تحتاجها إلا في وضع التنقيح، تحقق أولاً: if log.isEnabledFor(logging.DEBUG):.

التسجيل في ملف على القرص

import logging
from pathlib import Path

logging.basicConfig(
    level=logging.INFO,
    format="%(levelname)s %(name)s - %(message)s",
    filename="run.log",
)

log = logging.getLogger("shop")
log.info("starting")
log.warning("something odd")

print("nothing was printed to the screen by logging")
print(Path("run.log").read_text(encoding="utf-8"), end="")

nothing was printed to the screen by logging
INFO shop - starting
WARNING shop - something odd

بإضافة المعامل filename، تذهب الرسائل إلى ملف على القرص بدلاً من الشاشة — ودون تعديل سطر واحد في كودك البرمجي. وهنا يتضح الفارق الشاسع بين print و logging: الوحدات النمطية تقرر ما يجب تسجيله، والملف الرئيسي main يقرر أين تذهب تلك السجلات.

وفي التطبيقات العملية، يُضاف الوقت والتاريخ إلى صيغة format:

format="%(asctime)s %(levelname)-8s %(name)s - %(message)s"

مما يضع طابعاً زمنياً في بداية كل سطر. وتتجاهل الأمثلة في هذا الفصل ذلك عمداً حتى تتطابق المخرجات تماماً مع ما تراه على جهازك عند القراءة.

التسلل إلى داخل الكود — breakpoint()

يخبرك السجل بما حدث. ولكن في بعض الأحيان، ما تحتاجه حقاً هو معرفة الحالة الراهنة الآن في هذه اللحظة بالذات.

def discount(price, rate):
    result = price * (1 - rate)
    breakpoint()
    return result


print(discount(100.0, 0.1))

عند وصول التنفيذ إلى breakpoint()، يتوقف البرنامج مؤقتاً وتظهر لك موجه أوامر تفاعلي. وتبدو الجلسة هكذا — حيث يحمل السطر الأول المسار الكامل لملفك:

> .../main.py(4)discount()
-> return result
(Pdb) p price
100.0
(Pdb) p rate
0.1
(Pdb) p result
90.0
(Pdb) c
90.0

بضع أوامر بسيطة تغطي معظم ما تحتاجه:

• p <name> — لطباعة قيمة متغير (pp لطباعته بتنسيق منمق)
• n — الانتقال إلى السطر التالي (Next)، دون الدخول في جوف دالة مستدعاة
• s — الدخول في جوف الدالة المستدعاة خطوة بخطوة (Step)
• c — مواصلة التنفيذ حتى نقطة التوقف التالية (Continue)
• l — عرض الكود المحيط بنقطة التوقف الحالية (List)
• q — إنهاء الجلسة والخروج من البرنامج (Quit)

الميزة الهائلة هنا مقارنة بـ print هي أنك لست مضطراً لأن تقرر مسبقاً ما تريد رؤيته. فبمجرد توقف البرنامج، يمكنك فحص أي متغير وتشغيل أي تعبير برمجي بحرية تامة.

مثال متكامل

ملف pricing.py:

"""Prices and tax, with logging instead of prints."""

import logging

log = logging.getLogger(__name__)

TAX_RATE = 0.15


def line_total(price, quantity):
    log.debug("line_total(price=%s, quantity=%s)", price, quantity)
    if quantity < 1:
        raise ValueError(f"quantity must be at least 1: {quantity}")
    return round(price * quantity * (1 + TAX_RATE), 2)


def read_order(rows):
    """Returns the usable lines, logging and skipping the rest."""
    lines = []
    for number, row in enumerate(rows, start=1):
        try:
            name, price, quantity = row.split(",")
            lines.append((name, line_total(float(price), int(quantity))))
        except ValueError:
            log.warning("line %d skipped: %r", number, row)
    log.info("%d of %d lines usable", len(lines), len(rows))
    return lines

ملف main.py:

import logging
import os

import pricing

logging.basicConfig(
    level=logging.DEBUG if os.environ.get("SHOP_DEBUG") else logging.INFO,
    format="%(levelname)-8s %(name)s - %(message)s",
)

log = logging.getLogger(__name__)

ROWS = ["pen,15.0,3", "bag,eight,1", "ink,120.0,2", "clip,5.0,0"]


def main():
    log.info("reading %d rows", len(ROWS))
    for name, amount in pricing.read_order(ROWS):
        print(f"{name:<6} {amount:>9.2f}")


if __name__ == "__main__":
    main()

عند التشغيل العادي python main.py — تظهر الأسطر المطبوعة:

pen        51.75
ink       276.00

وفي السجل:

INFO     __main__ - reading 4 rows
WARNING  pricing - line 2 skipped: 'bag,eight,1'
WARNING  pricing - line 4 skipped: 'clip,5.0,0'
INFO     pricing - 2 of 4 lines usable

والآن عند تشغيل الكود ذاته مع تفعيل SHOP_DEBUG=1:

INFO     __main__ - reading 4 rows
DEBUG    pricing - line_total(price=15.0, quantity=3)
WARNING  pricing - line 2 skipped: 'bag,eight,1'
DEBUG    pricing - line_total(price=120.0, quantity=2)
DEBUG    pricing - line_total(price=5.0, quantity=0)
WARNING  pricing - line 4 skipped: 'clip,5.0,0'
INFO     pricing - 2 of 4 lines usable

خمسة أمور جديرة بالدراسة:

برنامج واحد، ومستويان من المخرجات، دون أي تعديل في سطر برمجي واحد. هذا هو جوهر هذا الفصل باختصار. فلو استُخدمت print، لما انتهت أبداً الدوامة المرهقة لإضافة أسطر الطباعة ثم حذفها.

تخطي سطر bag,eight,1 وسطر clip,5.0,0 لسببين مختلفين تماماً، وكتلة except ValueError واحدة التقطت كليهما. تحويل float("eight") أطلق ValueError، ودالة line_total أطلقت استثناءً بنفسها بسبب quantity=0. تصميم الفصل الرابع والعشرين في أبهى صوره: المستوى الأدنى يطلق الخطأ، والمستوى الأعلى يلتقطه ويقرر التصرف المناسب بشأنه.

سجل التنقيح يكشف ما يعجز السجل العادي عن إظهاره. بالنسبة لسطر clip، تم استدعاء line_total بالفعل — والسطر DEBUG ... quantity=0 يثبت ذلك — ثم انكسر بعدها. أما سطر bag فلا يحتوي على سطر DEBUG، لأن float("eight") انكسر قبله. كلا السطرين صُنفا على أنهما "تم تخطيهما"، لكنهما انكسرا في مكانين مختلفين كلياً، وهو ما لا يكشفه سوى مستوى debug.

يُحدد مستوى التسجيل من متغيرات البيئة، لا من داخل الكود المكتوب. وهذه هي الطريقة القياسية المتبعة في خوادم الإنتاج — يكفيك تعديل متغير بيئة وإعادة التشغيل، بدلاً من تعديل ملف كود ونشره مجدداً.

ملف pricing.py لا يستدعي basicConfig في أي مكان. إنه يكتفي بكتابة getLogger(__name__) وإرسال الرسائل. أما أين تذهب وكم عدد ما يظهر منها فهو قرار يعود بالكامل لـ main. ولهذا فإن اختبار pricing أو إعادة استخدامه في مشاريع أخرى لن يتدخل في إعدادات التسجيل الخاصة بأحد.

حالات الخطأ الشائعة

لا يظهر أي شيء في السجل لم يتم استدعاء basicConfig إطلاقاً، أو أن مستوى التسجيل المحدد أعلى من المطلوب. المستوى الافتراضي هو WARNING، لذا فإن رسائل log.info تكون مخفية افتراضياً.

استدعيت basicConfig لكن الإعدادات لم تتغير تسري الإعدادات مرة واحدة فقط — فإذا كان نظام التسجيل قد بدأ بالفعل في مكان ما، فسيتم تجاهل أي استدعاء لاحق بصمت. استدعها مرة واحدة في بداية البرنامج الرئيسي، أو مرر المعامل force=True.

تتكرر كل رسالة مرتين تم استدعاء basicConfig مرتين، أو أن مكتبة مستوردة استدعتها أيضاً. تذكر: لا تضع basicConfig في المكتبات.

لا يتم حفظ السجلات في الملف المحدد كان نظام التسجيل قد بدأ عمله قبل تحديد المعامل filename. وتنطبق هنا قاعدة "المرة الواحدة" مجدداً.

استخدمت log.exception ولم يظهر تقرير التتبع (Traceback) لا يظهر التقرير إلا إذا كان الاستدعاء واقعاً داخل كتلة except. وخارجها، استخدم log.error.

شغّلت python main.py > out.txt ولم أجد السجلات في الملف تكتب وحدة logging في مجرى stderr. استخدم إعادة التوجيه 2> log.txt، أو حدد filename.

تقرير التتبع طويل جداً وكل أسطره تتبع ملفات المكتبات اقرأ التقرير من الأسفل إلى الأعلى، وابحث عن أدنى إطار يمثل كودك أنت. المشكلة تكمن هناك دائماً تقريباً.

الأمر breakpoint() لا يوقف البرنامج متغير البيئة PYTHONBREAKPOINT=0 مفعل. قم بإلغائه.

دورك الآن

عد إلى ملف library.py من الفصل الثامن والعشرين واستبدل كل عبارة print بنظام logging.

• ضع log = logging.getLogger(__name__) في السطر الأول من الوحدة
• أضف رسالة debug داخل add() مع ذكر عنوان الكتاب
• أضف رسالة warning عند تخطي بيانات معيبة
• أنشئ ملف main.py يستدعي basicConfig ويأخذ مستوى التسجيل من متغير بيئة
• تأكد من عدم استدعاء basicConfig في library.py

ثم أجرِ هذه التجارب الست:

• شغّل البرنامج على مستوى INFO، ثم على مستوى DEBUG. هل احتجت لتعديل أي سطر في الكود؟
• أضف filename="run.log" إلى basicConfig. ماذا يتبقى معروضاً على الشاشة؟
• استدعِ basicConfig في ملف library.py أيضاً. ماذا يحدث لرسائل السجل؟
• تسبب في خطأ KeyError متعمداً، ثم في كتلة except اكتب log.error(err) مرة واكتب log.exception("...") مرة أخرى. أيهما أكثر فائدة، ولماذا؟
• اكتب log.debug("%s", expensive()) حيث تطبع الدالة expensive() نصاً، واحتفظ بالمستوى عند WARNING. هل يتم تنفيذ دالة expensive()؟
• ضع breakpoint() وتجول في داخل الكود باستخدام الأوامر p و n و c.

التجربة الرابعة هي الكلمة الختامية لهذا الفصل. تُعرف جودة وصحة عمل البرنامج من الأثر الذي يتركه وراءه — وكتلة except التي لا تترك أثراً لم تفعل سوى تأجيل السؤال عن المشكلة لوقت لاحق.

الخطوة التالية

هنا تنتهي هذه الدورة التدريبية في بايثون. بعد تسعة وعشرين فصلاً ثرياً، أصبحت قادراً على كتابة البرامج، والتعامل مع الأعطال، واختبار الكود بدقة، ومعرفة ما يجري بداخله — وهذه المهارات الثلاث الأخيرة تحديداً هي ما يبقي أي برنامج حياً ومستقراً إلى ما بعد يومه الأول.

الخطوة التالية لم تعد مجرد تعلم لغة البرمجة، بل بناء إنجازات حقيقية بها. ودورة مكتبة pandas تبدأ من هنا تحديداً: نفس ملفات CSV التي درسناها في الفصل الخامس والعشرين، ولكن مع آلاف الصفوف والبيانات الضخمة، والأسئلة المعقدة التي لم تعد الحلقات التكرارية البسيطة كافية للإجابة عنها.