Python standard logging pattern

(this article originally appeared in Websauna documentation)

Introduction

Python standard library provides logging module as a de facto solution for libraries and applications to log their behavior. logging is extensively used by Websauna, Pyramid, SQLAlchemy and other Python packages.

  • Python logging subsystem can be configured using external configuration file and the logging configuration format is specified in Python standard library.
  • Python logger can be individually turned on, off and their verbosity adjusted on per module basis. For example by default, Websauna development server sets SQLALchemy logging level to INFO instead of DEBUG to avoid flooding the console with verbose SQL logs. However if you are debugging issues related to a database you might want to set the SQLAlchemy logging back to INFO.
  • Logging is preferred diagnose method over print statements cluttered around source code.. Well designed logging calls can be left in the source code and later turned back on if the problems must be diagnosed further.
  • Python logging output can be directed to console, file, rotating file, syslog, remote server, email, etc.

Log colorization

  • Websauna uses rainbow_logging_handler which colorizes the logs, making it easier to read them in the console of the development web server.

logging

Standard logging pattern

A common logging pattern in Python is:

import logging


logger = logging.getLogger(__name__)


def my_view(request):
    logger.debug("my_view got request: %s", request)
    logger.info("my_view got request: %s", request)
    logger.error("my_view got request: %s and BAD STUFF HAPPENS", request)

    try:
        raise RuntimeError("OH NOES")
    except Exception as e:
        # Let's log full traceback even when we ignore this exception
        # and it's not risen again
        logger.exception(e)
  • This names a logger based on a module so you can switch logger on/off on module basis.
  • Pass logged objects to logging.Logger.debug() and co. as full and let the logger handle the string formatting. This allows intelligent display of logged objects when using non-console logging solutions like Sentry.
  • Use logging.Logger.exception() to report exceptions. This will record the full traceback of the exception and not just the error message.

Please note that although this logging pattern is common, it’s not a universal solution. For example if you are creating third party APIs, you might want to pass the logger to a class instance of an API, so that the API consumer can take over the logger setup and there is no inversion of control.

Changing logging level using INI settings

Websauna defines development web server log levels in its core development.ini. Your Websauna application inherits settings from this file and can override them for each logger in the conf/development.ini file of your application.

For example to set SQLAlchemy and transaction logging level to more verbose you can do:

[logger_sqlalchemy]
level = DEBUG

[logger_transaction]
level = DEBUG

Now console is flooded with very verbose logging:

[2016-05-22 20:39:55,429] [sqlalchemy.engine.base.Engine _begin_impl] BEGIN (implicit)
[2016-05-22 20:39:55,429] [txn.123145312813056 __init__] new transaction
[2016-05-22 20:39:55,429] [sqlalchemy.engine.base.Engine _execute_context] SELECT users.password AS users_password, users.id AS users_id, users.uuid AS users_uuid, users.username AS users_username, users.email AS users_email, users.created_at AS users_created_at, users.updated_at AS users_updated_at, users.activated_at AS users_activated_at, users.enabled AS users_enabled, users.last_login_at AS users_last_login_at, users.last_login_ip AS users_last_login_ip, users.user_data AS users_user_data, users.last_auth_sensitive_operation_at AS users_last_auth_sensitive_operation_at, users.activation_id AS users_activation_id

Initialization loggers from INI file

If you need to initialize loggers in your own applications see websauna.system.devop.cmdline.setup_logging() for how Websauna picks up loggers from INI configuration file.

More information

How Websauna logs username and email for every internal server error. It’s impressive service if your devops teams calls a customer on a second an error happens and guide the customer around the error. As a bonus if using Sentry you will see the Gravatar profile image of the user when viewing the exception.

Logbook is an alternative for Python standard library logging if performance is critical or the application has more complex logging requirements .

Discussion about log message formatting and why we are still using old style string formatting.

structlog package – add context to your logged messages like user id or HTTP request URL.

