Further feedback from comments

franchuterivera · franchuterivera · commit a40627479ddd · 2020-11-30T12:37:17.000+01:00
diff --git a/.github/workflows/pytest.yml b/.github/workflows/pytest.yml
@@ -56,6 +56,10 @@ jobs:
         python setup.py sdist
         last_dist=$(ls -t dist/auto-sklearn-*.tar.gz | head -n 1)
         pip install $last_dist
+    - name: Store repository status
+      id: status-before
+      run: |
+        echo "::set-output name=BEFORE::$(git status --porcelain -b)"
     - name: Conda Run tests
       if: matrix.use-conda == true
       run: |
@@ -66,15 +70,26 @@ jobs:
         # to change the default python
         export PATH="$CONDA/envs/testenv/bin:$PATH"
         if [ ${{ matrix.code-cov }} ]; then codecov='--cov=autosklearn --cov-report=xml'; fi
-        $CONDA/envs/testenv/bin/python3 -m pytest --durations=20 -sv $codecov test
+        $CONDA/envs/testenv/bin/python3 -m pytest --durations=20 -v $codecov test
     - name: Run tests
       if: matrix.use-conda == false
       run: |
         export OPENBLAS_NUM_THREADS=1
         export OMP_NUM_THREADS=1
         export MKL_NUM_THREADS=1
         if [ ${{ matrix.code-cov }} ]; then codecov='--cov=autosklearn --cov-report=xml'; fi
-        pytest --durations=20 -sv $codecov test
+        pytest --durations=20 -v $codecov test
+    - name: Check for files left behind by test
+      if: ${{ always() }}
+      run: |
+        before="${{ steps.status-before.outputs.BEFORE }}"
+        after="$(git status --porcelain -b)"
+        if [[ "$before" != "$after" ]]; then
+            echo "git status from before: $before"
+            echo "git status from after: $after"
+            echo "Not all generated files have been deleted!"
+            exit 1
+        fi
     - name: Upload coverage
       if: matrix.code-cov && always()
       uses: codecov/codecov-action@v1
