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

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

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

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 के साथ पकड़े गए एरर का पूरा ट्रेसबैक सुरक्षित रखना
• यह बताना कि मैसेज f-string के बजाय %s के साथ क्यों लिखे जाते हैं
• 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 के अंदर, लाइन 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)

अध्याय 22 का __name__ वापस आ गया है, बिल्कुल उसी नियम के तहत: जो फ़ाइल चलाई जा रही है वह __main__ है, और इम्पोर्ट किए गए मॉड्यूल का अपना नाम होता है।

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

एक कम दिखाई देने वाला फ़ायदा भी है: नाम डॉट के ज़रिए एक ट्री बनाते हैं, इसलिए 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 सेट कर दिया। फिर main.py का अपना basicConfig(level=logging.DEBUG, ...) चुपचाप अनदेखा हो गया। लाइब्रेरी ने उसे इम्पोर्ट करने वाले प्रोग्राम की लॉगिंग पर क़ब्ज़ा कर लिया।

पकड़े गए एरर का पूरा ट्रेसबैक

अध्याय 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 पूरे ट्रेसबैक को लॉग में सुरक्षित रखता है — और प्रोग्राम फिर भी चलता रहता है।

यही अध्याय 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)

इसका कारण है आलस्य (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) है वह है फ़ॉर्मेटिंग, आर्ग्युमेंट्स का हिसाब नहीं — वे 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:

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

डीबग लॉग वह दिखाता है जो सामान्य लॉग नहीं दिखा सकता। clip वाली पंक्ति के लिए line_total को वास्तव में कॉल किया गया था — DEBUG ... quantity=0 वाली लाइन इसे साबित करती है — और फिर एरर आया। bag वाली पंक्ति के लिए कोई DEBUG लाइन नहीं है, क्योंकि float("eight") उससे पहले ही टूट गया था। दोनों पंक्तियाँ "छोड़ी" गई हैं, और वे अलग-अलग जगहों पर टूटी हैं, जिसे केवल डिबग लेवल ही उजागर करता है।

लेवल एनवायरनमेंट वेरिएबल से आता है, कोड से नहीं। सर्वर पर चलने वाले प्रोग्राम के लिए यह सामान्य तरीका है — किसी फ़ाइल को एडिट करके रिलीज़ करने के बजाय एक वेरिएबल बदलें और प्रोग्राम को दोबारा चलाएँ।

pricing.py कहीं भी basicConfig को कॉल नहीं करता। यह केवल getLogger(__name__) लिखता है और मैसेज भेजता है। वे कहाँ जाते हैं और कितने दिखते हैं, यह पूरी तरह से main का निर्णय है। इसीलिए pricing को टेस्ट करना, या किसी अन्य प्रोग्राम में इसका उपयोग करना, किसी और की लॉगिंग में दखल नहीं देता।

जब कुछ टूटता है

लॉग में कुछ भी दिखाई नहीं देता basicConfig को कॉल नहीं किया गया था, या लेवल बहुत ऊँचा है। डिफ़ॉल्ट लेवल WARNING होता है, इसलिए log.info डिफ़ॉल्ट रूप से अदृश्य रहता है।

मैंने basicConfig को कॉल किया और कुछ नहीं बदला यह केवल एक बार प्रभावी होता है — यदि लॉगिंग कहीं पहले ही शुरू हो चुकी है, तो बाद के कॉल को चुपचाप अनदेखा कर दिया जाता है। इसे शुरुआत में ही एक बार कॉल करें, या force=True पास करें।

main का लेवल या फ़ॉर्मेट असर नहीं कर रहा, और कोई एरर भी नहीं इम्पोर्ट की गई किसी लाइब्रेरी ने ख़ुद basicConfig कॉल किया, और वह main की कॉल से पहले चला। इसलिए main का basicConfig चुपचाप अनदेखा हो गया। लाइब्रेरी से basicConfig हटाइए — लाइब्रेरी में सिर्फ़ getLogger(__name__)।

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

मैंने log.exception का उपयोग किया और कोई ट्रेसबैक नहीं है ट्रेसबैक केवल except ब्लॉक के अंदर ही मिलता है। उसके बाहर, log.error का उपयोग करें।

मैंने python main.py > out.txt चलाया और लॉग फ़ाइल में नहीं है logging stderr पर लिखता है। 2> log.txt, या filename का प्रयोग करें।

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

breakpoint() कुछ नहीं करता PYTHONBREAKPOINT=0 सेट है। इसे हटाएँ।

आपकी बारी

अध्याय 28 में आपने जिस 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 कॉल करें, main.py से अलग लेवल के साथ। अब किसका लेवल माना जाता है — और क्यों?
• जानबूझकर एक KeyError पैदा करें, फिर except ब्लॉक में एक बार log.error(err) और एक बार log.exception("...") लिखें। कौन सा अधिक उपयोगी है, और क्यों?
• log.debug("%s", expensive()) लिखें जहाँ expensive() कुछ प्रिंट करता हो, और लेवल को WARNING पर रखें। क्या expensive() चलता है?
• एक breakpoint() डालें और p, n और c के साथ अंदर पड़ताल करें।

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

आगे क्या है

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

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