\"\" Subscribe to RSS feed Image Follow me on Twitter Image Follow me on Facebook Image Follow me Google+

Inspecting thread dumps of hung Python processes and test runs

Sometimes, moderately complex Python applications with several threads tend to hang on exit. The application refuses to quit and just idles there waiting for something. Often this is because if any of the Python threads are alive when the process tries to exit it will wait any alive thread to terminate, unless Thread.daemon is set to true.

In the past, it use to be little painful to figure out which thread and function causes the application to hang, but no longer! Since Python 3.3 CPython interpreter comes with a faulthandler module. faulthandler is a mechanism to tell the Python interpreter to dump the stack trace of every thread upon receiving an external UNIX signal.

Here is an example how to figure out why the unit test run, executed with pytest, does not exit cleanly. All tests finish, but the test suite refuses to quit.

First we run the tests and set a special environment variable PYTHONFAULTHANDLER telling CPython interpreter to activate the fault handler. This environment variable works regardless how your Python application is started (you run python command, you run a script directly, etc.)

PYTHONFAULTHANDLER=true py.test

And then the test suite has finished, printing out the last dot… but nothing happens despite our ferocious sipping of coffee.

dotdotdotmoredotsthenthenthedotsstopappearing 
..

How to proceed:

Press CTRL-Z to suspend the current active process in UNIX shell.

Use the following command to send SIGABRT signal to the suspended process.

kill -SIGABRT %1

Voilá – you get the traceback. In this case, it instantly tells SQLAlchemy is waiting for something and most likely the database has deadlocked due to open conflicting transactions.

Fatal Python error: Aborted

Thread 0x0000000103538000 (most recent call first):
  File "/opt/local/Library/Fra%                                                                                                                                                                     meworks/Python.framework/Versions/3.4/lib/python3.4/socketserver.py", line 154 in _eintr_retry
  File "/opt/local/Library/Frameworks/Python.framework/Versions/3.4/lib/python3.4/socketserver.py", line 236 in serve_forever
  File "/Users/mikko/code/trees/pyramid_web20/pyramid_web20/tests/functional.py", line 40 in run
  File "/opt/local/Library/Frameworks/Python.framework/Versions/3.4/lib/python3.4/threading.py", line 921 in _bootstrap_inner
  File "/opt/local/Library/Frameworks/Python.framework/Versions/3.4/lib/python3.4/threading.py", line 889 in _bootstrap

Current thread 0x00007fff75128310 (most recent call first):
  File "/Users/mikko/code/trees/venv/lib/python3.4/site-packages/SQLAlchemy-1.0.0b5-py3.4-macosx-10.9-x86_64.egg/sqlalchemy/engine/default.py", line 442 in do_execute
...
  File "/Users/mikko/code/trees/venv/lib/python3.4/site-packages/SQLAlchemy-1.0.0b5-py3.4-macosx-10.9-x86_64.egg/sqlalchemy/sql/schema.py", line 3638 in drop_all
  File "/Users/mikko/code/trees/pyramid_web20/pyramid_web20/tests/conftest.py", line 124 in teardown
...
  File "/Users/mikko/code/trees/venv/lib/python3.4/site-packages/_pytest/config.py", line 41 in main
  File "/Users/mikko/code/trees/venv/bin/py.test", line 9 in <module>

\"\" Subscribe to RSS feed Image Follow me on Twitter Image Follow me on Facebook Image Follow me Google+

Introducing cryptoassets.core – Bitcoin and cryptocurrency framework for Python

This tutorial introduces cryptoassets.core: what it does for you and how to set up a trivial command-line Bitcoin wallet application on the top of it.

cryptoassets.core is a Python framework providing safe, scalable and future-proof cryptocurrency and cryptoassets accounting for your Python application. You can use it to accept cryptocurrency payments, build cryptoasset services and exchanges.

Benefits