diff --git a/autosklearn/evaluation/train_evaluator.py b/autosklearn/evaluation/train_evaluator.py
@@ -1201,6 +1201,7 @@ def eval_partial_cv_iterative(
         resampling_strategy=resampling_strategy,
         resampling_strategy_args=resampling_strategy_args,
         seed=seed,
+        port=port,
         num_run=num_run,
         instance=instance,
         all_scoring_functions=all_scoring_functions,
@@ -1293,6 +1294,7 @@ def eval_iterative_cv(
         include=include,
         exclude=exclude,
         disable_file_output=disable_file_output,
+        port=port,
         init_params=init_params,
         budget=budget,
         budget_type=budget_type,
diff --git a/autosklearn/util/backend.py b/autosklearn/util/backend.py
@@ -82,9 +82,11 @@ def __init__(self,
             )
         )
         self._output_directory = output_directory
-        # We create a dummy logger to start with
-        # Then, when a port is available we can create a
-        # client logger
+        # Auto-Sklearn logs through the use of a PicklableClientLogger
+        # For this reason we need a port to communicate with the server
+        # When the backend is created, this port is not available
+        # When the port is available in the main process, we
+        # call the setup_logger with this port and update self.logger
         self.logger = None  # type: Optional[PicklableClientLogger]
         self.create_directories()
 
@@ -165,6 +167,9 @@ class Backend(object):
     """
 
     def __init__(self, context: BackendContext):
+        # When the backend is created, this port is not available
+        # When the port is available in the main process, we
+        # call the setup_logger with this port and update self.logger
         self.logger = None  # type: Optional[PicklableClientLogger]
         self.context = context
 
diff --git a/scripts/run_auto-sklearn_for_metadata_generation.py b/scripts/run_auto-sklearn_for_metadata_generation.py
@@ -3,6 +3,7 @@
     import argparse
     import json
     import logging
+    import logging.handlers
     import os
     import shutil
     import sys
@@ -144,6 +145,7 @@
                                         include=include,
                                         metric=automl_arguments['metric'],
                                         cost_for_crash=get_cost_of_crash(automl_arguments['metric']),
+                                        port=logging.handlers.DEFAULT_TCP_LOGGING_PORT,
                                         abort_on_first_run_crash=False,)
             run_info, run_value = ta.run_wrapper(
                 RunInfo(
diff --git a/test/conftest.py b/test/conftest.py
@@ -1,5 +1,6 @@
 import os
 import shutil
+import tempfile
 import time
 import unittest.mock
 
@@ -124,7 +125,8 @@ def dask_client(request):
     Workers are in subprocesses to not create deadlocks with the pynisher and logging.
     """
 
-    client = Client(n_workers=2, threads_per_worker=1, processes=False)
+    client = Client(n_workers=2, threads_per_worker=1, processes=False,
+                    local_directory=tempfile.gettempdir())
     print("Started Dask client={}\n".format(client))
 
     def get_finalizer(address):
diff --git a/test/test_automl/automl_utils.py b/test/test_automl/automl_utils.py
@@ -66,6 +66,12 @@ def __init__(self, logfile: str):
 
     def parse_logfile(self) -> typing.List[str]:
         # We care about the [debug/info/...] messages
+        # At the time of writing, the message format was:
+        # [DEBUG] [2020-11-30 11:54:05,072:EnsembleBuilder] Restricting your
+        # function to 3072 mb memory.
+        #
+        # [DEBUG] [2020-11-30 11:53:55,062:pynisher] Redirecting
+        # output of the function to files.
         assert os.path.exists(self.logfile), "{} not found".format(self.logfile)
 
         with open(self.logfile) as fh:
@@ -85,6 +91,8 @@ def count_ensembler_iterations(self) -> int:
             # We expect the start msg to be something like:
             # [DEBUG] [2020-11-26 19:22:42,160:EnsembleBuilder] \
             # Function called with argument: (61....
+            # [DEBUG] [2020-11-30 11:53:47,069:EnsembleBuilder] Function called with argument:
+            # (28.246965646743774, 1, False), {}
             match = re.search(
                 r'EnsembleBuilder]\s+Function called with argument:\s+\(\d+\.\d+, (\d+), \w+',
                 line)
@@ -93,6 +101,8 @@ def count_ensembler_iterations(self) -> int:
 
             # Ensemble Builder actual call
             # Here we expect the msg:
+            # [DEBUG] [2020-11-30 11:53:14,877:EnsembleBuilder] Starting iteration 0,
+            # time left: 61.266255
             # [DEBUG] [2020-11-27 20:27:28,044:EnsembleBuilder] Starting iteration 2,
             # time left: 10.603252
             match = re.search(
@@ -110,21 +120,30 @@ def count_ensembler_iterations(self) -> int:
     def count_ensembler_success_pynisher_calls(self) -> int:
 
         # We expect the return msg to be something like:
-        # [DEBUG] [2020-11-26 19:22:43,018:EnsembleBuilder] return value: (([{'Times...
+        # [DEBUG] [2020-11-30 11:53:47,911:EnsembleBuilder] return value:
+        # (([{'Timestamp': Timestamp('2020-11-30 11:53:47.910727'),
+        # 'ensemble_optimization_score': 0.9787234042553191}], 50, None, None, None), 0)
+        # [DEBUG] [2020-11-30 11:54:05,984:EnsembleBuilder] return value:
+        # (([{'Timestamp': Timestamp('2020-11- 30 11:54:05.983837'),
+        # 'ensemble_optimization_score': 0.9787234042553191}], 50, None, None, None), 0)
         return_msgs = len([line for line in self.lines if re.search(
             r'EnsembleBuilder]\s+return value:.*Timestamp', line)])
 
         return return_msgs
 
     def count_tae_pynisher_calls(self) -> int:
         # We expect the return msg to be something like:
-        # [DEBUG] [2020-11-26 19:22:39,558:pynisher] return value: (...
+        # [DEBUG] [2020-11-30 11:53:11,264:pynisher] return value: (None, 0)
+        # [DEBUG] [2020-11-30 11:53:13,768:pynisher] return value: (None, 0)
         return_msgs = len([line for line in self.lines if re.search(
             r'pynisher]\s+return value:\s+', line)])
         return (return_msgs)
 
     def get_automl_setting_from_log(self, dataset_name: str, setting: str) -> str:
         for line in self.lines:
+            # We expect messages of the form
+            # [DEBUG] [2020-11-30 11:53:10,457:AutoML(5):breast_cancer]   ensemble_size: 50
+            # [DEBUG] [2020-11-30 11:53:10,457:AutoML(5):breast_cancer]   ensemble_nbest: 50
             match = re.search(
                 f"{dataset_name}]\\s*{setting}\\s*:\\s*(\\w+)",
                 line)
diff --git a/test/test_metalearning/pyMetaLearn/test_meta_features_sparse.py b/test/test_metalearning/pyMetaLearn/test_meta_features_sparse.py
@@ -1,4 +1,5 @@
 from io import StringIO
+import logging
 import os
 import sys
 import unittest
@@ -69,103 +70,104 @@ def setUp(self):
         self.y = y
         self.mf = meta_features.metafeatures
         self.helpers = meta_features.helper_functions
+        self.logger = logging.getLogger()
 
         # Precompute some helper functions
         self.helpers.set_value(
             "PCA",
-            self.helpers["PCA"](self.X_transformed, self.y),
+            self.helpers["PCA"](self.X_transformed, self.y, self.logger),
             )
         self.helpers.set_value(
             "MissingValues",
-            self.helpers["MissingValues"](self.X, self.y, self.categorical),
+            self.helpers["MissingValues"](self.X, self.y, self.logger, self.categorical),
             )
         self.mf.set_value(
             "NumberOfMissingValues",
-            self.mf["NumberOfMissingValues"](self.X, self.y, self.categorical),
+            self.mf["NumberOfMissingValues"](self.X, self.y, self.logger, self.categorical),
             )
         self.helpers.set_value(
             "NumSymbols",
-            self.helpers["NumSymbols"](self.X, self.y, self.categorical),
+            self.helpers["NumSymbols"](self.X, self.y, self.logger, self.categorical),
             )
         self.helpers.set_value(
             "ClassOccurences",
-            self.helpers["ClassOccurences"](self.X, self.y),
+            self.helpers["ClassOccurences"](self.X, self.y, self.logger),
             )
         self.helpers.set_value(
             "Skewnesses",
-            self.helpers["Skewnesses"](self.X_transformed, self.y, self.categorical_transformed),
+            self.helpers["Skewnesses"](self.X_transformed, self.y, self.logger, self.categorical_transformed),
             )
         self.helpers.set_value(
             "Kurtosisses",
-            self.helpers["Kurtosisses"](self.X_transformed, self.y, self.categorical_transformed),
+            self.helpers["Kurtosisses"](self.X_transformed, self.y, self.logger, self.categorical_transformed),
             )
 
     def test_missing_values(self):
-        mf = self.helpers["MissingValues"](self.X, self.y, self.categorical)
+        mf = self.helpers["MissingValues"](self.X, self.y, self.logger, self.categorical)
         self.assertTrue(sparse.issparse(mf.value))
         self.assertEqual(mf.value.shape, self.X.shape)
         self.assertEqual(mf.value.dtype, np.bool)
         self.assertEqual(0, np.sum(mf.value.data))
 
     def test_number_of_missing_values(self):
-        mf = self.mf["NumberOfMissingValues"](self.X, self.y, self.categorical)
+        mf = self.mf["NumberOfMissingValues"](self.X, self.y, self.logger, self.categorical)
         self.assertEqual(0, mf.value)
 
     def test_percentage_missing_values(self):
-        mf = self.mf["PercentageOfMissingValues"](self.X, self.y, self.categorical)
+        mf = self.mf["PercentageOfMissingValues"](self.X, self.y, self.logger, self.categorical)
         self.assertEqual(0, mf.value)
 
     def test_number_of_Instances_with_missing_values(self):
         mf = self.mf["NumberOfInstancesWithMissingValues"](
-            self.X, self.y, self.categorical)
+            self.X, self.y, self.logger, self.categorical)
         self.assertEqual(0, mf.value)
 
     def test_percentage_of_Instances_with_missing_values(self):
         self.mf.set_value("NumberOfInstancesWithMissingValues",
                           self.mf["NumberOfInstancesWithMissingValues"](
-                              self.X, self.y, self.categorical))
-        mf = self.mf["PercentageOfInstancesWithMissingValues"](self.X, self.y,
+                              self.X, self.y, self.logger, self.categorical))
+        mf = self.mf["PercentageOfInstancesWithMissingValues"](self.X, self.y, self.logger,
                                                                self.categorical)
         self.assertAlmostEqual(0, mf.value)
 
     def test_number_of_features_with_missing_values(self):
