logging.py 11.3 KB
Newer Older
Lysandre Debut's avatar
Lysandre Debut committed
1
2
3
4
5
6
7
8
9
10
11
12
13
14
# coding=utf-8
# Copyright 2020 Optuna, Hugging Face
#
# Licensed under the Apache License, Version 2.0 (the "License");
# you may not use this file except in compliance with the License.
# You may obtain a copy of the License at
#
#     http://www.apache.org/licenses/LICENSE-2.0
#
# Unless required by applicable law or agreed to in writing, software
# distributed under the License is distributed on an "AS IS" BASIS,
# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
# See the License for the specific language governing permissions and
# limitations under the License.
Sylvain Gugger's avatar
Sylvain Gugger committed
15
""" Logging utilities."""
Lysandre Debut's avatar
Lysandre Debut committed
16

17
18

import functools
Lysandre Debut's avatar
Lysandre Debut committed
19
import logging
20
import os
Stas Bekman's avatar
Stas Bekman committed
21
import sys
Lysandre Debut's avatar
Lysandre Debut committed
22
import threading
23
24
25
26
27
28
29
30
31
32
from logging import (
    CRITICAL,  # NOQA
    DEBUG,  # NOQA
    ERROR,  # NOQA
    FATAL,  # NOQA
    INFO,  # NOQA
    NOTSET,  # NOQA
    WARN,  # NOQA
    WARNING,  # NOQA
)
33
from logging import captureWarnings as _captureWarnings
Lysandre Debut's avatar
Lysandre Debut committed
34
35
from typing import Optional

36
import huggingface_hub.utils as hf_hub_utils
37
from tqdm import auto as tqdm_lib
38

Lysandre Debut's avatar
Lysandre Debut committed
39
40
41
42

_lock = threading.Lock()
_default_handler: Optional[logging.Handler] = None

43
log_levels = {
44
    "detail": logging.DEBUG,  # will also print filename and line number
45
46
47
48
49
50
51
52
53
    "debug": logging.DEBUG,
    "info": logging.INFO,
    "warning": logging.WARNING,
    "error": logging.ERROR,
    "critical": logging.CRITICAL,
}

_default_log_level = logging.WARNING

Jake Tae's avatar
Jake Tae committed
54
55
_tqdm_active = True

56
57
58

def _get_default_logging_level():
    """
Sylvain Gugger's avatar
Sylvain Gugger committed
59
    If TRANSFORMERS_VERBOSITY env var is set to one of the valid choices return that as the new default level. If it is
60
    not - fall back to `_default_log_level`
61
62
63
64
65
66
67
68
69
70
71
72
    """
    env_level_str = os.getenv("TRANSFORMERS_VERBOSITY", None)
    if env_level_str:
        if env_level_str in log_levels:
            return log_levels[env_level_str]
        else:
            logging.getLogger().warning(
                f"Unknown option TRANSFORMERS_VERBOSITY={env_level_str}, "
                f"has to be one of: { ', '.join(log_levels.keys()) }"
            )
    return _default_log_level

Lysandre Debut's avatar
Lysandre Debut committed
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89

def _get_library_name() -> str:
    return __name__.split(".")[0]


def _get_library_root_logger() -> logging.Logger:
    return logging.getLogger(_get_library_name())


def _configure_library_root_logger() -> None:
    global _default_handler

    with _lock:
        if _default_handler:
            # This library has already configured the library root logger.
            return
        _default_handler = logging.StreamHandler()  # Set sys.stderr as stream.
90
91
92
93
        # set defaults based on https://github.com/pyinstaller/pyinstaller/issues/7334#issuecomment-1357447176
        if sys.stderr is None:
            sys.stderr = open(os.devnull, "w")

Stas Bekman's avatar
Stas Bekman committed
94
        _default_handler.flush = sys.stderr.flush
Lysandre Debut's avatar
Lysandre Debut committed
95
96
97
98

        # Apply our default configuration to the library root logger.
        library_root_logger = _get_library_root_logger()
        library_root_logger.addHandler(_default_handler)
99
        library_root_logger.setLevel(_get_default_logging_level())
100
101
102
103
104
        # if logging level is debug, we add pathname and lineno to formatter for easy debugging
        if os.getenv("TRANSFORMERS_VERBOSITY", None) == "detail":
            formatter = logging.Formatter("[%(levelname)s|%(pathname)s:%(lineno)s] %(asctime)s >> %(message)s")
            _default_handler.setFormatter(formatter)

Lysandre Debut's avatar
Lysandre Debut committed
105
        library_root_logger.propagate = False
Lysandre Debut's avatar
Lysandre Debut committed
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120


def _reset_library_root_logger() -> None:
    global _default_handler

    with _lock:
        if not _default_handler:
            return

        library_root_logger = _get_library_root_logger()
        library_root_logger.removeHandler(_default_handler)
        library_root_logger.setLevel(logging.NOTSET)
        _default_handler = None


121
122
123
124
def get_log_levels_dict():
    return log_levels