cryptoassets.core is built on the top of Python programming language, community ecosystem and best practices. Python is proven tool for building financial applications and is widely used to develop cryptoassets software and Bitcoin exchanges. cryptoassets.core is

  • Easy: Documented user-friendly APIs.
  • Extensible: Any cryptocurrency and cryptoassets support.
  • Safe: Secure and high data integrity.
  • Lock-in free: Vendor independent and platform agnostics.
  • Customizable: Override and tailor any part of the framework for your specific needs.

Basics

_images/cryptoassets_framework.png

  • You can use cryptoassets.core framework in any Python application, including Django applications. Python 3 is required.
  • cryptoassets.core is designed to be extendable to support altcoins and different cryptoassets.
  • cryptoassets.core works with API services (block.io, blockchain.info) and daemons (bitcoind, dogecoind). The framework uses term backend to refer these. You either sign up for an account on the API service or run the daemon on your own server (*)
  • Basic SQLAlchemy knowledge is required for using the models API.
  • A separate a cryptoassets helper service process is responsible for communicating between your application and cryptoasset networks. This process runs on background on your server.
  • cryptoassets.core framework is initialized from a configuration, which can be passed in as a Python dictionary or a YAML configuration file.
  • For data integrity reasons, cryptoassets.core database connection usually differs from the default application database connection.
  • At the moment cryptoassets.core is in initial version 0.1 release. Expect the scope of the project to expand to support other cryptoassets (Counterparty, Ethereum, BitShares-X) out of the box.

Note: Please note that running bitcoind on a server requires at least 2 GB of RAM and 25 GB of disk space, so low end box hosting plans are not up for the task.

Interacting with cryptoassets.core

The basic programming flow with cryptoassets.core is

  • You set up cryptoassets.core.app.CryptoAssetsApp instance and configure it inside your Python code.
  • You set up a channel how cryptoassets helper service process calls backs your application. Usually this happens over HTTP web hooks.
  • You put your cryptoassets database accessing code to a separate function and decorate it with cryptoassets.core.app.CryptoAssetsApp.conflict_resolver to obtain transaction conflict aware SQLAlchemy session.
  • In your cryptoasset application logic, you obtain an instance to cryptoassets.core.models.GenericWallet subclass. Each cryptoasset has its own set of SQLAlchemy model classes. The wallet instance contains the accounting information: which assets and which transactions belong to which users. Simple applications usually require only one default wallet instance.
  • After having set up the wallet, call various wallet model API methods like cryptoassets.core.models.GenericWallet.send().
  • For receiving the payments you need to create at least one receiving address (see cryptoassets.core.models.GenericWallet.create_receiving_address()). Cryptoassets helper service triggers events which your application listens to and then performs application logic when a payment or a deposit is received.

Example command-line application

Below is a simple command line Bitcoin wallet application using block.io API service as the backend. It is configured to work with Bitcoin Testnet. Testnet Bitcoins are worthless, free to obtain and thus useful for application development and testing.The example comes with pre-created account on block.io. It is recommended that you sign up for your own block.io account and API key and use them instead of ones in the example configuration.

Install cryptoassets.core

Sample Application code

Note: The example is tested only for UNIX systems (Linux and OSX). The authors do not have availability of Microsoft development environments to ensure Microsoft Windows compatibility.

Here is an example walkthrough how to set up a command line application.

Save this as example.py file (see full source code with more comments):

import os
import warnings
from decimal import Decimal
import datetime


from sqlalchemy.exc import SAWarning

from cryptoassets.core.app import CryptoAssetsApp
from cryptoassets.core.configure import Configurator
from cryptoassets.core.utils.httpeventlistener import simple_http_event_listener
from cryptoassets.core.models import NotEnoughAccountBalance

# Because we are using a toy database and toy money, we ignore this SQLLite database warning
warnings.filterwarnings(
    'ignore',
    r"^Dialect sqlite\+pysqlite does \*not\* support Decimal objects natively\, "
    "and SQLAlchemy must convert from floating point - rounding errors and other "
    "issues may occur\. Please consider storing Decimal numbers as strings or "
    "integers on this platform for lossless storage\.$",
    SAWarning, r'^sqlalchemy\.sql\.type_api$')


