control framework loglevel in scripts and tests
Author: stas00
Pull request: yes

There is too much logging going on at times under `transformers` and friends. One needs to be able to turn the noise off easily. This is a follow up to https://github.com/huggingface/transformers/issues/3050#issuecomment-682167272

**edit**: The default was changed yesterday to`logging.WARNING` https://github.com/huggingface/transformers/commit/4561f05c5fafc2b636a2fc1d0dded9057d439745 so there is much less noise now.

**edit**: this PR has evolved since it was initially submitted, so this OP has been updated to reflect the current state of things.

This PR introduces 2 things.

# 1.  new function: `set_verbosity_all`

Usage:

a. override all module-specific loggers to a desired level (except whatever got logged during modules importing)
```
import everything, you, need
import transformers
transformers.testing_utils.set_verbosity_all(transformers.logging.ERROR)
```

b. If you want to disable specific loggers you can call it with specific top level names:
```
import transformers, torch, ...
transformers.testing_utils.set_verbosity_all(transformers.logging.ERROR, ["transformers", "nlp", "torch", "tensorflow", "tensorboard", "wandb"])
```
add/remove module name prefices as needed.

I initially placed it under `transformers.utils.logging` but then since it's beyond the core functionality, I moved it to testing_utils, since this is where we really want it. Please correct me if it should better belong elsewhere.

# 2.  new pytest option: `--log-level-all=error`

when debugging tests, sometimes framework-wide logging gets seriously in the way, e.g. try:

```
RUN_SLOW=1 pytest -sv --disable-warnings tests/test_modeling_bart.py::BartModelIntegrationTests::test_inference_no_head
```
gives a lot of noise. (it was so until `s/info/warn` recent change mention above, but there is noise still)

Now you will be able to turn it off, focusing only on the debug you want, by adding `--loglevel=error ` to the `pytest` options (or another level of your choice):

```
RUN_SLOW=1 pytest -sv --log-level-all=error --disable-warnings tests/test_modeling_bart.py::BartModelIntegrationTests::test_inference_no_head
```
voila - the noise is gone, while you can still do debug printing, etc.

```
pytest -h
  [...]
  --log-level-all={debug,info,warning,error,critical}
                        set global logger level before each test
```


# 3. new test + `CaptureLogger` context manager

While working on this a few integration tests were added and a helper `CaptureLogger` context manager
 to easily test the logger outputs.

# 4. cleaned up one test

removed verbosity setting in one test, which impacted other tests as it wasn't resetting the level to the original

-----

Quite a few testing features were added recently, I guess it's time to start `testing.md` or something. 

----

Fixes: https://github.com/huggingface/transformers/issues/3050

