do_subproject: Improve log messages and formatting

mesonbuild/interpreter.py

@@ -2352,7 +2352,7 @@ external dependencies (including libraries) must go to "dependencies".''')
     def do_subproject(self, dirname, kwargs):
         disabled, required, feature = extract_required_kwarg(kwargs, self.subproject)
         if disabled:
-            mlog.log('\nSubproject', mlog.bold(dirname), ':', 'skipped: feature', mlog.bold(feature), 'disabled')
+            mlog.log('Subproject', mlog.bold(dirname), ':', 'skipped: feature', mlog.bold(feature), 'disabled')
             return self.disabled_subproject(dirname)
 
         default_options = mesonlib.stringlistify(kwargs.get('default_options', []))
@@ -2373,39 +2373,37 @@ external dependencies (including libraries) must go to "dependencies".''')
             raise InvalidCode('Recursive include of subprojects: %s.' % incpath)
         if dirname in self.subprojects:
             subproject = self.subprojects[dirname]
-
             if required and not subproject.found():
                 raise InterpreterException('Subproject "%s/%s" required but not found.' % (
                                            self.subproject_dir, dirname))
-
             return subproject
+
         subproject_dir_abs = os.path.join(self.environment.get_source_dir(), self.subproject_dir)
         r = wrap.Resolver(subproject_dir_abs, self.coredata.get_builtin_option('wrap_mode'))
         try:
             resolved = r.resolve(dirname)
         except wrap.WrapException as e:
             subprojdir = os.path.join(self.subproject_dir, r.directory)
-            if not required:
-                mlog.log('\nSubproject ', mlog.bold(subprojdir), 'is buildable:', mlog.red('NO'), '(disabling)\n')
-                return self.disabled_subproject(dirname)
-
             if isinstance(e, wrap.WrapNotFoundException):
                 # if the reason subproject execution failed was because
                 # the directory doesn't exist, try to give some helpful
                 # advice if it's a nested subproject that needs
                 # promotion...
                 self.print_nested_info(dirname)
-
-            msg = 'Failed to initialize {!r}:\n{}'
-            raise InterpreterException(msg.format(subprojdir, e))
+            if not required:
+                mlog.log(e)
+                mlog.log('Subproject ', mlog.bold(subprojdir), 'is buildable:', mlog.red('NO'), '(disabling)')
+                return self.disabled_subproject(dirname)
+            raise e
 
         subdir = os.path.join(self.subproject_dir, resolved)
         os.makedirs(os.path.join(self.build.environment.get_build_dir(), subdir), exist_ok=True)
         self.global_args_frozen = True
         mlog.log()
         with mlog.nested():
-            try:
-                mlog.log('\nExecuting subproject', mlog.bold(dirname), '\n')
+            mlog.log('Executing subproject', mlog.bold(dirname), '\n')
+        try:
+            with mlog.nested():
                 new_build = self.build.copy()
                 subi = Interpreter(new_build, self.backend, dirname, subdir, self.subproject_dir,
                                    self.modules, default_options)
