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

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

هذا ما نفعله جميعاً عندما يحدث خطأ ما:

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

هذا ينجح. المشكلة هي ما يحدث بعد ذلك.

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

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

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

• قراءة traceback بالترتيب الصحيح، وإيجاد المكان الحقيقي للمشكلة
• كتابة الرسائل باستخدام logging، والاختيار بين المستويات
• شرح لماذا تُكتب logging.getLogger(__name__) بهذا الشكل
• الاحتفاظ بالـtraceback الكامل لخطأ تم التقاطه باستخدام log.exception
• شرح لماذا كتابة الرسائل بـ%s أفضل
• التوقف داخل برنامج يعمل باستخدام breakpoint()

ما تحتاج معرفته أولاً: كتابة الاختبارات باستخدام pytest.

الـtraceback يُقرأ من الأسفل

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، في السطر 2.

الجزء العلوي هو الطريق الذي أوصل إلى هناك، إذا قرأته من الأعلى إلى الأسفل: <module> استدعت total، وtotal استدعت المولّد (generator)، والمولّد استدعى parse. هذا الجزء لا تحتاجه إلا عندما يكون السؤال: “أي استدعاء أرسل هذه القيمة الخاطئة؟”

وعلامات ^^^^ تُظهر أي جزء من السطر انكسر — وهذا أنفع ما يكون في سطر طويل.

ابحث عن أدنى إطار (frame) من كودك أنت. حتى لو كان نصف الـtraceback ملفات مكتبات، فالمشكلة في الغالب تقريباً في آخر سطر من كودك.

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 — أحداث عادية: بدأ البرنامج، قُرئ كذا سطراً، انتهى
• warning — شيء غير معتاد، لكن العمل مستمر
• error — فشلت مهمة، لكن البرنامج ما زال يعمل
• critical — البرنامج نفسه لم يعد يستطيع الاستمرار

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

__name__ — اسم الوحدة هو اسم الـlogger

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__ من الفصل 22 يعود هنا، بالقاعدة نفسها تماماً: الملف الذي يُشغَّل اسمه __main__، والوحدة (module) المستوردة لها اسمها الخاص.

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

وهناك فائدة أقل ظهوراً: الأسماء تُكوّن شجرة بالنقاط، لذا يمكن تغيير مستوى shop.pricing وحده، بينما تبقى سجلات بقية البرنامج كما هي.

لا تستدعِ basicConfig في مكتبة. كل وحدة تكتب فقط getLogger(__name__) وترسل الرسائل؛ أين تذهب وكم منها يظهر — هذا قرار main.

السبب يتضح بجمع قاعدتين. الاستيراد يعني تشغيل الملف. وbasicConfig تعمل في المرة الأولى فقط — بعد إعداد السجل مرة، لا تفعل الاستدعاءات اللاحقة شيئاً بصمت. لنفترض أن pricing.py تستدعي basicConfig بنفسها خطأً:

import logging

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

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 السابق مرة أخرى دون أي تغيير:

51.75

هذا كل شيء — لا أسطر سجل، ولا أي خطأ أيضاً. main.py نفّذ import pricing أولاً، فعملت basicConfig الخاصة بالمكتبة أولاً وضبطت المستوى على WARNING. ثم تُجوهلت بصمت basicConfig(level=logging.DEBUG, ...) الخاصة بـmain.py. لقد استولت المكتبة على سجلّ البرنامج الذي استوردها.

الـtraceback الكامل لخطأ تم التقاطه

في الفصل 24 تعلّمنا التقاط الأخطاء. لكن الالتقاط لا يعني أن نفقد المعلومة.

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 تحفظ الـtraceback كاملاً في السجل — ومع ذلك يستمر البرنامج في العمل.

وهذا هو حل المعضلة من الفصل 24. 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'

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

%s في الرسالة، لا f-string

الشكل المعتاد لكتابة رسائل السجل يبدو غريباً قليلاً في البداية:

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

السبب هو التأجيل (lazy formatting): إذا استُبعدت الرسالة بسبب المستوى، فلا يُركَّب النص أصلاً. أما مع 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() يتوقف البرنامج ويعطيك موجّهاً (prompt). تبدو الجلسة هكذا — وفي السطر الأول سيظهر المسار الكامل لملفك:

> .../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 — ينتقل إلى السطر التالي، دون الدخول داخل الدالة
• s — يدخل داخل الدالة
• c — يستمر حتى التوقف التالي
• l — يعرض الكود المحيط
• q — يخرج

الفائدة مقارنة بـ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 نفسها تُطلق ValueError بسبب quantity=0. تصميم الفصل 24 يعمل هنا: الدالة الأدنى أطلقت الخطأ، والدالة الأعلى التقطته وقررت ماذا تفعل.

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

المستوى يأتي من متغير بيئة (environment variable)، لا من الكود. في برنامج يعمل على خادم هذه هي الطريقة المعتادة — تغيير متغير بيئة وإعادة التشغيل، لا تعديل ملف ونشره من جديد.

pricing.py لا تستدعي basicConfig في أي مكان. إنها تكتب فقط getLogger(__name__) وترسل الرسائل. أين تذهب وكم منها يظهر — كله قرار main. لذلك عند اختبار pricing أو استخدامها في برنامج آخر، لا تستولي على سجلّ أحد.

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

لا يظهر شيء من السجل لم تُستدعَ basicConfig، أو المستوى مرتفع جداً. المستوى الافتراضي WARNING، لذا لا تظهر log.info افتراضياً.

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

مستوى main أو صيغتها بلا تأثير، ولا يوجد أي خطأ مكتبة مستوردة استدعت basicConfig بنفسها، وعمل ذلك قبل استدعاء main. لذلك تُتجاهل basicConfig الخاصة بـmain بصمت. احذف basicConfig من المكتبة — في المكتبة فقط getLogger(__name__).

السجل لا يذهب إلى الملف أُعدّ السجل قبل إعطاء filename. قاعدة “المرة الواحدة” نفسها.

استخدمت log.exception ولا يوجد traceback لا تحصل على الـtraceback إلا داخل كتلة except. خارجها استخدم log.error.

نفّذت python main.py > out.txt والسجلات ليست في الملف logging تكتب في stderr. استخدم 2> log.txt، أو filename.

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

breakpoint() لا تفعل شيئاً PYTHONBREAKPOINT=0 مضبوط. احذفه.

دورك الآن

خذ library.py التي اختبرتها في الفصل 28، واستبدل كل print فيها بـlogging.

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

ثم ست تجارب:

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

التجربة الرابعة هي الكلمة الأخيرة في هذا الفصل. حال البرنامج يُعرف مما يتركه خلفه — وكتلة except لا تترك شيئاً إنما تؤجّل السؤال فقط.

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

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

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