डिबगिंग और लॉगिंग

वह समस्या जिसे हम हल कर रहे हैं

जब कुछ गड़बड़ हो जाती है, तो हर कोई यही करता है:

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 के साथ मैसेज लिखना, और विभिन्न स्तरों (levels) के बीच चुनाव करना
• यह बताना कि logging.getLogger(__name__) को इसी तरह क्यों लिखा जाता है
• log.exception के साथ पकड़े गए एरर का पूरा ट्रेसबैक सुरक्षित रखना
• यह बताना कि मैसेज f-string के बजाय %s के साथ क्यों लिखे जाते हैं
• breakpoint() के साथ चलते हुए प्रोग्राम के अंदर रुकना

ज़रूरी शर्तें: pytest के साथ टेस्टिंग (Testing with 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 के अंदर, लाइन 2 पर।

ऊपर का हिस्सा वह रास्ता है जहाँ से होते हुए यह यहाँ पहुँचा, जिसे ऊपर से नीचे की ओर पढ़ा जाता है: <module> ने total को कॉल किया, total ने जेनरेटर को कॉल किया, और उसने parse को कॉल किया। इस हिस्से की आवश्यकता तब होती है जब सवाल यह हो कि "किस कॉल ने ग़लत वैल्यू भेजी थी"।

और ^^^^ के निशान दिखाते हैं कि लाइन का कौन सा हिस्सा टूटा — किसी लंबी लाइन में यह सबसे उपयोगी होता है।

सबसे निचला वह फ़्रेम ढूँढें जो आपका अपना कोड है। भले ही ट्रेसबैक का आधा हिस्सा लाइब्रेरी फ़ाइलों से भरा हो, समस्या लगभग हमेशा आपके अपने कोड की आखिरी लाइन में होती है।

print के बजाय logging

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 आउटपुट को फ़ाइल में भेजता है और लॉग को स्क्रीन पर छोड़ देता है। यही कारण है कि नीचे दिए गए आउटपुट दोनों स्ट्रीम्स को अलग-अलग दिखाते हैं — पहले प्रिंट की गई लाइनें, फिर लॉग; आपके टर्मिनल पर वे एक साथ मिलकर दिखाई देते हैं।

__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__ है, और इम्पोर्ट किए गए मॉड्यूल का अपना नाम होता है।

इसका फ़ायदा लॉग में साफ़ दिखता है — प्रत्येक मैसेज बताता है कि वह कहाँ से आया है। बीस मॉड्यूल्स वाले प्रोग्राम में यही चीज़ सबसे बड़ा अंतर पैदा करती है।

एक कम दिखाई देने वाला फ़ायदा भी है: नाम डॉट्स के ज़रिए एक पदानुक्रम (tree) बनाते हैं, इसलिए 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'

नियम सरल है: except ब्लॉक के अंदर log.exception, और उसके बाहर log.error। exception का कोई अर्थ केवल तभी होता है जब किसी एरर को हैंडल किया जा रहा हो।

मैसेज में %s, f-string नहीं

लॉगिंग में मैसेज लिखने का पारंपरिक तरीका पहली बार में अजीब लग सकता है:

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

इसका कारण है आलस्य (laziness): यदि लॉगिंग का स्तर उस मैसेज को छोड़ देता है, तो वह टेक्स्ट स्ट्रिंग कभी तैयार ही नहीं की जाती। 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() चला। जो चीज़ लेज़ी (lazy) है वह है फ़ॉर्मेटिंग, तर्कों (arguments) का मूल्यांकन नहीं — वे 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 — अगली लाइन पर जाएँ, किसी फ़ंक्शन के अंदर जाए बिना
• s — फ़ंक्शन के अंदर क़दम रखें (step in)
• c — अगले स्टॉप तक जारी रखें (continue)
• l — आस-पास का कोड देखें
• q — बाहर निकलें (quit)

print की तुलना में इसका फ़ायदा यह है कि आपको पहले से यह तय नहीं करना पड़ता कि आप क्या देखना चाहते हैं। एक बार रुकने के बाद, किसी भी नाम को प्रिंट किया जा सकता है और किसी भी एक्सप्रेशन को चलाकर देखा जा सकता है।

पूर्ण उदाहरण

pricing.py:

"""क़ीमतें और टैक्स, प्रिंट्स के बजाय लॉगिंग के साथ।"""

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):
    """उपयोगी लाइनों को लौटाता है, बाकी को लॉग करता है और छोड़ देता है।"""
    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 देता है, और quantity=0 के लिए line_total खुद एक एरर उठाता है। चौबीसवें अध्याय की रूपरेखा यहाँ काम कर रही है: निचला स्तर एरर फेंकता है, ऊपरी स्तर उसे पकड़ता है और तय करता है कि क्या करना है।

