Progress reporting for --skip shows wrong extensions #3253
Description
I'm debugging a TensorFlow build improvement/issue with EB so to reproduce this I suggest to temporarily change the TF EasyBlock to issue a build error on configure.
So what I did:
eb <TF 2.0.0 EC> --rebuild-> TF failseb <TF 2.0.0 EC> --rebuild --module-only-> Doneeb <TF 2.0.0 EC> --rebuild --skip
stdout of last command ends with:
== taking care of extensions...
== installing extension setuptools 41.3.0 (1/25)...
== installing extension Markdown 3.1.1 (2/25)...
== FAILED: Installation ended unsuccessfully (build directory: /dev/shm/s3248973-EasyBuild/TensorFlow/2.0.0/foss-2019a-Python-3.7.2): build failed (first 300 chars): cmd "export TF_MKL_DOWNLOAD=1 && bazel --output_base=/tmp/easybuild-tm ...
So it says it installs Markdown (and previously setuptools) although it shouldn't but then fails on installing TensorFlow which is very confusing.
Log shows:
== 2020-03-24 10:09:11,998 run.py:222 INFO running cmd: python -c "import setuptools"
== 2020-03-24 10:09:17,801 easyblock.py:1479 INFO exts_filter result 0
== 2020-03-24 10:09:17,801 easyblock.py:1485 INFO Skipping setuptools
== 2020-03-24 10:09:17,801 run.py:222 INFO running cmd: python -c "import markdown"
== 2020-03-24 10:09:18,937 easyblock.py:1479 INFO exts_filter result 0
== 2020-03-24 10:09:18,938 easyblock.py:1485 INFO Skipping Markdown
== 2020-03-24 10:09:18,938 run.py:222 INFO running cmd: python -c "import pyasn1"
== 2020-03-24 10:09:19,386 easyblock.py:1479 INFO exts_filter result 0
== 2020-03-24 10:09:19,387 easyblock.py:1485 INFO Skipping pyasn1
== 2020-03-24 10:09:19,387 run.py:222 INFO running cmd: python -c "import pyasn1_modules"
== 2020-03-24 10:09:19,869 easyblock.py:1479 INFO exts_filter result 0
== 2020-03-24 10:09:19,870 easyblock.py:1485 INFO Skipping pyasn1-modules
== 2020-03-24 10:09:19,870 run.py:222 INFO running cmd: python -c "import rsa"
== 2020-03-24 10:09:20,429 easyblock.py:1479 INFO exts_filter result 0
== 2020-03-24 10:09:20,430 easyblock.py:1485 INFO Skipping rsa
== 2020-03-24 10:09:20,430 run.py:222 INFO running cmd: python -c "import cachetools"
== 2020-03-24 10:09:20,934 easyblock.py:1479 INFO exts_filter result 0
== 2020-03-24 10:09:20,934 easyblock.py:1485 INFO Skipping cachetools
== 2020-03-24 10:09:20,935 run.py:222 INFO running cmd: python -c "import google.auth"
== 2020-03-24 10:09:21,840 easyblock.py:1479 INFO exts_filter result 0
== 2020-03-24 10:09:21,840 easyblock.py:1485 INFO Skipping google-auth
== 2020-03-24 10:09:21,841 run.py:222 INFO running cmd: python -c "import oauthlib"
== 2020-03-24 10:09:22,225 easyblock.py:1479 INFO exts_filter result 0
== 2020-03-24 10:09:22,225 easyblock.py:1485 INFO Skipping oauthlib
== 2020-03-24 10:09:22,226 run.py:222 INFO running cmd: python -c "import requests_oauthlib"
== 2020-03-24 10:09:25,616 easyblock.py:1479 INFO exts_filter result 0
== 2020-03-24 10:09:25,617 easyblock.py:1485 INFO Skipping requests-oauthlib
== 2020-03-24 10:09:25,617 run.py:222 INFO running cmd: python -c "import google_auth_oauthlib"
== 2020-03-24 10:09:29,003 easyblock.py:1479 INFO exts_filter result 0
== 2020-03-24 10:09:29,004 easyblock.py:1485 INFO Skipping google-auth-oauthlib
== 2020-03-24 10:09:29,004 run.py:222 INFO running cmd: python -c "import werkzeug"
== 2020-03-24 10:09:29,756 easyblock.py:1479 INFO exts_filter result 0
== 2020-03-24 10:09:29,756 easyblock.py:1485 INFO Skipping Werkzeug
== 2020-03-24 10:09:29,757 run.py:222 INFO running cmd: python -c "import google.protobuf"
== 2020-03-24 10:09:30,596 easyblock.py:1479 INFO exts_filter result 0
== 2020-03-24 10:09:30,597 easyblock.py:1485 INFO Skipping protobuf
== 2020-03-24 10:09:30,597 run.py:222 INFO running cmd: python -c "import absl"
== 2020-03-24 10:09:30,994 easyblock.py:1479 INFO exts_filter result 0
== 2020-03-24 10:09:30,994 easyblock.py:1485 INFO Skipping absl-py
== 2020-03-24 10:09:30,995 run.py:222 INFO running cmd: python -c "import grpc"
== 2020-03-24 10:09:32,491 easyblock.py:1479 INFO exts_filter result 0
== 2020-03-24 10:09:32,491 easyblock.py:1479 INFO exts_filter result 0
== 2020-03-24 10:09:32,492 easyblock.py:1485 INFO Skipping grpcio
== 2020-03-24 10:09:32,492 run.py:222 INFO running cmd: python -c "import tensorboard"
== 2020-03-24 10:09:32,967 easyblock.py:1479 INFO exts_filter result 0
== 2020-03-24 10:09:32,968 easyblock.py:1485 INFO Skipping tensorboard
== 2020-03-24 10:09:32,968 run.py:222 INFO running cmd: python -c "import pasta"
== 2020-03-24 10:09:33,531 easyblock.py:1479 INFO exts_filter result 0
== 2020-03-24 10:09:33,531 easyblock.py:1485 INFO Skipping google-pasta
== 2020-03-24 10:09:33,532 run.py:222 INFO running cmd: python -c "import termcolor"
== 2020-03-24 10:09:33,958 easyblock.py:1479 INFO exts_filter result 0
== 2020-03-24 10:09:33,959 easyblock.py:1485 INFO Skipping termcolor
== 2020-03-24 10:09:33,959 run.py:222 INFO running cmd: python -c "import tensorflow_estimator"
== 2020-03-24 10:09:34,447 easyblock.py:1479 INFO exts_filter result Traceback (most recent call last):...
== 2020-03-24 10:09:34,447 easyblock.py:1481 INFO Not skipping tensorflow-estimator
== 2020-03-24 10:09:34,448 run.py:222 INFO running cmd: python -c "import astor"
== 2020-03-24 10:09:35,006 easyblock.py:1479 INFO exts_filter result 0
== 2020-03-24 10:09:35,006 easyblock.py:1485 INFO Skipping astor
== 2020-03-24 10:09:35,007 run.py:222 INFO running cmd: python -c "import keras_applications"
== 2020-03-24 10:09:39,151 easyblock.py:1479 INFO exts_filter result 0
== 2020-03-24 10:09:39,151 easyblock.py:1485 INFO Skipping Keras-Applications
== 2020-03-24 10:09:39,152 run.py:222 INFO running cmd: python -c "import gast"
== 2020-03-24 10:09:39,687 easyblock.py:1479 INFO exts_filter result 0
== 2020-03-24 10:09:39,688 easyblock.py:1485 INFO Skipping gast
== 2020-03-24 10:09:39,688 run.py:222 INFO running cmd: python -c "import opt_einsum"
== 2020-03-24 10:09:40,363 easyblock.py:1479 INFO exts_filter result 0
== 2020-03-24 10:09:40,364 easyblock.py:1485 INFO Skipping opt-einsum
== 2020-03-24 10:09:40,364 run.py:222 INFO running cmd: python -c "import wrapt"
== 2020-03-24 10:09:40,917 easyblock.py:1479 INFO exts_filter result 0
== 2020-03-24 10:09:40,917 easyblock.py:1485 INFO Skipping wrapt
== 2020-03-24 10:09:40,918 run.py:222 INFO running cmd: python -c "import keras_preprocessing"
== 2020-03-24 10:09:41,363 easyblock.py:1479 INFO exts_filter result 0
== 2020-03-24 10:09:41,363 easyblock.py:1485 INFO Skipping Keras-Preprocessing
== 2020-03-24 10:09:41,364 run.py:222 INFO running cmd: python -c "import tensorflow"
== 2020-03-24 10:09:41,816 easyblock.py:1479 INFO exts_filter result Traceback (most recent call last): ...
So everything normal here. Not sure what went wrong. Could well be an output buffering issue.