assets_app = CryptoAssetsApp()

conf_file = os.path.join(os.path.dirname(__file__), "example.config.yaml")
configurer = Configurator(assets_app)
configurer.load_yaml_file(conf_file)

assets_app.setup_session()

@simple_http_event_listener(configurer.config)
def handle_cryptoassets_event(event_name, data):
    if event_name == "txupdate":
        address = data["address"]
        confirmations = data["confirmations"]
        txid = data["txid"]
        print("")
        print("")
        print("Got transaction notification txid:{} addr:{}, confirmations:{}".
            format(txid, address, confirmations))
        print("")


def get_wallet_and_account(session):
    WalletClass = assets_app.coins.get("btc").wallet_model

    wallet = WalletClass.get_or_create_by_name("default wallet", session)
    session.flush()

    account = wallet.get_or_create_account_by_name("my account")
    session.flush()

    # If we don't have any receiving addresses, create a default one
    if len(account.addresses) == 0:
        wallet.create_receiving_address(account, automatic_label=True)
        session.flush()

    return wallet, account

@assets_app.conflict_resolver.managed_transaction
def create_receiving_address(session):
    wallet, my_account = get_wallet_and_account(session)
    wallet.create_receiving_address(my_account, automatic_label=True)


@assets_app.conflict_resolver.managed_transaction
def send_to(session, address, amount):
    """Perform the actual send operation within managed transaction."""
    wallet, my_account = get_wallet_and_account(session)
    friendly_date = datetime.datetime.utcnow().strftime("%Y-%m-%dT%H:%M:%S")
    transaction = wallet.send(my_account, address, amount, "Test send at {}".format(friendly_date))
    print("Created new transaction #{}".format(transaction.id))


def send():
    """Ask how many BTCTEST bitcoins to send and to which address."""
    address = input("Give the bitcoin TESTNET address where you wish to send the bitcoins:")
    amount = input("Give the amount in BTC to send:")

    try:
        amount = Decimal(amount)
    except ValueError:
        print("Please enter a dot separated decimal number as amount.")
        return

    try:
        send_to(address, amount)
    except NotEnoughAccountBalance:
        print("*" * 40)
        print("Looks like your wallet doesn't have enough Bitcoins to perform the send. Please top up your wallet from testnet faucet.")
        print("*" * 40)


@assets_app.conflict_resolver.managed_transaction
def print_status(session):
    """Print the state of our wallet and transactions."""
    wallet, account = get_wallet_and_account(session)

    # Get hold of classes we use for modelling Bitcoin
    # These classes are defined in cryptoassets.core.coin.bitcoind.model models
    Address = assets_app.coins.get("btc").address_model
    Transaction = assets_app.coins.get("btc").transaction_model

    print("-" * 40)
    print("Account #{}, confirmed balance {:.8f} BTC, incoming BTC {:.8f}". \
        format(account.id, account.balance, account.get_unconfirmed_balance()))

    print("")
    print("Receiving addresses available:")
    print("(Send Testnet Bitcoins to them to see what happens)")

    for address in session.query(Address).filter(Address.account == account):
        print("- {}: confirmed received {:.8f} BTC".format(address.address, address.balance))
    print("")
    print("Wallet transactions:")
    for tx in session.query(Transaction):
        if tx.state in ("pending", "broadcasted"):

            # This transactions might not be broadcasted out by
            # cryptoassets helper service yet, thus it
            # does not have network txid yet
            txid = "(pending broadcast)" if tx.state == "pending" else tx.txid

            print("- OUT tx:{} to {} amount:{:.8f} BTC confirmations:{}".format(
                txid, tx.address.address, tx.amount, tx.confirmations))
        elif tx.state in ("incoming", "processed"):
            print("- IN tx:{} to:{} amount:{:.8f} BTC confirmations:{}".format(
                tx.txid, tx.address.address, tx.amount, tx.confirmations))
        else:
            print("- OTHER tx:{} {} amount:{:.8f} BTC".format(
                tx.id, tx.state, tx.amount))

    print("")
    print("Available commands:")
    print("1) Create new receiving address")
    print("2) Send bitcoins to other address")
    print("3) Quit")


