ডিবাগিং আর লগিং

যে সমস্যাটা আমরা সমাধান করছি

কিছু একটা ভুল হলে আমরা সবাই যা করি:

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 কোথায় যায় তা কেউ জানে না।

এই অধ্যায়টা দুটো জিনিস নিয়ে: কীভাবে একটা প্রোগ্রাম নিজের কাজের হিসাব রাখে, আর কীভাবে ভাঙা অবস্থায় ভিতরে ঢুকে দেখা যায়।

এই অধ্যায় শেষে আপনি পারবেন

• একটা ট্রেসব্যাক ঠিক ক্রমে পড়তে, আর আসল জায়গাটা খুঁজে বের করতে
• logging দিয়ে বার্তা লিখতে, আর স্তরগুলোর মধ্যে বেছে নিতে
• logging.getLogger(__name__) কেন এভাবে লেখা হয় তা বলতে
• log.exception দিয়ে একটা ধরা পড়া ত্রুটির পুরো ট্রেসব্যাক রাখতে
• %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-এর ভিতরে, লাইন ২।

উপরের দিকটা হলো সেখানে পৌঁছানোর পথ, নিচের দিকে পড়লে: <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-এর লেখাগুলো ফাইলে যাবে আর লগগুলো পর্দায় থেকে যাবে। এই অধ্যায়ের নিচের আউটপুটগুলোতে তাই দুটো ধারা আলাদা করে দেখানো হয়েছে — আগে 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'

নিয়মটা সহজ: except ব্লকের ভিতরে log.exception, বাইরে log.error. exception কেবল একটা ত্রুটি সামলানোর সময়ই অর্থপূর্ণ।

বার্তায় %s, f-string নয়

লগিং-এর বার্তা লেখার প্রচলিত রূপটা একটু অদ্ভুত লাগে:

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

কারণটা হলো অলসতা: স্তরটা যদি বার্তাটাকে বাদ দেয়, তাহলে লেখাটা জোড়াই লাগানো হয় না। 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 <নাম> — একটা মান ছাপে (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 নিজেও quantity=0-এর জন্য একটা ValueError তোলে। চতুর্বিংশ অধ্যায়ের নকশাটা এখানে কাজে লাগছে: নিচের স্তর ছুঁড়েছে, উপরের স্তর ধরেছে আর ঠিক করেছে কী করা হবে।

ডিবাগ লগটা দেখাচ্ছে যা সাধারণ লগ দেখায় না। clip সারিটার জন্য line_total সত্যিই ডাকা হয়েছিল — DEBUG ... quantity=0 লাইনটা তার প্রমাণ — আর তারপর সে ছুঁড়েছে। bag সারিটায় কোনো DEBUG লাইন নেই, কারণ float("eight") তার আগেই ভেঙেছে। দুটো সারিই «বাদ পড়া», কিন্তু তারা দুই জায়গায় ভেঙেছে, আর সেটা কেবল ডিবাগ স্তরেই দেখা যায়।

স্তরটা পরিবেশ থেকে আসছে, কোড থেকে নয়। সার্ভারে চলা একটা প্রোগ্রামে এটাই স্বাভাবিক উপায় — একটা পরিবেশ চলক বদলে আবার চালানো, ফাইল সম্পাদনা করে নতুন করে ছাড়া নয়।

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 ফাইলগুলো, কিন্তু হাজার হাজার সারি নিয়ে, আর প্রশ্নগুলো যেখানে লুপ দিয়ে উত্তর দেওয়া আর বাস্তবসম্মত নয়।