-        mf = self.mf["NumberOfFeaturesWithMissingValues"](self.X, self.y,
+        mf = self.mf["NumberOfFeaturesWithMissingValues"](self.X, self.y, self.logger,
                                                           self.categorical)
         self.assertEqual(0, mf.value)
 
     def test_percentage_of_features_with_missing_values(self):
         self.mf.set_value("NumberOfFeaturesWithMissingValues",
                           self.mf["NumberOfFeaturesWithMissingValues"](
-                              self.X, self.y, self.categorical))
-        mf = self.mf["PercentageOfFeaturesWithMissingValues"](self.X, self.y,
+                              self.X, self.y, self.logger, self.categorical))
+        mf = self.mf["PercentageOfFeaturesWithMissingValues"](self.X, self.y, self.logger,
                                                               self.categorical)
         self.assertAlmostEqual(0, mf.value)
 
     def test_num_symbols(self):
-        mf = self.helpers["NumSymbols"](self.X, self.y, self.categorical)
+        mf = self.helpers["NumSymbols"](self.X, self.y, self.logger, self.categorical)
 
         symbol_frequency = [2, 0, 6, 0, 1, 3, 0, 0, 3, 1, 0, 0, 0, 1, 0, 0,
                             0, 0, 0, 0, 0, 0, 0, 2, 0, 0, 0, 0, 1, 1, 2, 2]
         self.assertEqual(mf.value, symbol_frequency)
 
     def test_symbols_max(self):
         # this is attribute steel