125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
def captureWarnings(capture):
    """
    Calls the `captureWarnings` method from the logging library to enable management of the warnings emitted by the
    `warnings` library.

    Read more about this method here:
    https://docs.python.org/3/library/logging.html#integration-with-the-warnings-module

    All warnings will be logged through the `py.warnings` logger.

    Careful: this method also adds a handler to this logger if it does not already have one, and updates the logging
    level of that logger to the library's root logger.
    """
    logger = get_logger("py.warnings")

    if not logger.handlers:
        logger.addHandler(_default_handler)

    logger.setLevel(_get_library_root_logger().level)

    _captureWarnings(capture)


Lysandre Debut's avatar
Lysandre Debut committed
148
def get_logger(name: Optional[str] = None) -> logging.Logger:
Sylvain Gugger's avatar
Sylvain Gugger committed
149
150
151
152
    """
    Return a logger with the specified name.

    This function is not supposed to be directly accessed unless you are writing a custom transformers module.
Lysandre Debut's avatar
Lysandre Debut committed
153
154
155
156
157
158
159
160
161
162
    """

    if name is None:
        name = _get_library_name()

    _configure_library_root_logger()
    return logging.getLogger(name)


def get_verbosity() -> int:
Sylvain Gugger's avatar
Sylvain Gugger committed
163
164
165
    """
    Return the current level for the 馃 Transformers's root logger as an int.

Lysandre Debut's avatar
Lysandre Debut committed
166
    Returns:
167
        `int`: The logging level.
Sylvain Gugger's avatar
Sylvain Gugger committed
168

169
    <Tip>
Sylvain Gugger's avatar
Sylvain Gugger committed
170

171
    馃 Transformers has following logging levels:
Sylvain Gugger's avatar
Sylvain Gugger committed
172

173
174
175
176
177
178
179
    - 50: `transformers.logging.CRITICAL` or `transformers.logging.FATAL`
    - 40: `transformers.logging.ERROR`
    - 30: `transformers.logging.WARNING` or `transformers.logging.WARN`
    - 20: `transformers.logging.INFO`
    - 10: `transformers.logging.DEBUG`

    </Tip>"""
Lysandre Debut's avatar
Lysandre Debut committed
180
181
182
183
184
185

    _configure_library_root_logger()
    return _get_library_root_logger().getEffectiveLevel()


def set_verbosity(verbosity: int) -> None:
Sylvain Gugger's avatar
Sylvain Gugger committed
186
    """
187
    Set the verbosity level for the 馃 Transformers's root logger.
Sylvain Gugger's avatar
Sylvain Gugger committed
188

Lysandre Debut's avatar
Lysandre Debut committed
189
    Args:
190
        verbosity (`int`):
Sylvain Gugger's avatar
Sylvain Gugger committed
191
192
            Logging level, e.g., one of:

193
194
195
196
197
            - `transformers.logging.CRITICAL` or `transformers.logging.FATAL`
            - `transformers.logging.ERROR`
            - `transformers.logging.WARNING` or `transformers.logging.WARN`
            - `transformers.logging.INFO`
            - `transformers.logging.DEBUG`
Lysandre Debut's avatar
Lysandre Debut committed
198
199
200
201
202
203
204
    """

    _configure_library_root_logger()
    _get_library_root_logger().setLevel(verbosity)


def set_verbosity_info():
205
    """Set the verbosity to the `INFO` level."""
Lysandre Debut's avatar
Lysandre Debut committed
206
207
208
209
    return set_verbosity(INFO)


def set_verbosity_warning():
210
    """Set the verbosity to the `WARNING` level."""
Lysandre Debut's avatar
Lysandre Debut committed
211
212
213
214
    return set_verbosity(WARNING)


def set_verbosity_debug():
215
    """Set the verbosity to the `DEBUG` level."""
Lysandre Debut's avatar
Lysandre Debut committed
216
217
218
219
    return set_verbosity(DEBUG)


def set_verbosity_error():
220
    """Set the verbosity to the `ERROR` level."""
Lysandre Debut's avatar
Lysandre Debut committed
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
    return set_verbosity(ERROR)


def disable_default_handler() -> None:
    """Disable the default handler of the HuggingFace Transformers's root logger."""

    _configure_library_root_logger()

    assert _default_handler is not None
    _get_library_root_logger().removeHandler(_default_handler)


def enable_default_handler() -> None:
    """Enable the default handler of the HuggingFace Transformers's root logger."""

    _configure_library_root_logger()

    assert _default_handler is not None
    _get_library_root_logger().addHandler(_default_handler)


242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
def add_handler(handler: logging.Handler) -> None:
    """adds a handler to the HuggingFace Transformers's root logger."""

    _configure_library_root_logger()

    assert handler is not None
    _get_library_root_logger().addHandler(handler)


def remove_handler(handler: logging.Handler) -> None:
    """removes given handler from the HuggingFace Transformers's root logger."""

    _configure_library_root_logger()

    assert handler is not None and handler not in _get_library_root_logger().handlers
    _get_library_root_logger().removeHandler(handler)


