testing/testcase: configure default logging to a file

This should make investigation of errors on testnode easiers, any logged
messages by test framework goes to testcase.log

Setup logging at the very beginning, to also have messages logged during
initialization

Also adjust a bit the logged messages, we don't need to log everytime we
snapshot a file or folder, this cause the log to be very big, but it can
be interesting to log when we start and stop checking software, so that
we see how long this took.

slapos/testing/testcase.py

@@ -113,6 +113,20 @@ def makeModuleSetUpAndTestCaseClass(
     base_directory = os.path.realpath(
         os.environ.get(
             'SLAPOS_TEST_WORKING_DIR', os.path.join(os.getcwd(), '.slapos')))
+
+  software_id = urlparse(software_url).path.split('/')[-2]
+
+  logging.basicConfig(
+      level=logging.DEBUG,
+      format='%(asctime)s - {} - %(name)s - %(levelname)s - %(message)s'.format(software_id),
+      filename=os.path.join(snapshot_directory or base_directory, 'testcase.log'),
+  )
+  logger = logging.getLogger()
+  console_handler = logging.StreamHandler()
+  console_handler.setLevel(
+      logging.DEBUG if (verbose or debug) else logging.WARNING)
+  logger.addHandler(console_handler)
+
   # TODO: fail if already running ?
   try:
     slap = StandaloneSlapOS(
@@ -131,7 +145,7 @@ def makeModuleSetUpAndTestCaseClass(
       (SlapOSInstanceTestCase,), {
           'slap': slap,
           'getSoftwareURL': classmethod(lambda _cls: software_url),
-          'software_id': urlparse(software_url).path.split('/')[-2],
+          'software_id': software_id,
           '_debug': debug,
           '_verbose': verbose,
           '_ipv4_address': ipv4_address,
@@ -150,8 +164,6 @@ def makeModuleSetUpAndTestCaseClass(
     # type: () -> None
     if debug:
       unittest.installHandler()
-    logging.basicConfig(
-        level=logging.DEBUG if (verbose or debug) else logging.WARNING)
     installSoftwareUrlList(cls, [software_url], debug=debug)
 
   return setUpModule, SlapOSInstanceTestCase_
@@ -361,7 +373,9 @@ def installSoftwareUrlList(cls, software_url_list, max_retry=10, debug=False):
     cls.slap.waitForSoftware(max_retry=max_retry, debug=debug)
     _storeSoftwareSnapshot('setupModule')
     for software_url in software_url_list:
+      cls.logger.debug("Checking software %s", software_url)
       checkSoftware(cls.slap, software_url)
+      cls.logger.debug("Done checking software %s", software_url)
   except BaseException as e:
     if not debug:
       cls.logger.exception("Error building software, removing")
@@ -614,10 +628,8 @@ class SlapOSInstanceTestCase(unittest.TestCase):
       with open(destination, 'w') as f:
         f.write('broken symink to {}\n'.format(os.readlink(source_file_name)))
     elif os.path.isfile(source_file_name):
-      cls.logger.debug("copy %s as %s", source_file_name, destination)
       shutil.copy(source_file_name, destination)
     elif os.path.isdir(source_file_name):
-      cls.logger.debug("copy directory %s as %s", source_file_name, destination)
       # we copy symlinks as symlinks, so that this does not fail when
       # we copy a directory containing broken symlinks.
       shutil.copytree(source_file_name, destination, symlinks=True)