print("Welcome to cryptoassets example app")
print("")

running = True
while running:

    print_status()
    command = input("Enter command [1-3]:")
    print("")
    if command == "1":
        create_receiving_address()
    elif command == "2":
        send()
    elif command == "3":
        running = False
    else:
        print("Unknown command!")

Example configuration

Save this as example.config.yaml file (see full source code with more comments):

---

database:
    url: sqlite:////tmp/cryptoassets.example.sqlite

coins:
    btc:
        backend:
            class: cryptoassets.core.backend.blockio.BlockIo
            api_key: b2db-xxxx-xxxx-xxxx
            pin: ThisIsNotVerySecret1
            network: btctest
            walletnotify:
                class: cryptoassets.core.backend.sochainwalletnotify.SochainWalletNotifyHandler
                pusher_app_key: e9f5cc20074501ca7395

events:
    example_app:
        class: cryptoassets.core.event.http.HTTPEventHandler
        url: http://localhost:10000

Creating the database structure

The example application uses SQLite database as a simple self-contained test database.

Run the command to create the database tables:

cryptoassets-initialize-database example.config.yaml

This should print out:

[11:49:16] cryptoassets.core version 0.0
[11:49:16] Creating database tables for sqlite:////tmp/cryptoassets.example.sqlite

Running the example

The example application is fully functional and you can start your Bitcoin wallet business right away. Only one more thing to do…

…the communication between cryptoasset networks and your application is handled by the cryptoassets helper service background process. Thus, nothing comes in or goes out to your application if the helper service process is not running. Start the helper service:

cryptoassets-helper-service example.config.yaml

You should see something like this:

...
[00:23:09] [cryptoassets.core.service.main splash_version] cryptoassets.core version 0.0

Now leave cryptoassets helper service running and start the example application in another terminal:

python example.py

You should see something like this:

Welcome to cryptoassets example app

Receiving addresses available:
(Send testnet Bitcoins to them to see what happens)
- 2MzGzEUyHgqBXzbuGCJDSBPKAyRxhj2q9hj: total received 0.00000000 BTC

We know about the following transactions:

Give a command
1) Create new receiving address
2) Send Bitcoins to other address
3) Quit

Now you can send or receive Bitcoins within your application. If you don’t start the helper service the application keeps functioning, but all external cryptoasset network traffic is being buffered until the cryptoassets helper service is running again.

If you want to reset the application just delete the database file /tmp/cryptoassets.test.sqlite.

Obtaining testnet Bitcoins and sending them

The example runs on testnet Bitcoins which are not real Bitcoins. Get some testnet coins and send them from the faucet to the receiving address provided by the application.

List of services providing faucets giving out Testnet Bitcoins.

No more than 0.01 Bitcoins are needed for playing around with the example app.

After sending the Bitcoins you should see a notification printed for an incoming transaction in ~30 seconds which is the time it takes for the Bitcoin transaction to propagate through testnet:

Got transaction notification txid:512a082c2f4908d243cb52576cd5d22481344faba0d7a837098f9af81cfa8ef3 addr:2N7Fi392deSEnQgiYbmpw1NmK6vMVrVzuwc, confirmations:0

After completing the example

Explore model API documentation, configuration and what tools there are available.

You can also study Liberty Music Store open source application, built on the top of Django and Bitcoin.

Django integration

If you are using Django see cryptoassets.django package.

\"\" Subscribe to RSS feed Image Follow me on Twitter Image Follow me on Facebook Image Follow me Google+