@@ -2414,17 +2412,21 @@ external dependencies (including libraries) must go to "dependencies".''')
                 subi.subproject_stack = self.subproject_stack + [dirname]
                 current_active = self.active_projectname
                 subi.run()
-                mlog.log('\nSubproject', mlog.bold(dirname), 'finished.')
-            # Invalid code is always an error
-            except InvalidCode:
-                raise
-            except Exception as e:
-                if not required:
-                    mlog.log(e)
-                    mlog.log('\nSubproject', mlog.bold(dirname), 'is buildable:', mlog.red('NO'), '(disabling)')
-                    return self.disabled_subproject(dirname)
-                else:
-                    raise e
+                mlog.log('Subproject', mlog.bold(dirname), 'finished.')
+        # Invalid code is always an error
+        except InvalidCode:
+            raise
+        except Exception as e:
+            if not required:
+                with mlog.nested():
+                    # Suppress the 'ERROR:' prefix because this exception is not
+                    # fatal and VS CI treat any logs with "ERROR:" as fatal.
+                    mlog.exception(e, prefix=None)
+                mlog.log('\nSubproject', mlog.bold(dirname), 'is buildable:', mlog.red('NO'), '(disabling)')
+                return self.disabled_subproject(dirname)
+            raise e
+
+        mlog.log()
 
         if 'version' in kwargs:
             pv = subi.project_version

mesonbuild/mlog.py

@@ -195,12 +195,15 @@ def warning(*args, **kwargs):
 def deprecation(*args, **kwargs):
     return _log_error('deprecation', *args, **kwargs)
 
-def exception(e):
+def exception(e, prefix=red('ERROR:')):
     log()
+    args = []
     if hasattr(e, 'file') and hasattr(e, 'lineno') and hasattr(e, 'colno'):
-        log('%s:%d:%d:' % (e.file, e.lineno, e.colno), red('ERROR: '), e)
-    else:
-        log(red('ERROR:'), e)
+        args.append('%s:%d:%d:' % (e.file, e.lineno, e.colno))
+    if prefix:
+        args.append(prefix)
+    args.append(e)
+    log(*args)
 
 # Format a list for logging purposes as a string. It separates
 # all but the last item with commas, and the last with 'and'.

run_unittests.py

@@ -3502,23 +3502,22 @@ class FailureTests(BasePlatformTests):
         Test that:
         1. The correct message is outputted when a not-required dep is not
            found and the fallback subproject is also not found.
-        2. A not-found not-required dep with a fallback subproject outputs the
+        2. A not-required fallback dependency is not found because the
+           subproject failed to parse.
+        3. A not-found not-required dep with a fallback subproject outputs the
            correct message when the fallback subproject is found but the
            variable inside it is not.
-        3. A fallback dependency is found from the subproject parsed in (2)
-        4. A not-required fallback dependency is not found because the
-           subproject failed to parse.
+        4. A fallback dependency is found from the subproject parsed in (3)
+        5. The correct message is outputted when the .wrap file is missing for
+           a sub-subproject.
         '''
         tdir = os.path.join(self.unit_test_dir, '20 subproj dep variables')
         out = self.init(tdir, inprocess=True)
-        self.assertRegex(out, r"Couldn't use fallback subproject "
-                         "in.*subprojects.*nosubproj.*for the dependency.*somedep")
-        self.assertRegex(out, r'Dependency.*somenotfounddep.*from subproject.*'
-                         'subprojects.*somesubproj.*found:.*NO')
-        self.assertRegex(out, r'Dependency.*zlibproxy.*from subproject.*'
-                         'subprojects.*somesubproj.*found:.*YES.*(cached)')
-        self.assertRegex(out, r'Couldn\'t use fallback subproject in '
-                         '.*subprojects.*failingsubproj.*for the dependency.*somedep')
+        self.assertRegex(out, r"Subproject directory not found and .*nosubproj.wrap.* file not found")
+        self.assertRegex(out, r'Function does not take positional arguments.')
+        self.assertRegex(out, r'WARNING:.* Dependency .*subsubproject.* not found but it is available in a sub-subproject.')
+        self.assertRegex(out, r'Subproject directory not found and .*subsubproject.wrap.* file not found')
+        self.assertRegex(out, r'Dependency .*zlibproxy.* from subproject .*subprojects.*somesubproj.* found: .*YES.*')
 
     def test_exception_exit_status(self):
         '''

test cases/unit/20 subproj dep variables/meson.build

@@ -11,3 +11,6 @@ dependency('somenotfounddep', required : false,
 
 dependency('zlibproxy', required : true,
            fallback : ['somesubproj', 'zlibproxy_dep'])
+
+dependency('somedep', required : false,
+           fallback : ['nestedsubproj', 'nestedsubproj_dep'])

test cases/unit/20 subproj dep variables/subprojects/nestedsubproj/meson.build

@@ -0,0 +1,3 @@
+project('dep', 'c')
+
+subproject('subsubproject')

test cases/unit/20 subproj dep variables/subprojects/nestedsubproj/subprojects/subsubproject.wrap

@@ -0,0 +1 @@
+[wrap-file]