Lysandre Debut's avatar
Lysandre Debut committed
260
def disable_propagation() -> None:
Sylvain Gugger's avatar
Sylvain Gugger committed
261
262
    """
    Disable propagation of the library log outputs. Note that log propagation is disabled by default.
Lysandre Debut's avatar
Lysandre Debut committed
263
264
265
266
267
268
269
    """

    _configure_library_root_logger()
    _get_library_root_logger().propagate = False


def enable_propagation() -> None:
Sylvain Gugger's avatar
Sylvain Gugger committed
270
271
272
    """
    Enable propagation of the library log outputs. Please disable the HuggingFace Transformers's default handler to
    prevent double logging if the root logger has been configured.
Lysandre Debut's avatar
Lysandre Debut committed
273
274
275
276
    """

    _configure_library_root_logger()
    _get_library_root_logger().propagate = True
Lysandre Debut's avatar
Lysandre Debut committed
277
278
279
280
281


def enable_explicit_format() -> None:
    """
    Enable explicit formatting for every HuggingFace Transformers's logger. The explicit formatter is as follows:
Stas Bekman's avatar
Stas Bekman committed
282
    ```
Lysandre Debut's avatar
Lysandre Debut committed
283
        [LEVELNAME|FILENAME|LINE NUMBER] TIME >> MESSAGE
Stas Bekman's avatar
Stas Bekman committed
284
    ```
Lysandre Debut's avatar
Lysandre Debut committed
285
286
287
288
289
290
291
292
293
294
295
296
297
298
299
300
301
302
303
    All handlers currently bound to the root logger are affected by this method.
    """
    handlers = _get_library_root_logger().handlers

    for handler in handlers:
        formatter = logging.Formatter("[%(levelname)s|%(filename)s:%(lineno)s] %(asctime)s >> %(message)s")
        handler.setFormatter(formatter)


def reset_format() -> None:
    """
    Resets the formatting for HuggingFace Transformers's loggers.

    All handlers currently bound to the root logger are affected by this method.
    """
    handlers = _get_library_root_logger().handlers

    for handler in handlers:
        handler.setFormatter(None)
304
305
306
307
308
309
310
311
312
313
314
315
316
317


def warning_advice(self, *args, **kwargs):
    """
    This method is identical to `logger.warning()`, but if env var TRANSFORMERS_NO_ADVISORY_WARNINGS=1 is set, this
    warning will not be printed
    """
    no_advisory_warnings = os.getenv("TRANSFORMERS_NO_ADVISORY_WARNINGS", False)
    if no_advisory_warnings:
        return
    self.warning(*args, **kwargs)


logging.Logger.warning_advice = warning_advice
Jake Tae's avatar
Jake Tae committed
318
319


320
321
322
323
324
325
326
327
328
329
330
331
332
333
334
@functools.lru_cache(None)
def warning_once(self, *args, **kwargs):
    """
    This method is identical to `logger.warning()`, but will emit the warning with the same message only once

    Note: The cache is for the function arguments, so 2 different callers using the same arguments will hit the cache.
    The assumption here is that all warning messages are unique across the code. If they aren't then need to switch to
    another type of cache that includes the caller frame information in the hashing function.
    """
    self.warning(*args, **kwargs)


logging.Logger.warning_once = warning_once


Jake Tae's avatar
Jake Tae committed
335
336
337
338
339
340
341
342
343
344
345
346
347
348
349
350
351
352
353
354
355
356
357
358
359
360
361
362
363
364
365
366
367
368
369
370
371
372
373
374
375
376
377
378
379
380
381
382
383
384
385
386
387
388
class EmptyTqdm:
    """Dummy tqdm which doesn't do anything."""

    def __init__(self, *args, **kwargs):  # pylint: disable=unused-argument
        self._iterator = args[0] if args else None

    def __iter__(self):
        return iter(self._iterator)

    def __getattr__(self, _):
        """Return empty function."""

        def empty_fn(*args, **kwargs):  # pylint: disable=unused-argument
            return

        return empty_fn

    def __enter__(self):
        return self

    def __exit__(self, type_, value, traceback):
        return


class _tqdm_cls:
    def __call__(self, *args, **kwargs):
        if _tqdm_active:
            return tqdm_lib.tqdm(*args, **kwargs)
        else:
            return EmptyTqdm(*args, **kwargs)

    def set_lock(self, *args, **kwargs):
        self._lock = None
        if _tqdm_active:
            return tqdm_lib.tqdm.set_lock(*args, **kwargs)

    def get_lock(self):
        if _tqdm_active:
            return tqdm_lib.tqdm.get_lock()


tqdm = _tqdm_cls()


def is_progress_bar_enabled() -> bool:
    """Return a boolean indicating whether tqdm progress bars are enabled."""
    global _tqdm_active
    return bool(_tqdm_active)


def enable_progress_bar():
    """Enable tqdm progress bar."""
    global _tqdm_active
    _tqdm_active = True
389
    hf_hub_utils.enable_progress_bars()
Jake Tae's avatar
Jake Tae committed
390
391
392


def disable_progress_bar():
393
    """Disable tqdm progress bar."""
Jake Tae's avatar
Jake Tae committed
394
395
    global _tqdm_active
    _tqdm_active = False
396
    hf_hub_utils.disable_progress_bars()