डीबग लॉग वह दिखाता है जो सामान्य लॉग नहीं दिखा सकता। 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 पास करें।

प्रत्येक मैसेज दो बार दिखाई देता है basicConfig को दो बार कॉल किया गया था, या किसी लाइब्रेरी ने भी इसे कॉल किया था। लाइब्रेरीज़ में basicConfig नहीं होना चाहिए।

लॉग फ़ाइल में नहीं जा रहा है filename दिए जाने से पहले ही लॉगिंग शुरू हो चुकी थी। "एक बार" वाला नियम फिर से लागू होता है।

मैंने log.exception का उपयोग किया और कोई ट्रेसबैक नहीं है ट्रेसबैक केवल 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__)
• किताब के शीर्षक के साथ add() में एक debug मैसेज
• ख़राब डेटा छोड़े जाने पर एक warning
• एक main.py जो basicConfig को कॉल करता है और एनवायरनमेंट वेरिएबल से लेवल लेता है
• library.py में basicConfig नहीं होना चाहिए

फिर छह प्रयोग करें:

• लेवल INFO पर चलाएँ, फिर DEBUG पर। क्या किसी कोड को बदलना पड़ा?
• basicConfig में filename="run.log" जोड़ें। स्क्रीन पर क्या बचता है?
• library.py में भी basicConfig को कॉल करें। मैसेजेस के साथ क्या होता है?
• जानबूझकर एक KeyError पैदा करें, फिर except ब्लॉक में एक बार log.error(err) और एक बार log.exception("...") लिखें। कौन सा अधिक उपयोगी है, और क्यों?
• log.debug("%s", expensive()) लिखें जहाँ expensive() कुछ प्रिंट करता हो, और लेवल को WARNING पर रखें। क्या expensive() चलता है?
• एक breakpoint() डालें और p, n और c के साथ अंदर पड़ताल करें।

चौथा प्रयोग इस अध्याय का अंतिम निष्कर्ष है। कोई प्रोग्राम कैसा काम कर रहा है, यह उससे पता चलता है जो वह पीछे छोड़ता है — और एक ऐसा except ब्लॉक जो पीछे कुछ नहीं छोड़ता, उसने केवल सवाल को आगे के लिए टाल दिया है।

आगे क्या है

यह पायथन कोर्स का अंतिम पड़ाव है। उनतीस अध्यायों के बाद, अब आप एक प्रोग्राम लिख सकते हैं, टूटी हुई चीज़ों को संभाल सकते हैं, उसका परीक्षण कर सकते हैं और देख सकते हैं कि वह क्या कर रहा है — और यही अंतिम तीन बातें किसी प्रोग्राम को उसके पहले दिन के बाद भी जीवित रखती हैं।

अगला क़दम अब केवल भाषा सीखना नहीं है, बल्कि उसके साथ कुछ सार्थक करना है। pandas कोर्स ठीक वहीं से शुरू होता है: पच्चीसवें अध्याय की CSV फ़ाइलें, लेकिन हज़ारों पंक्तियों के साथ, और ऐसे सवाल जिनका जवाब पाने के लिए लूप चलाना अब समझदारी भरा तरीका नहीं है।