-        mf = self.mf["SymbolsMax"](self.X, self.y, self.categorical)
+        mf = self.mf["SymbolsMax"](self.X, self.y, self.logger, self.categorical)
         self.assertEqual(mf.value, 6)
 
     def test_symbols_mean(self):
-        mf = self.mf["SymbolsMean"](self.X, self.y, self.categorical)
+        mf = self.mf["SymbolsMean"](self.X, self.y, self.logger, self.categorical)
         # Empty looking spaces denote empty attributes
         symbol_frequency = [2, 6, 1, 3, 3, 1, 1, 2, 1, 1, 2, 2]
         self.assertAlmostEqual(mf.value, np.mean(symbol_frequency))
 
     def test_symbols_std(self):
-        mf = self.mf["SymbolsSTD"](self.X, self.y, self.categorical)
+        mf = self.mf["SymbolsSTD"](self.X, self.y, self.logger, self.categorical)
         symbol_frequency = [2, 6, 1, 3, 3, 1, 1, 2, 1, 1, 2, 2]
         self.assertAlmostEqual(mf.value, np.std(symbol_frequency))
 
     def test_symbols_sum(self):
-        mf = self.mf["SymbolsSum"](self.X, self.y, self.categorical)
+        mf = self.mf["SymbolsSum"](self.X, self.y, self.logger, self.categorical)
         self.assertEqual(mf.value, 25)
 
     def test_skewnesses(self):
@@ -175,7 +177,7 @@ def test_skewnesses(self):
                    -0.6969708499033568, 0.626346013011263,
                    0.3809987596624038, 1.4762248835141034,
                    0.07687661087633726, 0.36889797830360116]
-        mf = self.helpers["Skewnesses"](self.X_transformed, self.y)
+        mf = self.helpers["Skewnesses"](self.X_transformed, self.y, self.logger)
         print(mf.value)
         print(fixture)
         np.testing.assert_allclose(mf.value, fixture)
@@ -188,25 +190,25 @@ def test_kurtosisses(self):
                    -1.1786325509475712, -1.2387998382327912,
                    1.393438264413704, -0.9768209837948336,
                    -1.7937072296512782]
-        mf = self.helpers["Kurtosisses"](self.X_transformed, self.y)
+        mf = self.helpers["Kurtosisses"](self.X_transformed, self.y, self.logger)
         np.testing.assert_allclose(mf.value, fixture)
 
     def test_pca_95percent(self):
         mf = self.mf["PCAFractionOfComponentsFor95PercentVariance"](
-            self.X_transformed, self.y)
+            self.X_transformed, self.y, self.logger)
         self.assertAlmostEqual(0.7741935483870968, mf.value)
 
     def test_pca_kurtosis_first_pc(self):
-        mf = self.mf["PCAKurtosisFirstPC"](self.X_transformed, self.y)
+        mf = self.mf["PCAKurtosisFirstPC"](self.X_transformed, self.y, self.logger)
         self.assertAlmostEqual(-0.15444516166802469, mf.value)
 
     def test_pca_skewness_first_pc(self):
-        mf = self.mf["PCASkewnessFirstPC"](self.X_transformed, self.y)
+        mf = self.mf["PCASkewnessFirstPC"](self.X_transformed, self.y, self.logger)
         self.assertAlmostEqual(0.026514792083623905, mf.value)
 
     def test_calculate_all_metafeatures(self):
         mf = meta_features.calculate_all_metafeatures(
-            self.X, self.y, self.categorical, "2")
+            self.X, self.y, self.categorical, "2", logger=self.logger)
         self.assertEqual(52, len(mf.metafeature_values))
         sio = StringIO()
         mf.dump(sio)