Comments:
# [Codecov](https://codecov.io/gh/huggingface/transformers/pull/6816?src=pr&el=h1) Report
> Merging [#6816](https://codecov.io/gh/huggingface/transformers/pull/6816?src=pr&el=desc) into [master](https://codecov.io/gh/huggingface/transformers/commit/367235ee52537ff7cada5e1c5c41cdd78731f092?el=desc) will **increase** coverage by `2.48%`.
> The diff coverage is `67.85%`.

[![Impacted file tree graph](https://codecov.io/gh/huggingface/transformers/pull/6816/graphs/tree.svg?width=650&height=150&src=pr&token=9qOlN6Hb1c)](https://codecov.io/gh/huggingface/transformers/pull/6816?src=pr&el=tree)

```diff
@@            Coverage Diff             @@
##           master    #6816      +/-   ##
==========================================
+ Coverage   76.27%   78.76%   +2.48%     
==========================================
  Files         157      157              
  Lines       28795    28823      +28     
==========================================
+ Hits        21963    22701     +738     
+ Misses       6832     6122     -710     
```


| [Impacted Files](https://codecov.io/gh/huggingface/transformers/pull/6816?src=pr&el=tree) | Coverage Δ | |
|---|---|---|
| [src/transformers/testing\_utils.py](https://codecov.io/gh/huggingface/transformers/pull/6816/diff?src=pr&el=tree#diff-c3JjL3RyYW5zZm9ybWVycy90ZXN0aW5nX3V0aWxzLnB5) | `66.24% <67.85%> (+0.35%)` | :arrow_up: |
| [src/transformers/configuration\_openai.py](https://codecov.io/gh/huggingface/transformers/pull/6816/diff?src=pr&el=tree#diff-c3JjL3RyYW5zZm9ybWVycy9jb25maWd1cmF0aW9uX29wZW5haS5weQ==) | `34.28% <0.00%> (-62.86%)` | :arrow_down: |
| [src/transformers/tokenization\_albert.py](https://codecov.io/gh/huggingface/transformers/pull/6816/diff?src=pr&el=tree#diff-c3JjL3RyYW5zZm9ybWVycy90b2tlbml6YXRpb25fYWxiZXJ0LnB5) | `28.84% <0.00%> (-58.66%)` | :arrow_down: |
| [src/transformers/modeling\_openai.py](https://codecov.io/gh/huggingface/transformers/pull/6816/diff?src=pr&el=tree#diff-c3JjL3RyYW5zZm9ybWVycy9tb2RlbGluZ19vcGVuYWkucHk=) | `23.87% <0.00%> (-57.10%)` | :arrow_down: |
| [src/transformers/modeling\_tf\_distilbert.py](https://codecov.io/gh/huggingface/transformers/pull/6816/diff?src=pr&el=tree#diff-c3JjL3RyYW5zZm9ybWVycy9tb2RlbGluZ190Zl9kaXN0aWxiZXJ0LnB5) | `64.47% <0.00%> (-34.36%)` | :arrow_down: |
| [src/transformers/modeling\_t5.py](https://codecov.io/gh/huggingface/transformers/pull/6816/diff?src=pr&el=tree#diff-c3JjL3RyYW5zZm9ybWVycy9tb2RlbGluZ190NS5weQ==) | `77.63% <0.00%> (-6.21%)` | :arrow_down: |
| [src/transformers/tokenization\_dpr.py](https://codecov.io/gh/huggingface/transformers/pull/6816/diff?src=pr&el=tree#diff-c3JjL3RyYW5zZm9ybWVycy90b2tlbml6YXRpb25fZHByLnB5) | `53.15% <0.00%> (-4.51%)` | :arrow_down: |
| [src/transformers/configuration\_bart.py](https://codecov.io/gh/huggingface/transformers/pull/6816/diff?src=pr&el=tree#diff-c3JjL3RyYW5zZm9ybWVycy9jb25maWd1cmF0aW9uX2JhcnQucHk=) | `90.00% <0.00%> (-4.00%)` | :arrow_down: |
| [src/transformers/generation\_tf\_utils.py](https://codecov.io/gh/huggingface/transformers/pull/6816/diff?src=pr&el=tree#diff-c3JjL3RyYW5zZm9ybWVycy9nZW5lcmF0aW9uX3RmX3V0aWxzLnB5) | `83.95% <0.00%> (-1.51%)` | :arrow_down: |
| [src/transformers/modeling\_utils.py](https://codecov.io/gh/huggingface/transformers/pull/6816/diff?src=pr&el=tree#diff-c3JjL3RyYW5zZm9ybWVycy9tb2RlbGluZ191dGlscy5weQ==) | `87.50% <0.00%> (-0.56%)` | :arrow_down: |
| ... and [13 more](https://codecov.io/gh/huggingface/transformers/pull/6816/diff?src=pr&el=tree-more) | |

------

[Continue to review full report at Codecov](https://codecov.io/gh/huggingface/transformers/pull/6816?src=pr&el=continue).
> **Legend** - [Click here to learn more](https://docs.codecov.io/docs/codecov-delta)
> `Δ = absolute <relative> (impact)`, `ø = not affected`, `? = missing data`
> Powered by [Codecov](https://codecov.io/gh/huggingface/transformers/pull/6816?src=pr&el=footer). Last update [367235e...05ec0d0](https://codecov.io/gh/huggingface/transformers/pull/6816?src=pr&el=lastupdated). Read the [comment docs](https://docs.codecov.io/docs/pull-request-comments).


[moved to the normal comment from the code review comment, as it might be removed]

>  What is the difference between this method and the previous set_verbosity?
> I think we should select just one way to set the verbosity of the library.

@thomwolf, I agree. Now that I added a test I can see that `set_verbosity` is an equivalent of `set_global_logging_level(prefices=["transformers"])` (the proposed function).

So the main question then is this: do we want to provide a util that allows to do the setting not just for `transformers.`? or leave that to the user - sort of contrib library somewhere?

The main reason for setting a global log level not just for `transfromers`, but also for `torch`, `wandb`, etc. is to be able to quickly turn off the noise when it's interfering. And currently each of these external libraries `transformers` uses add their noise to the output. When debugging tests it's very helpful to control the noise-levels. So having a quick switch --logger-be-quiet saves a lot of time.




I also added: 
- a logger setting integration test
- a helper `CaptureLogger` ctx manager

Could someone please explain why CI gets `logging.ERROR` as the default logging level, when it should be `logging.WARNING` https://github.com/stas00/transformers/blob/loglevels/src/transformers/utils/logging.py#L58 (I rebased this branch to catch that very recent change)

When I run it on my machine, I get `logging.WARNING`. 

On CI the failure is:

```
[gw4] linux -- Python 3.7.9 /usr/local/bin/python

self = <tests.test_logging.HfArgumentParserTest testMethod=test_set_level>

    def test_set_level(self):
        logger = logging.get_logger()
    
        level_origin = logging.get_verbosity()
>       self.assertEqual(level_origin, logging.WARNING)
E       AssertionError: 40 != 30
```
(`logging.ERROR == 40`, `logging.WARNING == 30`)

**edit**: found the culprit - it was another test not cleaning up after itself. fixed in this PR.

Thank you all for your excellent feedback. I made changes and updated the first post to reflect the PR's current state of things.

I'm not sure we really need to control the logging level of all libraries. Since the logging level was changed back to its initial level `WARNING`, do you feel like there are too much logs during tests?

For Bart tests there is a repetitive warning, which I raised here: https://github.com/huggingface/transformers/issues/6652

If you run others, you will see a bunch still, e.g.:

```RUN_SLOW=1 pytest -sv --disable-warnings tests/test_modeling_t5.py ```

```
tests/test_modeling_t5.py::T5ModelTest::test_generate_with_past_key_value_states You might want to consider setting `use_cache=True` to speed up decoding
You might want to consider setting `use_cache=True` to speed up decoding
You might want to consider setting `use_cache=True` to speed up decoding
You might want to consider setting `use_cache=True` to speed up decoding
[...]
Downloading: 100%|█████████████████████████████████████████████████████████████████████████████████████████████████| 242M/242M [00:06<00:00, 40.1MB/s]
Some weights of T5Model were not initialized from the model checkpoint at t5-small and are newly initialized: ['encoder.embed_tokens.weight', 'decoder.embed_tokens.weight']
You should probably TRAIN this model on a down-stream task to be able to use it for predictions and inference.
PASSED
```

And this is just one test.

Of course, the other approach is to go and fix all those warnings, so that the tests that are fully under our control can be written according to the requirements the library sets and then warnings won't be there :) But see the next comment with a large dump of loggers that aren't `transformers`.

----

Yet another alternative solution is instead of flag we add an env var, `LOG_LEVEL_GLOBAL`


Here is some more samples of noise coming from outside `transformers` - a lot of it:

```
tests/test_modeling_tf_albert.py::TFAlbertModelTest::test_albert_model 2020-09-02 10:32:56.462871: I tensorflow/stream_executor/platform/default/dso_loader.cc:48] Successfully opened dynamic library libcuda.so.1
2020-09-02 10:32:56.467570: I tensorflow/stream_executor/cuda/cuda_gpu_executor.cc:982] successful NUMA node read from SysFS had negative value (-1), but there must be at least one NUMA node, so returning NUMA node zero
2020-09-02 10:32:56.469326: I tensorflow/core/common_runtime/gpu/gpu_device.cc:1716] Found device 0 with properties: 
pciBusID: 0000:01:00.0 name: GeForce GTX TITAN X computeCapability: 5.2
coreClock: 1.2155GHz coreCount: 24 deviceMemorySize: 11.93GiB deviceMemoryBandwidth: 313.37GiB/s
2020-09-02 10:32:56.469400: I tensorflow/stream_executor/cuda/cuda_gpu_executor.cc:982] successful NUMA node read from SysFS had negative value (-1), but there must be at least one NUMA node, so returning NUMA node zero
2020-09-02 10:32:56.470032: I tensorflow/core/common_runtime/gpu/gpu_device.cc:1716] Found device 1 with properties: 
pciBusID: 0000:02:00.0 name: GeForce GTX TITAN X computeCapability: 5.2
coreClock: 1.2155GHz coreCount: 24 deviceMemorySize: 11.93GiB deviceMemoryBandwidth: 313.37GiB/s
2020-09-02 10:32:56.470303: I tensorflow/stream_executor/platform/default/dso_loader.cc:48] Successfully opened dynamic library libcudart.so.10.1
2020-09-02 10:32:56.470670: I tensorflow/stream_executor/platform/default/dso_loader.cc:48] Successfully opened dynamic library libcublas.so.10
2020-09-02 10:32:56.470719: I tensorflow/stream_executor/platform/default/dso_loader.cc:48] Successfully opened dynamic library libcufft.so.10
2020-09-02 10:32:56.470752: I tensorflow/stream_executor/platform/default/dso_loader.cc:48] Successfully opened dynamic library libcurand.so.10
2020-09-02 10:32:56.495979: I tensorflow/stream_executor/platform/default/dso_loader.cc:48] Successfully opened dynamic library libcusolver.so.10
2020-09-02 10:32:56.496076: I tensorflow/stream_executor/platform/default/dso_loader.cc:48] Successfully opened dynamic library libcusparse.so.10
2020-09-02 10:32:56.594292: I tensorflow/stream_executor/platform/default/dso_loader.cc:48] Successfully opened dynamic library libcudnn.so.7
2020-09-02 10:32:56.594768: I tensorflow/stream_executor/cuda/cuda_gpu_executor.cc:982] successful NUMA node read from SysFS had negative value (-1), but there must be at least one NUMA node, so returning NUMA node zero
2020-09-02 10:32:56.597007: I tensorflow/stream_executor/cuda/cuda_gpu_executor.cc:982] successful NUMA node read from SysFS had negative value (-1), but there must be at least one NUMA node, so returning NUMA node zero
2020-09-02 10:32:56.599207: I tensorflow/stream_executor/cuda/cuda_gpu_executor.cc:982] successful NUMA node read from SysFS had negative value (-1), but there must be at least one NUMA node, so returning NUMA node zero
2020-09-02 10:32:56.601306: I tensorflow/stream_executor/cuda/cuda_gpu_executor.cc:982] successful NUMA node read from SysFS had negative value (-1), but there must be at least one NUMA node, so returning NUMA node zero
2020-09-02 10:32:56.603994: I tensorflow/core/common_runtime/gpu/gpu_device.cc:1858] Adding visible gpu devices: 0, 1
2020-09-02 10:32:56.612943: I tensorflow/core/platform/cpu_feature_guard.cc:142] This TensorFlow binary is optimized with oneAPI Deep Neural Network Library (oneDNN)to use the following CPU instructions in performance-critical operations:  AVX2 FMA
To enable them in other operations, rebuild TensorFlow with the appropriate compiler flags.
2020-09-02 10:32:56.672605: I tensorflow/core/platform/profile_utils/cpu_utils.cc:104] CPU Frequency: 3199980000 Hz
2020-09-02 10:32:56.675701: I tensorflow/compiler/xla/service/service.cc:168] XLA service 0x556ed093a910 initialized for platform Host (this does not guarantee that XLA will be used). Devices:
2020-09-02 10:32:56.675767: I tensorflow/compiler/xla/service/service.cc:176]   StreamExecutor device (0): Host, Default Version
2020-09-02 10:32:56.678402: I tensorflow/stream_executor/cuda/cuda_gpu_executor.cc:982] successful NUMA node read from SysFS had negative value (-1), but there must be at least one NUMA node, so returning NUMA node zero
2020-09-02 10:32:56.680525: I tensorflow/core/common_runtime/gpu/gpu_device.cc:1716] Found device 0 with properties: 
pciBusID: 0000:01:00.0 name: GeForce GTX TITAN X computeCapability: 5.2
coreClock: 1.2155GHz coreCount: 24 deviceMemorySize: 11.93GiB deviceMemoryBandwidth: 313.37GiB/s
2020-09-02 10:32:56.680889: I tensorflow/stream_executor/cuda/cuda_gpu_executor.cc:982] successful NUMA node read from SysFS had negative value (-1), but there must be at least one NUMA node, so returning NUMA node zero
2020-09-02 10:32:56.683022: I tensorflow/core/common_runtime/gpu/gpu_device.cc:1716] Found device 1 with properties: 
pciBusID: 0000:02:00.0 name: GeForce GTX TITAN X computeCapability: 5.2
coreClock: 1.2155GHz coreCount: 24 deviceMemorySize: 11.93GiB deviceMemoryBandwidth: 313.37GiB/s
2020-09-02 10:32:56.683197: I tensorflow/stream_executor/platform/default/dso_loader.cc:48] Successfully opened dynamic library libcudart.so.10.1
2020-09-02 10:32:56.683257: I tensorflow/stream_executor/platform/default/dso_loader.cc:48] Successfully opened dynamic library libcublas.so.10
2020-09-02 10:32:56.683304: I tensorflow/stream_executor/platform/default/dso_loader.cc:48] Successfully opened dynamic library libcufft.so.10
2020-09-02 10:32:56.683346: I tensorflow/stream_executor/platform/default/dso_loader.cc:48] Successfully opened dynamic library libcurand.so.10
2020-09-02 10:32:56.683504: I tensorflow/stream_executor/platform/default/dso_loader.cc:48] Successfully opened dynamic library libcusolver.so.10
2020-09-02 10:32:56.683566: I tensorflow/stream_executor/platform/default/dso_loader.cc:48] Successfully opened dynamic library libcusparse.so.10
2020-09-02 10:32:56.683693: I tensorflow/stream_executor/platform/default/dso_loader.cc:48] Successfully opened dynamic library libcudnn.so.7
2020-09-02 10:32:56.684014: I tensorflow/stream_executor/cuda/cuda_gpu_executor.cc:982] successful NUMA node read from SysFS had negative value (-1), but there must be at least one NUMA node, so returning NUMA node zero
2020-09-02 10:32:56.686245: I tensorflow/stream_executor/cuda/cuda_gpu_executor.cc:982] successful NUMA node read from SysFS had negative value (-1), but there must be at least one NUMA node, so returning NUMA node zero
2020-09-02 10:32:56.688465: I tensorflow/stream_executor/cuda/cuda_gpu_executor.cc:982] successful NUMA node read from SysFS had negative value (-1), but there must be at least one NUMA node, so returning NUMA node zero
2020-09-02 10:32:56.690589: I tensorflow/stream_executor/cuda/cuda_gpu_executor.cc:982] successful NUMA node read from SysFS had negative value (-1), but there must be at least one NUMA node, so returning NUMA node zero
2020-09-02 10:32:56.692497: I tensorflow/core/common_runtime/gpu/gpu_device.cc:1858] Adding visible gpu devices: 0, 1
2020-09-02 10:32:56.692670: I tensorflow/core/common_runtime/gpu/gpu_device.cc:1257] Device interconnect StreamExecutor with strength 1 edge matrix:
2020-09-02 10:32:56.692706: I tensorflow/core/common_runtime/gpu/gpu_device.cc:1263]      0 1 
2020-09-02 10:32:56.693071: I tensorflow/core/common_runtime/gpu/gpu_device.cc:1276] 0:   N Y 
2020-09-02 10:32:56.693135: I tensorflow/core/common_runtime/gpu/gpu_device.cc:1276] 1:   Y N 
2020-09-02 10:32:56.694784: I tensorflow/stream_executor/cuda/cuda_gpu_executor.cc:982] successful NUMA node read from SysFS had negative value (-1), but there must be at least one NUMA node, so returning NUMA node zero
2020-09-02 10:32:56.696986: I tensorflow/stream_executor/cuda/cuda_gpu_executor.cc:982] successful NUMA node read from SysFS had negative value (-1), but there must be at least one NUMA node, so returning NUMA node zero
2020-09-02 10:32:56.699094: I tensorflow/stream_executor/cuda/cuda_gpu_executor.cc:982] successful NUMA node read from SysFS had negative value (-1), but there must be at least one NUMA node, so returning NUMA node zero
2020-09-02 10:32:56.701214: I tensorflow/stream_executor/cuda/cuda_gpu_executor.cc:982] successful NUMA node read from SysFS had negative value (-1), but there must be at least one NUMA node, so returning NUMA node zero
2020-09-02 10:32:56.703406: I tensorflow/core/common_runtime/gpu/gpu_device.cc:1402] Created TensorFlow device (/job:localhost/replica:0/task:0/device:GPU:0 with 10865 MB memory) -> physical GPU (device: 0, name: GeForce GTX TITAN X, pci bus id: 0000:01:00.0, compute capability: 5.2)
2020-09-02 10:32:56.706854: I tensorflow/stream_executor/cuda/cuda_gpu_executor.cc:982] successful NUMA node read from SysFS had negative value (-1), but there must be at least one NUMA node, so returning NUMA node zero
2020-09-02 10:32:56.709029: I tensorflow/stream_executor/cuda/cuda_gpu_executor.cc:982] successful NUMA node read from SysFS had negative value (-1), but there must be at least one NUMA node, so returning NUMA node zero
2020-09-02 10:32:56.710969: I tensorflow/core/common_runtime/gpu/gpu_device.cc:1402] Created TensorFlow device (/job:localhost/replica:0/task:0/device:GPU:1 with 10856 MB memory) -> physical GPU (device: 1, name: GeForce GTX TITAN X, pci bus id: 0000:02:00.0, compute capability: 5.2)
2020-09-02 10:32:56.718970: I tensorflow/compiler/xla/service/service.cc:168] XLA service 0x556e0ea3c200 initialized for platform CUDA (this does not guarantee that XLA will be used). Devices:
2020-09-02 10:32:56.719031: I tensorflow/compiler/xla/service/service.cc:176]   StreamExecutor device (0): GeForce GTX TITAN X, Compute Capability 5.2
2020-09-02 10:32:56.719056: I tensorflow/compiler/xla/service/service.cc:176]   StreamExecutor device (1): GeForce GTX TITAN X, Compute Capability 5.2
2020-09-02 10:32:57.410269: W tensorflow/python/util/util.cc:348] Sets are not currently considered sequences, but this may change in the future, so consider avoiding using them.
PASSED
[...]
tests/test_modeling_tf_albert.py::TFAlbertModelTest::test_for_sequence_classification PASSED
tests/test_modeling_tf_albert.py::TFAlbertModelTest::test_graph_mode WARNING:tensorflow:5 out of the last 5 calls to <function TFModelTesterMixin.test_graph_mode.<locals>.run_in_graph_mode at 0x7f273870ba70> triggered tf.function retracing. Tracing is expensive and the excessive number of tracings could be due to (1) creating @tf.function repeatedly in a loop, (2) passing tensors with different shapes, (3) passing Python objects instead of tensors. For (1), please define your @tf.function outside of the loop. For (2), @tf.function has experimental_relax_shapes=True option that relaxes argument shapes that can avoid unnecessary retracing. For (3), please refer to https://www.tensorflow.org/tutorials/customization/performance#python_or_tensor_args and https://www.tensorflow.org/api_docs/python/tf/function for  more details.
WARNING:tensorflow:6 out of the last 6 calls to <function TFModelTesterMixin.test_graph_mode.<locals>.run_in_graph_mode at 0x7f2738779ef0> triggered tf.function retracing. Tracing is expensive and the excessive number of tracings could be due to (1) creating @tf.function repeatedly in a loop, (2) passing tensors with different shapes, (3) passing Python objects instead of tensors. For (1), please define your @tf.function outside of the loop. For (2), @tf.function has experimental_relax_shapes=True option that relaxes argument shapes that can avoid unnecessary retracing. For (3), please refer to https://www.tensorflow.org/tutorials/customization/performance#python_or_tensor_args and https://www.tensorflow.org/api_docs/python/tf/function for  more details.
WARNING:tensorflow:7 out of the last 7 calls to <function TFModelTesterMixin.test_graph_mode.<locals>.run_in_graph_mode at 0x7f2742cb89e0> triggered tf.function retracing. Tracing is expensive and the excessive number of tracings could be due to (1) creating @tf.function repeatedly in a loop, (2) passing tensors with different shapes, (3) passing Python objects instead of tensors. For (1), please define your @tf.function outside of the loop. For (2), @tf.function has experimental_relax_shapes=True option that relaxes argument shapes that can avoid unnecessary retracing. For (3), please refer to https://www.tensorflow.org/tutorials/customization/performance#python_or_tensor_args and https://www.tensorflow.org/api_docs/python/tf/function for  more details.
PASSED
[...]
tests/test_modeling_tf_albert.py::TFAlbertModelTest::test_model_common_attributes PASSED
Downloading: 100%|███████████████████████████████████████████████████████████████████████████████████████████████| 63.0M/63.0M [00:02<00:00, 28.8MB/s]
PASSED
tests/test_modeling_tf_albert.py::TFAlbertModelTest::test_model_outputs_equivalence PASSED
tests/test_modeling_tf_albert.py::TFAlbertModelTest::test_pt_tf_model_equivalence PASSED
tests/test_modeling_tf_albert.py::TFAlbertModelTest::test_resize_token_embeddings PASSED
tests/test_modeling_tf_albert.py::TFAlbertModelTest::test_save_load PASSED
tests/test_modeling_tf_albert.py::TFAlbertModelTest::test_saved_model_with_attentions_output WARNING:tensorflow:Skipping full serialization of Keras layer <tensorflow.python.keras.layers.core.Dropout object at 0x7f273831d450>, because it is not built.
WARNING:tensorflow:From /home/stas/anaconda3/envs/main/lib/python3.7/site-packages/tensorflow/python/training/tracking/tracking.py:111: Model.state_updates (from tensorflow.python.keras.engine.training) is deprecated and will be removed in a future version.
Instructions for updating:
This property should not be used in TensorFlow 2.0, as updates are applied automatically.
WARNING:tensorflow:From /home/stas/anaconda3/envs/main/lib/python3.7/site-packages/tensorflow/python/training/tracking/tracking.py:111: Layer.updates (from tensorflow.python.keras.engine.base_layer) is deprecated and will be removed in a future version.
Instructions for updating:
This property should not be used in TensorFlow 2.0, as updates are applied automatically.
WARNING:tensorflow:No training configuration found in save file, so the model was *not* compiled. Compile it manually.
FAILED
tests/test_modeling_tf_albert.py::TFAlbertModelTest::test_saved_model_with_hidden_states_output WARNING:tensorflow:Skipping full serialization of Keras layer <tensorflow.python.keras.layers.core.Dropout object at 0x7f26cb69b7d0>, because it is not built.
WARNING:tensorflow:No training configuration found in save file, so the model was *not* compiled. Compile it manually.
WARNING:tensorflow:Skipping full serialization of Keras layer <tensorflow.python.keras.layers.core.Dropout object at 0x7f26c625ccd0>, because it is not built.
WARNING:tensorflow:No training configuration found in save file, so the model was *not* compiled. Compile it manually.
FAILED
tests/test_modeling_tf_auto.py::TFAutoModelTest::test_from_identifier_from_model_type PASSED
tests/test_modeling_tf_auto.py::TFAutoModelTest::test_from_pretrained_identifier PASSED
Downloading: 100%|█████████████████████████████████████████████████████████████████████████████████████████████████| 536M/536M [00:18<00:00, 28.9MB/s]
2020-09-02 10:34:15.259729: W tensorflow/core/framework/cpu_allocator_impl.cc:81] Allocation of 93763584 exceeds 10% of free system memory.
2020-09-02 10:34:15.394172: W tensorflow/core/framework/cpu_allocator_impl.cc:81] Allocation of 93763584 exceeds 10% of free system memory.
PASSED
Downloading: 100%|█████████████████████████████████████████████████████████████████████████████████████████████████| 498M/498M [00:12<00:00, 40.0MB/s]
2020-09-02 10:34:29.779196: W tensorflow/core/framework/cpu_allocator_impl.cc:81] Allocation of 154389504 exceeds 10% of free system memory.
2020-09-02 10:34:30.859094: W tensorflow/core/framework/cpu_allocator_impl.cc:81] Allocation of 154389504 exceeds 10% of free system memory.
PASSED
tests/test_modeling_tf_auto.py::TFAutoModelTest::test_model_for_encoder_decoder_lm 2020-09-02 10:34:32.437951: W tensorflow/core/framework/cpu_allocator_impl.cc:81] Allocation of 65798144 exceeds 10% of free system memory.
PASSED
[...]
tests/test_modeling_tf_bert.py::TFBertModelTest::test_for_token_classification PASSED
tests/test_modeling_tf_bert.py::TFBertModelTest::test_graph_mode WARNING:tensorflow:8 out of the last 8 calls to <function TFModelTesterMixin.test_graph_mode.<locals>.run_in_graph_mode at 0x7f26c5ccbef0> triggered tf.function retracing. Tracing is expensive and the excessive number of tracings could be due to (1) creating @tf.function repeatedly in a loop, (2) passing tensors with different shapes, (3) passing Python objects instead of tensors. For (1), please define your @tf.function outside of the loop. For (2), @tf.function has experimental_relax_shapes=True option that relaxes argument shapes that can avoid unnecessary retracing. For (3), please refer to https://www.tensorflow.org/tutorials/customization/performance#python_or_tensor_args and https://www.tensorflow.org/api_docs/python/tf/function for  more details.
WARNING:tensorflow:9 out of the last 9 calls to <function TFModelTesterMixin.test_graph_mode.<locals>.run_in_graph_mode at 0x7f26c5db8950> triggered tf.function retracing. Tracing is expensive and the excessive number of tracings could be due to (1) creating @tf.function repeatedly in a loop, (2) passing tensors with different shapes, (3) passing Python objects instead of tensors. For (1), please define your @tf.function outside of the loop. For (2), @tf.function has experimental_relax_shapes=True option that relaxes argument shapes that can avoid unnecessary retracing. For (3), please refer to https://www.tensorflow.org/tutorials/customization/performance#python_or_tensor_args and https://www.tensorflow.org/api_docs/python/tf/function for  more details.
WARNING:tensorflow:10 out of the last 10 calls to <function TFModelTesterMixin.test_graph_mode.<locals>.run_in_graph_mode at 0x7f26c5ccbcb0> triggered tf.function retracing. Tracing is expensive and the excessive number of tracings could be due to (1) creating @tf.function repeatedly in a loop, (2) passing tensors with different shapes, (3) passing Python objects instead of tensors. For (1), please define your @tf.function outside of the loop. For (2), @tf.function has experimental_relax_shapes=True option that relaxes argument shapes that can avoid unnecessary retracing. For (3), please refer to https://www.tensorflow.org/tutorials/customization/performance#python_or_tensor_args and https://www.tensorflow.org/api_docs/python/tf/function for  more details.
WARNING:tensorflow:11 out of the last 11 calls to <function TFModelTesterMixin.test_graph_mode.<locals>.run_in_graph_mode at 0x7f277c0eb5f0> triggered tf.function retracing. Tracing is expensive and the excessive number of tracings could be due to (1) creating @tf.function repeatedly in a loop, (2) passing tensors with different shapes, (3) passing Python objects instead of tensors. For (1), please define your @tf.function outside of the loop. For (2), @tf.function has experimental_relax_shapes=True option that relaxes argument shapes that can avoid unnecessary retracing. For (3), please refer to https://www.tensorflow.org/tutorials/customization/performance#python_or_tensor_args and https://www.tensorflow.org/api_docs/python/tf/function for  more details.
WARNING:tensorflow:11 out of the last 11 calls to <function TFModelTesterMixin.test_graph_mode.<locals>.run_in_graph_mode at 0x7f26c8298dd0> triggered tf.function retracing. Tracing is expensive and the excessive number of tracings could be due to (1) creating @tf.function repeatedly in a loop, (2) passing tensors with different shapes, (3) passing Python objects instead of tensors. For (1), please define your @tf.function outside of the loop. For (2), @tf.function has experimental_relax_shapes=True option that relaxes argument shapes that can avoid unnecessary retracing. For (3), please refer to https://www.tensorflow.org/tutorials/customization/performance#python_or_tensor_args and https://www.tensorflow.org/api_docs/python/tf/function for  more details.
WARNING:tensorflow:11 out of the last 11 calls to <function TFModelTesterMixin.test_graph_mode.<locals>.run_in_graph_mode at 0x7f273816d5f0> triggered tf.function retracing. Tracing is expensive and the excessive number of tracings could be due to (1) creating @tf.function repeatedly in a loop, (2) passing tensors with different shapes, (3) passing Python objects instead of tensors. For (1), please define your @tf.function outside of the loop. For (2), @tf.function has experimental_relax_shapes=True option that relaxes argument shapes that can avoid unnecessary retracing. For (3), please refer to https://www.tensorflow.org/tutorials/customization/performance#python_or_tensor_args and https://www.tensorflow.org/api_docs/python/tf/function for  more details.
WARNING:tensorflow:11 out of the last 11 calls to <function TFModelTesterMixin.test_graph_mode.<locals>.run_in_graph_mode at 0x7f26c8235560> triggered tf.function retracing. Tracing is expensive and the excessive number of tracings could be due to (1) creating @tf.function repeatedly in a loop, (2) passing tensors with different shapes, (3) passing Python objects instead of tensors. For (1), please define your @tf.function outside of the loop. For (2), @tf.function has experimental_relax_shapes=True option that relaxes argument shapes that can avoid unnecessary retracing. For (3), please refer to https://www.tensorflow.org/tutorials/customization/performance#python_or_tensor_args and https://www.tensorflow.org/api_docs/python/tf/function for  more details.
WARNING:tensorflow:11 out of the last 11 calls to <function TFModelTesterMixin.test_graph_mode.<locals>.run_in_graph_mode at 0x7f26caab45f0> triggered tf.function retracing. Tracing is expensive and the excessive number of tracings could be due to (1) creating @tf.function repeatedly in a loop, (2) passing tensors with different shapes, (3) passing Python objects instead of tensors. For (1), please define your @tf.function outside of the loop. For (2), @tf.function has experimental_relax_shapes=True option that relaxes argument shapes that can avoid unnecessary retracing. For (3), please refer to https://www.tensorflow.org/tutorials/customization/performance#python_or_tensor_args and https://www.tensorflow.org/api_docs/python/tf/function for  more details.
WARNING:tensorflow:11 out of the last 11 calls to <function TFModelTesterMixin.test_graph_mode.<locals>.run_in_graph_mode at 0x7f26c9da34d0> triggered tf.function retracing. Tracing is expensive and the excessive number of tracings could be due to (1) creating @tf.function repeatedly in a loop, (2) passing tensors with different shapes, (3) passing Python objects instead of tensors. For (1), please define your @tf.function outside of the loop. For (2), @tf.function has experimental_relax_shapes=True option that relaxes argument shapes that can avoid unnecessary retracing. For (3), please refer to https://www.tensorflow.org/tutorials/customization/performance#python_or_tensor_args and https://www.tensorflow.org/api_docs/python/tf/function for  more details.
PASSED
```


Thinking about it more while working with other tools, it'd be of a great help to have an env var that can set the default logging level for `transformers`. e.g. I wanted to change the logging level for `run_eval.py` and I couldn't do that w/o modifying it. If we had an env var that would have been trivial and much faster to use.

This is regardless of the outcome of this discussion of whether we should have a way to turn non-transformers-related loggers off.

I understand the issue, and while I agree that some frameworks are extremely log intensive (TensorFlow ...), I wonder if it's such a bad thing to have too many logs during testing. If a test fails, the logs may help to understand the issue quicker when the stack trace isn't helping much. Removing these logs would mean needing to restart the CI with a different logging level to see what's happening in the logs around this error.

Regarding your second point, yes, I think it would be nice to control the default logging level with an environment variable! Would welcome such a PR.

I would find some more control over logging very useful! A lot of our users are on colab, and warnings waste a ton of screen space there. Same with my debugging workflow -- there are so many logger statements that can't see my full traceback on the screen.

> I would find some more control over logging very useful! A lot of our users are on colab, and warnings waste a ton of screen space there. Same with my debugging workflow -- there are so many logger statements that can't see my full traceback on the screen.

I wonder whether we should just have an env var `DISABLE_LOGGING=info` that will just do:
```
import logging
logging.disable(logging.INFO) # disable INFO and DEBUG logger everywhere
```
`DISABLE_LOGGING=warning` for WARNING, INFO and DEBUG...

In addition to the transformers-specific one `TRANSFORMERS_VERBOSITY=info...` which I will add.


> I understand the issue, and while I agree that some frameworks are extremely log intensive (TensorFlow ...), I wonder if it's such a bad thing to have too many logs during testing. If a test fails, the logs may help to understand the issue quicker when the stack trace isn't helping much. Removing these logs would mean needing to restart the CI with a different logging level to see what's happening in the logs around this error.

In no way I am proposing to impact CI in any way - on the contrary - on CI the more debug info the merrier. I'm only proposing a way for a developer to turn the logging off on their own setup. i.e. we won't be enabling any such features on CI.

Different developers have different needs and for me, for example, noise is very counterproductive for development. When debugging something I only want to see outputs that are relevant to what I'm debugging and nothing else - and seconding @sshleifer's comment  - I too want them to fit into the current screen so I don't need to scroll. Especially in complicated situations when I need to look at output numbers. I understand how this can be a total non-issue for others.

> Regarding your second point, yes, I think it would be nice to control the default logging level with an environment variable! Would welcome such a PR.

I will do so. Thank you!

> I would find some more control over logging very useful! A lot of our users are on colab, and warnings waste a ton of screen space there. Same with my debugging workflow -- there are so many logger statements that can't see my full traceback on the screen.

@sshleifer have you tried the new library-wide control for logging that Lysandre added in #6434?
The doc is here: https://huggingface.co/transformers/master/main_classes/logging.html

Added the env var to control the transformers verbosity level: https://github.com/huggingface/transformers/pull/6961

It feels that this proposal is a no go at the moment, so I'm closing it down.

The extended tests and added testing utils which were part of this PR have been merged in https://github.com/huggingface/transformers/pull/6961

Thank you all who contributed to this discussion.