Logging

All messages are emitted by id_translation namespace loggers. The id_translation namespace uses the logging.WARNING log level (similar to SQLAlchemy). To enable logs at the ℹ️ INFO level and below, you must explicitly configure the log level.

Verbose logging

Set the global ENABLE_VERBOSE_LOGGING flag (or use enable_verbose_debug_messages()) to enable additional 🪲 DEBUG-level messages. Use the ID_TRANSLATION_VERBOSE variable in containers.

Warning

Verbose logging may emit hundreds of messages for a single translation task!

Note that verbose and 🪲 DEBUG logging are different things; verbose logging may emit hundreds of messages where regular 🪲 DEBUG might only emit a dozen.

Example

The ℹ️ INFO-level messages emitted for a single Translator.translate() class.

[id_translation.fetching]: Finished initialization of 'MemoryFetcher' in 205 μs:
    MemoryFetcher(sources=['category'], return_all=True)

[id_translation.fetching]: Finished initialization of 'SqlFetcher' in 159 ms:
    SqlFetcher('postgresql+pg8000://postgres:***@localhost:5002/sakila',
    sources=['address', 'film', 'language', 'customer', 'country', 'staff',
    'actor', 'city'])

[id_translation.Translator.map]: Finished mapping of 4/6 names in 'DataFrame' in
    4 ms: {'customer_id': 'customer', 'film_id': 'film', 'category_id':
    'category', 'staff_id': 'staff', 'rental_date': None, 'return_date': None}.

[id_translation.fetching]: Finished fetching from 1 sources in 2 ms: ['category'
    x ('id', 'name') x 16/7 IDs].

[id_translation.fetching]: Finished fetching from 3 sources in 24 ms:
    ['customer' x ('last_name', 'id', 'name') x 10/10 IDs], ['film' x ('id',
    'name') x 10/10 IDs], ['staff' x ('last_name', 'id', 'name') x 2/2 IDs].

[id_translation.Translator]: Finished translation of 'DataFrame' in 31 ms.

Since these are 🔑 key event messages, there are corresponding entry events (the messages above all all 'exit'-records). The 'enter'-records, however, are only emitted on the 🪲 DEBUG level.

Key Event Records

Key event messages are emitted at the boundaries of the various stages in the translation process (see the Translation primer and Mapping primer pages). Common fields are listed below.

Key Event Record Structure

Field	Type	Description
task_id	int	Unique task identifier, e.g. for a single translate() call.
event_key	str = class.method:stage	E.g. MultiFetcher.fetch_all:enter (where stage='enter').
seconds	float	Task duration in seconds. Only when stage='exit'.

All key event methods add additional fields that are relevant to the current task and stage. Fields may be added, removed, or change values depending on the stage of the event.

Event-specific fields

Let’s take closer look at the final message. The LogRecord contains additional information that isn’t included in the message itself. The full Translator.translate:exit-record is shown as JSON below.

Translation exit event. Click here to download.

  {
    "name": "id_translation.Translator",
    "msg": "Finished translation of 'DataFrame' in 31 ms.",
    "args": [],
    "levelname": "INFO",
    "levelno": 20,
    "pathname": "<site-packages>/id_translation/_tasks/_translate.py",
    "filename": "_translate.py",
    "module": "_translate",
    "exc_info": null,
    "exc_text": null,
    "stack_info": null,
    "lineno": 174,
    "funcName": "log_key_event_exit",
    "created": 1557606600.493773,
    "msecs": 535.0,
    "relativeCreated": 1392.953872680664,
    "thread": 137920029544576,
    "threadName": "MainThread",
    "processName": "MainProcess",
    "process": 44038,
    "task_id": 20190511,
    "event_key": "Translator.translate:exit",
    "seconds": 0.031172684000921436,
    "duration_ms": {
      "map": 3.8,
      "extract": 0.1,
      "fetch": 25.2,
      "verify": 0.4,
      "insert": 1.5
    },
    "online": true,
    "translatable_type": "pandas.DataFrame",
    "copy": true,
    "reverse": false,
    "name_to_source": {
      "staff_id": "staff",
      "customer_id": "customer",
      "category_id": "category",
      "film_id": "film"
    },
    "message": "Finished translation of 'DataFrame' in 31 ms.",
    "asctime": "2019-05-11T20:30:00"
  }

About 350 messages were emitted since ENABLE_VERBOSE_LOGGING=True. If we were using regular 🪲 DEBUG-logging, about 40 messages would have been emitted instead. The vast majority of the verbose messages relate to mapping and fetcher initialization.

Dummy version of the code that produced the the records.

from logging import basicConfig, DEBUG
from id_translation import Translator
from id_translation.logging import enable_verbose_debug_messages

basicConfig(handlers=[SomeJsonExporter()])

translator = Translator.from_config(main_config, [fetcher_configs..])
with enable_verbose_debug_messages():
    translator.translate(df)

The configs that were used are available here.