Repository: zephyrproject-rtos/west

Issue:
Logging for imported projects being added is wrong
The west.manifest logging calls for when projects are being added is wrong. The recursive call to the Manifest constructor is logging the addition of a project, and then it happens again in the parent manifest level of the recursion tree.

The logging calls need to happen exactly once, when the project was actually added. This requires passing the map of existing projects to the Manifest constructor so it knows when a project is truly new to the entire import tree instead of just new to the current level.

CC: @carlescufi @tejlmand this covers the remaining work described in https://github.com/zephyrproject-rtos/west/pull/359

Discussion:
mbolivar: @carlescufi can you please check that this gist's `west -v manifest --resolve` output covers what you were asking for when it comes to logging what projects are added and why?

https://gist.github.com/mbolivar/e3e5f8a6121cf48b9676d2a173f761b7

It was generated with the code in this PR.

Thanks!
tejlmand: First issue discovered when building and installing.

Running `west update` fails with following error:
```
$ west update
Traceback (most recent call last):
  File "/home/tora/.local/bin/west", line 11, in <module>
    sys.exit(main())
  File "/home/tora/.local/lib/python3.6/site-packages/west/app/main.py", line 801, in main
    app = WestApp()
  File "/home/tora/.local/lib/python3.6/site-packages/west/app/main.py", line 91, in __init__
    lst = [cls() for cls in classes]
  File "/home/tora/.local/lib/python3.6/site-packages/west/app/main.py", line 91, in <listcomp>
    lst = [cls() for cls in classes]
  File "/home/tora/.local/lib/python3.6/site-packages/west/app/project.py", line 141, in __init__
    requires_workspace=False)
TypeError: __init__() got an unexpected keyword argument 'requires_workspace'
```
Going to test a bit more.
tejlmand: Same happens with `west init -l`

mbolivar: Thanks very much for review!

Patch:
diff --git a/src/west/app/main.py b/src/west/app/main.py
index a22cba5..5aeba9c 100755
--- a/src/west/app/main.py
+++ b/src/west/app/main.py
@@ -38,6 +38,33 @@ from west.manifest import Manifest, MalformedConfig, MalformedManifest, \
 from west.util import quote_sh_list, west_topdir, WestNotFound
 from west.version import __version__
 
+class LogFormatter(logging.Formatter):
+
+    def __init__(self):
+        super().__init__(fmt='%(name)s: %(message)s')
+
+class LogHandler(logging.Handler):
+
+    def __init__(self, *args, **kwargs):
+        super().__init__(*args, **kwargs)
+        self.setFormatter(LogFormatter())
+
+    def emit(self, record):
+        fmt = self.format(record)
+        lvl = record.levelno
+        if lvl > logging.CRITICAL:
+            log.die(fmt)
+        elif lvl >= logging.ERROR:
+            log.err(fmt)
+        elif lvl >= logging.WARNING:
+            log.wrn(fmt)
+        elif lvl >= logging.INFO:
+            log.inf(fmt)
+        elif lvl >= logging.DEBUG:
+            log.dbg(fmt)
+        else:
+            log.dbg(fmt, level=log.VERBOSE_EXTREME)
+
 class WestApp:
     # The west 'application' object.
     #
@@ -305,6 +332,7 @@ class WestApp:
         # Set up logging verbosity before running the command, so e.g.
         # verbose messages related to argument handling errors work
         # properly.
+        self.setup_logging(args)
         log.set_verbosity(args.verbose)
         log.dbg('args namespace:', args, level=log.VERBOSE_EXTREME)
 
@@ -356,6 +384,18 @@ class WestApp:
             # for logging its own errors.
             sys.exit(ce.returncode)
 
+    def setup_logging(self, args):
+        logger = logging.getLogger('west.manifest')
+
+        verbose = min(args.verbose, log.VERBOSE_EXTREME)
+        if verbose >= log.VERBOSE_NORMAL:
+            level = logging.DEBUG
+        else:
+            level = logging.INFO
+
+        logger.setLevel(level)
+        logger.addHandler(LogHandler())
+
     def run_extension(self, name, argv):
         # Check a program invariant. We should never get here
         # unless we were able to parse the manifest. That's where
diff --git a/src/west/app/project.py b/src/west/app/project.py
index 53fa424..0b74de0 100644
--- a/src/west/app/project.py
+++ b/src/west/app/project.py
@@ -6,7 +6,7 @@
 '''West project commands'''
 
 import argparse
-from functools import partial
+from functools import partial, lru_cache
 import os
 from os.path import join, relpath, basename, dirname, exists, isdir
 import shutil
@@ -181,8 +181,7 @@ class Init(_ProjectCommand):
         if args.local and (args.manifest_url or args.manifest_rev):
             log.die('-l cannot be combined with -m or --mr')
 
-        if shutil.which('git') is None:
-            log.die("can't find git; install it or ensure it's on your PATH")
+        die_if_no_git()
 
         if args.local:
             topdir = self.local(args)
@@ -379,6 +378,8 @@ class List(_ProjectCommand):
 
     def do_run(self, args, user_args):
         def sha_thunk(project):
+            die_if_no_git()
+
             if not project.is_cloned():
                 log.die(f'cannot get sha for uncloned project {project.name}; '
                         f'run "west update {project.name}" and retry')
@@ -388,6 +389,8 @@ class List(_ProjectCommand):
                 return f'{"N/A":40}'
 
         def cloned_thunk(project):
+            die_if_no_git()
+
             return "cloned" if project.is_cloned() else "not-cloned"
 
         def delay(func, project):
@@ -485,7 +488,7 @@ class ManifestCommand(_ProjectCommand):
         #
         # The code in main.py is responsible for handling any errors
         # and printing useful messages.
-        manifest = Manifest.from_file()
+        manifest = Manifest.from_file(topdir=self.topdir)
         dump_kwargs = {'default_flow_style': False,
                        'sort_keys': False}
 
@@ -519,6 +522,8 @@ class Diff(_ProjectCommand):
         return parser
 
     def do_run(self, args, ignored):
+        die_if_no_git()
+
         failed = []
         for project in self._cloned_projects(args):
             log.banner(f'diff for {project.name_and_path}:')
@@ -544,6 +549,8 @@ class Status(_ProjectCommand):
         return parser
 
     def do_run(self, args, user_args):
+        die_if_no_git()
+
         failed = []
         for project in self._cloned_projects(args):
             log.banner(f'status of {project.name_and_path}:')
@@ -612,6 +619,8 @@ class Update(_ProjectCommand):
         return parser
 
     def do_run(self, args, user_args):
+        die_if_no_git()
+
         self.args = args
         if args.exclude_west:
             log.wrn('ignoring --exclude-west')
@@ -1046,6 +1055,22 @@ def _post_checkout_help(project, branch, sha, is_ancestor):
         log.dbg('(To do this automatically in the future,',
                 'use "west update --rebase".)')
 
+@lru_cache(maxsize=1)
+def warn_once_if_no_git():
+    # Using an LRU cache means this gets called once. Afterwards, the
+    # memoized return value (None) is simply returned from the cache,
+    # so the warning is emitted only once per process invocation.
+    if shutil.which('git') is None:
+        log.wrn('git is not installed or cannot be found; this may fail')
+
+@lru_cache(maxsize=1)
+def die_if_no_git():
+    # Using an LRU cache means this only calls shutil.which() once.
+    # This is useful when the function is called multiple times, e.g.
+    # from the west list thunk for computing a SHA.
+    if shutil.which('git') is None:
+        log.die("can't find git; install it or ensure it's on your PATH")
+
 #
 # Special files and directories in the west workspace.
 #
diff --git a/src/west/manifest.py b/src/west/manifest.py
index 688deb2..c89fb83 100644
--- a/src/west/manifest.py
+++ b/src/west/manifest.py
@@ -1,4 +1,4 @@
-# Copyright (c) 2018, 2019 Nordic Semiconductor ASA
+# Copyright (c) 2018, 2019, 2020 Nordic Semiconductor ASA
 # Copyright 2018, 2019 Foundries.io Ltd
 #
 # SPDX-License-Identifier: Apache-2.0
@@ -11,10 +11,9 @@ import collections
 import configparser
 import enum
 import errno
-from functools import lru_cache
+import logging
 import os
 from pathlib import PurePath, Path
-import shutil
 import shlex
 import subprocess
 
@@ -22,7 +21,7 @@ from packaging.version import parse as parse_version
 import pykwalify.core
 import yaml
 
-from west import util, log
+from west import util
 import west.configuration as cfg
 
 #: Index in a Manifest.projects attribute where the `ManifestProject`
@@ -46,6 +45,8 @@ SCHEMA_VERSION = '0.6.99'
 # ^^ will be bumped to 0.7 for that release; this just marks that
 # there were changes since 0.6 and we're in a development tree.
 
+_logger = logging.getLogger(__name__)
+
 def manifest_path():
     '''Absolute path of the manifest file in the current workspace.
 
@@ -84,7 +85,8 @@ def validate(data):
         if not isinstance(data, dict):
             raise MalformedManifest(f'{as_str} is not a YAML dictionary')
     elif not isinstance(data, dict):
-        raise TypeError(f'data type {type(data)} must be str or dict')
+        raise TypeError(f'{data} has type {type(data)}, '
+                        'expected valid manifest data')
 
     if 'manifest' not in data:
         raise MalformedManifest('manifest data contains no "manifest" key')
@@ -118,7 +120,6 @@ def validate(data):
     except pykwalify.errors.SchemaError as se:
         raise MalformedManifest(se._msg) from se
 
-# TODO rewrite without enum.IntFlag if we can't move to python 3.6+
 class ImportFlag(enum.IntFlag):
     '''Bit flags for handling imports when resolving a manifest.
 
@@ -261,7 +262,7 @@ class Manifest:
 
     def __init__(self, source_file=None, source_data=None,
                  manifest_path=None, topdir=None, importer=None,
-                 import_flags=0):
+                 import_flags=0, **kwargs):
         '''
         Using `from_file` or `from_data` is usually easier than direct
         instantiation.
@@ -363,6 +364,8 @@ class Manifest:
             raise ManifestVersionError(mv.version, file=source_file) from mv
         except MalformedManifest as mm:
             self._malformed(mm.args[0], parent=mm)
+        except TypeError as te:
+            self._malformed(te.args[0], parent=te)
 
         self.projects = None
         '''Sequence of `Project` objects representing manifest
@@ -383,7 +386,13 @@ class Manifest:
         # any internal attributes needed to implement the public API.
         self._importer = importer or _default_importer
         self._import_flags = import_flags
-        self._load(source_data['manifest'], manifest_path)
+        self._load(source_data['manifest'], manifest_path,
+                   # Known projects map, from name to Project.
+                   kwargs.get('projects', {}),
+                   # name->Project predicate, Project -> Bool. True if
+                   # OK to add a project to 'projects'. A None value is
+                   # treated as a function which always returns True.
+                   kwargs.get('filter_fn'))
 
     def get_projects(self, project_ids, allow_paths=True, only_cloned=False):
         '''Get a list of `Project` objects in the manifest from
@@ -533,13 +542,22 @@ class Manifest:
         else:
             raise exc
 
-    def _load(self, manifest, path_hint):
-        # Initialize this instance's fields from values given in the
-        # manifest data, which must be validated according to the schema.
+    def _load(self, manifest, path_hint, projects, filter_fn):
+        # Initialize this instance.
+        #
+        # - manifest: manifest data, parsed and validated
+        # - path_hint: optional hint about where the manifest repo lives
+        # - projects: map from name to Project for known projects
+        # - filter_fn: predicate which returns True if it's OK to add a project
+
+        top_level = not bool(projects)
 
         if self.path:
-            log.dbg('loading manifest file:',
-                    self.path, level=log.VERBOSE_EXTREME)
+            loading_what = self.path
+        else:
+            loading_what = 'data (no file)'
+
+        _logger.debug(f'loading {loading_what}')
 
         # We want to make an ordered map from project names to
         # corresponding Project instances. Insertion order into this
@@ -549,19 +567,18 @@ class Manifest:
         # 1. Imported projects from "manifest: self: import:"
         # 2. "manifest: projects:"
         # 3. Imported projects from "manifest: projects: ... import:"
-        projects = collections.OrderedDict()
 
         # Create the ManifestProject, and import projects from "self:".
-        mp = self._load_self(manifest, path_hint, projects)
+        mp = self._load_self(manifest, path_hint, projects, filter_fn)
 
         # Add this manifest's projects to the map, then project imports.
         url_bases = {r['name']: r['url-base'] for r in
                      manifest.get('remotes', [])}
         defaults = self._load_defaults(manifest.get('defaults', {}), url_bases)
-        self._load_projects(manifest, url_bases, defaults, projects)
+        self._load_projects(manifest, url_bases, defaults, projects, filter_fn)
 
         # The manifest is resolved. Make sure paths are unique.
-        self._check_paths_are_unique(mp, projects)
+        self._check_paths_are_unique(mp, projects, top_level)
 
         # Save the results.
         self.projects = list(projects.values())
@@ -577,7 +594,9 @@ class Manifest:
                     continue
                 self._projects_by_cpath[util.canon_path(p.abspath)] = p
 
-    def _load_self(self, manifest, path_hint, projects):
+        _logger.debug(f'loaded {loading_what}')
+
+    def _load_self(self, manifest, path_hint, projects, filter_fn):
         # Handle the "self:" section in the manifest data.
 
         slf = manifest.get('self', {})
@@ -588,14 +607,11 @@ class Manifest:
         imp = slf.get('import')
         if imp is not None:
             if self._import_flags & ImportFlag.IGNORE:
-                log.dbg(f'manifest {mp} self import {imp}: ignored',
-                        level=log.VERBOSE_EXTREME)
+                _logger.debug('ignored self import')
             else:
-                log.dbg('resolving self imports for:', self.path,
-                        level=log.VERBOSE_EXTREME)
-                self._import_from_self(mp, imp, projects)
-                log.dbg('done resolving self imports for:', self.path,
-                        level=log.VERBOSE_EXTREME)
+                _logger.debug(f'resolving self import {imp}')
+                self._import_from_self(mp, imp, projects, filter_fn)
+                _logger.debug('resolved self import')
 
         return mp
 
@@ -608,12 +624,14 @@ class Manifest:
 
         assert not self._import_flags & ImportFlag.IGNORE
 
-    def _import_from_self(self, mp, imp, projects):
+    def _import_from_self(self, mp, imp, projects, filter_fn):
         # Recursive helper to import projects from the manifest repository.
         #
         # - mp: the ManifestProject
         # - imp: "self: import: <imp>" value from manifest data
         # - projects: ordered map of Project instances we've already got
+        # - filter_fn: predicate for whether it's OK to add a project,
+        #   or None if all projects are OK
         #
         # All data is read from the file system. Requests to read
         # files which don't exist or aren't ordinary files/directories
@@ -631,45 +649,51 @@ class Manifest:
         if imptype == bool:
             self._malformed(f'got "self: import: {imp}" of boolean')
         elif imptype == str:
-            self._import_path_from_self(mp, imp, projects)
+            self._import_path_from_self(mp, imp, projects, filter_fn)
         elif imptype == list:
             for subimp in imp:
-                self._import_from_self(mp, subimp, projects)
+                self._import_from_self(mp, subimp, projects, filter_fn)
         elif imptype == dict:
-            self._import_map(mp, imp, self.import_path_from_self, projects)
+            imap = self._load_imap(mp, imp)
+            # Since 'imap' may introduce additional filtering
+            # requirements on top of the existing 'filter_fn', we need
+            # to compose them, e.g. to respect import map whitelists
+            # and blacklists from higher up in the recursion tree.
+            self._import_path_from_self(mp, imap.file, projects,
+                                        _and_filters(filter_fn,
+                                                     _imap_filter(imap)))
         else:
             self._malformed(f'{mp.abspath}: "self: import: {imp}" '
                             f'has invalid type {imptype}')
 
-    def _import_path_from_self(self, mp, imp, projects):
+    def _import_path_from_self(self, mp, imp, projects, filter_fn):
         if mp.abspath:
             # Fast path, when we're working inside a fully initialized
             # topdir.
-            log.dbg('manifest repository root:', mp.abspath,
-                    level=log.VERBOSE_EXTREME)
             repo_root = Path(mp.abspath)
         else:
             # Fallback path, which is needed by at least west init. If
             # this happens too often, something may be wrong with how
             # we've implemented this. We'd like to avoid too many git
             # commands, as subprocesses are slow on windows.
-            log.dbg('searching for the manifest repository root',
-                    level=log.VERBOSE_EXTREME)
+            start = Path(self.path).parent
+            _logger.debug(
+                f'searching for manifest repository root from {start}')
             repo_root = Path(mp.git('rev-parse --show-toplevel',
                                     capture_stdout=True,
-                                    cwd=str(Path(self.path).parent)).
+                                    cwd=start).
                              stdout[:-1].      # chop off newline
                              decode('utf-8'))  # hopefully this is safe
-        p = Path(repo_root) / imp
+        p = repo_root / imp
 
         if p.is_file():
-            log.dbg(f'found submanifest: {p}', level=log.VERBOSE_EXTREME)
-            self._import_pathobj_from_self(mp, p, projects)
+            _logger.debug(f'found submanifest file: {p}')
+            self._import_pathobj_from_self(mp, p, projects, filter_fn)
         elif p.is_dir():
-            log.dbg(f'found directory of submanifests: {p}',
-                    level=log.VERBOSE_EXTREME)
+            _logger.debug(f'found submanifest directory: {p}')
             for yml in filter(_is_yml, sorted(p.iterdir())):
-                self._import_pathobj_from_self(mp, p / yml, projects)
+                self._import_pathobj_from_self(mp, p / yml, projects,
+                                               filter_fn)
         else:
             # This also happens for special files like character
             # devices, but it doesn't seem worth handling that error
@@ -677,29 +701,30 @@ class Manifest:
             self._malformed(f'{mp.abspath}: "self: import: {imp}": '
                             f'file {p} not found')
 
-    def _import_pathobj_from_self(self, mp, pathobj, projects):
+    def _import_pathobj_from_self(self, mp, pathobj, projects, filter_fn):
         # Import a Path object, which is a manifest file in the
         # manifest repository whose ManifestProject is mp.
 
+        # Destructively add the imported content into our 'projects'
+        # map, respecting our filter. The intermediate manifest is
+        # thrown away; we're basically just using __init__ as a
+        # function here.
+        #
+        # The only thing we need to do with it is check if the
+        # submanifest has west commands, add them to mp's if so.
         submp = Manifest(source_file=str(pathobj),
                          manifest_path=mp.path,
                          topdir=self.topdir,
                          importer=self._importer,
-                         import_flags=self._import_flags)
-
-        for i, project in enumerate(submp.projects):
-            if i == MANIFEST_PROJECT_INDEX:
-                # If the submanifest has west commands, add them to
-                # mp's.
-                #
-                # project.west_commands comes first because we
-                # logically treat imports from self as if they are
-                # defined before the contents in the higher level
-                # manifest.
-                mp.west_commands = self._merge_wcs(
-                    project.west_commands, mp.west_commands)
-            else:
-                self._add_project(project, projects)
+                         import_flags=self._import_flags,
+                         projects=projects,
+                         filter_fn=filter_fn).projects[MANIFEST_PROJECT_INDEX]
+        # submp.west_commands comes first because we
+        # logically treat imports from self as if they are
+        # defined before the contents in the higher level
+        # manifest.
+        mp.west_commands = self._merge_wcs(submp.west_commands,
+                                           mp.west_commands)
 
     def _load_defaults(self, md, url_bases):
         # md = manifest defaults (dictionary with values parsed from
@@ -713,43 +738,43 @@ class Manifest:
         return _defaults(mdrem, md.get('revision', _DEFAULT_REV))
 
     def _load_projects(self, manifest, url_bases, defaults, projects,
-                       path_hint=None):
+                       filter_fn):
         # Load projects and add them to the list, returning
         # information about which ones have imports that need to be
         # processed next.
 
-        if not path_hint:
-            path_hint = self.path
-
         have_imports = []
         names = set()
         for pd in manifest['projects']:
             project = self._load_project(pd, url_bases, defaults)
             name = project.name
 
+            if not _filter_ok(filter_fn, project):
+                _logger.debug(f'project {name} in file {self.path} ' +
+                              'ignored due to filters')
+                continue
+
             if name in names:
                 # Project names must be unique within a manifest.
                 self._malformed(f'project name {name} used twice in ' +
-                                (path_hint or 'the same manifest'))
+                                (self.path or 'the same manifest'))
             names.add(name)
 
             # Add the project to the map if it's new.
             added = self._add_project(project, projects)
             if added:
-                log.dbg(f'manifest file {self.path}: added {project}',
-                        level=log.VERBOSE_EXTREME)
                 # Track project imports unless we are ignoring those.
                 imp = pd.get('import')
                 if imp:
                     if self._import_flags & ImportFlag.IGNORE:
-                        log.dbg(f'project {project} import {imp} ignored',
-                                level=log.VERBOSE_EXTREME)
+                        _logger.debug(
+                            f'project {project}: ignored import ({imp})')
                     else:
                         have_imports.append((project, imp))
 
         # Handle imports from new projects in our "projects:" section.
         for project, imp in have_imports:
-            self._import_from_project(project, imp, projects)
+            self._import_from_project(project, imp, projects, filter_fn)
 
     def _load_project(self, pd, url_bases, defaults):
         # pd = project data (dictionary with values parsed from the
@@ -797,12 +822,13 @@ class Manifest:
                        west_commands=pd.get('west-commands'),
                        topdir=self.topdir)
 
-    def _import_from_project(self, project, imp, projects):
+    def _import_from_project(self, project, imp, projects, filter_fn):
         # Recursively resolve a manifest import from 'project'.
         #
         # - project: Project instance to import from
         # - imp: the parsed value of project's import key (string, list, etc.)
         # - projects: ordered dictionary of projects
+        # - filter_fn: predicate which returns True if it's OK to add a project
 
         self._assert_imports_ok()
 
@@ -812,20 +838,25 @@ class Manifest:
         if imptype == bool:
             # We should not have been called unless the import was truthy.
             assert imp
-            self._import_path_from_project(project, _WEST_YML, projects)
+            self._import_path_from_project(project, _WEST_YML, projects,
+                                           filter_fn)
         elif imptype == str:
-            self._import_path_from_project(project, imp, projects)
+            self._import_path_from_project(project, imp, projects, filter_fn)
         elif imptype == list:
             for subimp in imp:
-                self._import_from_project(project, subimp, projects)
+                self._import_from_project(project, subimp, projects, filter_fn)
         elif imptype == dict:
-            self._import_map(project, imp, self._import_path_from_project,
-                             projects)
+            imap = self._load_imap(project, imp)
+            # Similar comments about composing filters apply here as
+            # they do in _import_from_self().
+            self._import_path_from_project(project, imap.file, projects,
+                                           _and_filters(filter_fn,
+                                                        _imap_filter(imap)))
         else:
             self._malformed(f'{project.name_and_path}: invalid import {imp} '
                             f'type: {imptype}')
 
-    def _import_path_from_project(self, project, path, projects):
+    def _import_path_from_project(self, project, path, projects, filter_fn):
         # Import data from git at the given path at revision manifest-rev.
         # Fall back on self._importer if that fails.
 
@@ -846,25 +877,25 @@ class Manifest:
                 del data['manifest']['self']['path']
             except KeyError:
                 pass
-            submp = Manifest(source_data=data,
-                             manifest_path=project.path,
-                             topdir=self.topdir,
-                             importer=self._importer,
-                             import_flags=self._import_flags)
-
-            for i, subp in enumerate(submp.projects):
-                if i == MANIFEST_PROJECT_INDEX:
-                    # If the submanifest has west commands, merge them
-                    # into project's.
-                    project.west_commands = self._merge_wcs(
-                        project.west_commands, subp.west_commands)
-                else:
-                    self._add_project(subp, projects)
+
+            # Destructively add the imported content into our 'projects'
+            # map, respecting our filter.
+            submp = Manifest(
+                source_data=data,
+                manifest_path=project.path,
+                topdir=self.topdir,
+                importer=self._importer,
+                import_flags=self._import_flags,
+                projects=projects,
+                filter_fn=filter_fn).projects[MANIFEST_PROJECT_INDEX]
+
+            # If the submanifest has west commands, merge them
+            # into project's.
+            project.west_commands = self._merge_wcs(
+                project.west_commands, submp.west_commands)
 
     def _import_content_from_project(self, project, path):
-        log.dbg(f'manifest file {self.path}: resolving import {path} '
-                f'for {project}',
-                level=log.VERBOSE_EXTREME)
+        _logger.debug(f'resolving import {path} for {project}')
         if not (self._import_flags & ImportFlag.FORCE_PROJECTS) and \
            project.is_cloned():
             try:
@@ -890,21 +921,6 @@ class Manifest:
 
         return content
 
-    def _import_map(self, p, imp, base_importer, projects):
-        # Helper routine used to handle imports from self and projects.
-        # We import everything, then filter out what's not desired.
-
-        imap = self._load_imap(p, imp)
-
-        all_imported = {}
-        base_importer(p, imap.file, all_imported)
-
-        for name, project in all_imported.items():
-            if _is_imap_ok(project, imap):
-                if name in imap.rename:
-                    project.name = imap.rename[name]
-                self._add_project(project, projects)
-
     def _load_imap(self, project, imp):
         # Convert a parsed self or project import value from YAML into
         # an _import_map namedtuple.
@@ -915,8 +931,7 @@ class Manifest:
                           copy.pop('name-whitelist', []),
                           copy.pop('path-whitelist', []),
                           copy.pop('name-blacklist', []),
-                          copy.pop('path-blacklist', []),
-                          copy.pop('rename', {}))
+                          copy.pop('path-blacklist', []))
 
         # Find a useful name for the project on error.
         if isinstance(project, ManifestProject):
@@ -940,15 +955,6 @@ class Manifest:
         elif not _is_imap_list(ret.path_blacklist):
             self._malformed(f'{what}: bad import path-blacklist '
                             f'{ret.path_blacklist}')
-        elif not isinstance(ret.rename, dict):
-            self._malformed(f'{what}: rename: {ret.rename} '
-                            f'expected a map, {type(ret.rename)}')
-        else:
-            err = f"{what}: import map's rename includes "
-            for f, t in ret.rename.items():
-                if 'manifest' in [f, t]:
-                    self._malformed(err + f'{f}: {t}; '
-                                    '"manifest" is a reserved name')
 
         return ret
 
@@ -958,11 +964,15 @@ class Manifest:
 
         if project.name not in projects:
             projects[project.name] = project
+            _logger.debug(f'added project {project.name}' +
+                          (f' from {self.path}' if self.path else ''))
             return True
         else:
             return False
 
-    def _check_paths_are_unique(self, mp, projects):
+    def _check_paths_are_unique(self, mp, projects, top_level):
+        # TODO: top_level can probably go away when #327 is done.
+
         ppaths = {}
         if mp.path:
             mppath = PurePath(mp.path)
@@ -970,7 +980,7 @@ class Manifest:
             mppath = None
         for name, project in projects.items():
             pp = PurePath(project.path)
-            if pp == mppath:
+            if top_level and pp == mppath:
                 self._malformed(f'project {name} path "{project.path}" '
                                 'is taken by the manifest repository')
             other = ppaths.get(pp)
@@ -1157,8 +1167,6 @@ class Project:
             raised if git finishes with a non-zero return code
         :param cwd: directory to run git in (default: ``self.abspath``)
         '''
-        _warn_once_if_no_git()
-
         if isinstance(cmd, str):
             cmd_list = shlex.split(cmd)
         else:
@@ -1175,7 +1183,7 @@ class Project:
         args = ['git'] + cmd_list + extra_args
         cmd_str = util.quote_sh_list(args)
 
-        log.dbg(f"running '{cmd_str}' in {cwd}", level=log.VERBOSE_VERY)
+        _logger.debug(f"running '{cmd_str}' in {cwd}")
         popen = subprocess.Popen(
             args, cwd=cwd,
             stdout=subprocess.PIPE if capture_stdout else None,
@@ -1183,13 +1191,12 @@ class Project:
 
         stdout, stderr = popen.communicate()
 
-        if log.VERBOSE >= log.VERBOSE_VERY:
-            dbg_msg = f"{cmd_str} exit code: {popen.returncode}"
-            if capture_stdout:
-                dbg_msg += f'\ncaptured stdout:\n{stdout}'
-            if capture_stderr:
-                dbg_msg += f'\ncaptured stderr:\n{stderr}'
-            log.dbg(dbg_msg, level=log.VERBOSE_VERY)
+        # We use logger style % formatting here to avoid the
+        # potentially expensive overhead of formatting long
+        # stdout/stderr strings if the current log level isn't DEBUG,
+        # which is the usual case.
+        _logger.debug('"%s" exit code: %d stdout: %r stderr: %r',
+                      cmd_str, popen.returncode, stdout, stderr)
 
         if check and popen.returncode:
             raise subprocess.CalledProcessError(popen.returncode, cmd_list,
@@ -1236,9 +1243,7 @@ class Project:
         elif rc == 1:
             return False
         else:
-            log.wrn(f'{self.name_and_path}: git failed with exit code {rc}; '
-                    f'treating as if "{rev1}" is not an ancestor of "{rev2}"')
-            return False
+            raise RuntimeError(f'unexpected git merge-base result {rc}')
 
     def is_up_to_date_with(self, rev, cwd=None):
         '''Check if the project is up to date with *rev*, returning
@@ -1279,7 +1284,7 @@ class Project:
         # the top-level directory of a Git repository. Use --show-cdup
         # instead, which prints an empty string (i.e., just a newline,
         # which we strip) for the top-level directory.
-        log.dbg(f'{self.name}: checking if cloned', level=log.VERBOSE_EXTREME)
+        _logger.debug(f'{self.name}: checking if cloned')
         res = self.git('rev-parse --show-cdup', check=False,
                        capture_stderr=True, capture_stdout=True)
 
@@ -1445,8 +1450,7 @@ _defaults = collections.namedtuple('_defaults', 'remote revision')
 _import_map = collections.namedtuple('_import_map',
                                      'file '
                                      'name_whitelist path_whitelist '
-                                     'name_blacklist path_blacklist '
-                                     'rename')
+                                     'name_blacklist path_blacklist')
 _YML_EXTS = ['yml', 'yaml']
 _WEST_YML = 'west.yml'
 _SCHEMA_PATH = os.path.join(os.path.dirname(__file__), "manifest-schema.yml")
@@ -1455,14 +1459,6 @@ _EARLIEST_VER_STR = '0.6.99'  # we introduced the version feature after 0.6
 _EARLIEST_VER = parse_version(_EARLIEST_VER_STR)
 _DEFAULT_REV = 'master'
 
-@lru_cache(maxsize=1)
-def _warn_once_if_no_git():
-    # Using an LRU cache means this gets called once. Afterwards, the
-    # (nonexistent) memoized result is simply returned from the cache,
-    # so the warning is emitted only once per process invocation.
-    if shutil.which('git') is None:
-        log.wrn('Git is not installed or cannot be found')
-
 def _mpath(cp=None, topdir=None):
     # Return the value of the manifest.path configuration option
     # in *cp*, a ConfigParser. If not given, create a new one and
@@ -1494,8 +1490,7 @@ def _manifest_content_at(project, path, rev=QUAL_MANIFEST_REV_BRANCH):
     # Though this module and the "west update" implementation share
     # this code, it's an implementation detail, not API.
 
-    log.dbg(f'{project.name}: looking up path {path} type at {rev}',
-            level=log.VERBOSE_EXTREME)
+    _logger.debug(f'{project.name}: looking up path {path} type at {rev}')
 
     # Returns 'blob', 'tree', etc. for path at revision, if it exists.
     out = project.git(['ls-tree', rev, path], capture_stdout=True,
@@ -1546,7 +1541,35 @@ def _is_imap_list(value):
             (isinstance(value, list) and
              all(isinstance(item, str) for item in value)))
 
-def _is_imap_ok(project, imap):
+def _filter_ok(filter_fn, project):
+    # Returns True if the given filter_fn allows the project to be added
+    # to the current working list in a None-safe way.
+
+    return (filter_fn is None) or filter_fn(project)
+
+def _and_filters(filter_fn1, filter_fn2):
+    # Return a filter function which is the logical AND of the two
+    # arguments. Any filter_fn which is None is treated as an
+    # always-true predicate.
+    #
+    # The return value therefore needs to be used with _filter_ok().
+
+    if filter_fn1 and filter_fn2:
+        return lambda project: (filter_fn1(project) and filter_fn2(project))
+    else:
+        return filter_fn1 or filter_fn2
+
+def _imap_filter(imap):
+    # Returns either None (if no filter is necessary) or a predicate
+    # function for the given import map.
+
+    if any([imap.name_whitelist, imap.path_whitelist,
+            imap.name_blacklist, imap.path_blacklist]):
+        return lambda project: _is_imap_ok(imap, project)
+    else:
+        return None
+
+def _is_imap_ok(imap, project):
     # Return True if a project passes an import map's filters,
     # and False otherwise.
 


Test patch:
diff --git a/tests/test_manifest.py b/tests/test_manifest.py
index 70ef1a5..eb137a9 100644
--- a/tests/test_manifest.py
+++ b/tests/test_manifest.py
@@ -1676,6 +1676,21 @@ _IMPORT_SELF_MANIFESTS = [
           - west.d/02-vendor-hals.yml
           - west.d/03-applications.yml
     '''
+    # as an equivalent map:
+    '''\
+    manifest:
+      remotes:
+        - name: upstream
+          url-base: upstream.com
+      projects:
+        - name: upstream
+          remote: upstream
+          revision: refs/tags/v1.0
+          import: true
+      self:
+        import:
+          file: west.d
+    '''
 ]
 
 _IMPORT_SELF_SUBMANIFESTS = {
@@ -1920,7 +1935,7 @@ def test_import_flags_ignore(tmpdir):
     ''', import_flags=ImportFlag.IGNORE)
     assert m.get_projects(['foo'])
 
-def test_import_name_whitelist(fs_topdir):
+def test_import_map_name_whitelist(fs_topdir):
     # This tests an example from the documentation which uses
     # name-whitelist.
 
@@ -1933,11 +1948,9 @@ def test_import_name_whitelist(fs_topdir):
               url: https://git.example.com/mainline/manifest
               import:
                 name-whitelist:
-                  - app
+                  - mainline-app
                   - lib2
-                rename:
-                  app: mainline-app
-            - name: app
+            - name: downstream-app
               url: https://git.example.com/downstream/app
             - name: lib3
               path: libraries/lib3
@@ -1954,7 +1967,7 @@ def test_import_name_whitelist(fs_topdir):
                       '''
                       manifest:
                         projects:
-                          - name: app
+                          - name: mainline-app
                             path: examples/app
                             url: https://git.example.com/mainline/app
                           - name: lib
@@ -1970,19 +1983,19 @@ def test_import_name_whitelist(fs_topdir):
 
     expected = M('''\
     projects:
-       - name: mainline
-         url: https://git.example.com/mainline/manifest
-       - name: app
-         url: https://git.example.com/downstream/app
-       - name: lib3
-         path: libraries/lib3
-         url: https://git.example.com/downstream/lib3
-       - name: mainline-app
-         path: examples/app
-         url: https://git.example.com/mainline/app
-       - name: lib2
-         path: libraries/lib2
-         url: https://git.example.com/mainline/lib2
+      - name: mainline
+        url: https://git.example.com/mainline/manifest
+      - name: downstream-app
+        url: https://git.example.com/downstream/app
+      - name: lib3
+        path: libraries/lib3
+        url: https://git.example.com/downstream/lib3
+      - name: mainline-app
+        path: examples/app
+        url: https://git.example.com/mainline/app
+      - name: lib2
+        path: libraries/lib2
+        url: https://git.example.com/mainline/lib2
     ''',
                  manifest_path='mp',
                  topdir=fs_topdir).projects
@@ -1990,6 +2003,62 @@ def test_import_name_whitelist(fs_topdir):
     for a, e in zip(actual, expected):
         check_proj_consistency(a, e)
 
+def test_import_map_filter_propagation(fs_topdir):
+    # Blacklists and whitelists need to propagate down imports.
+
+    manifest_repo = fs_topdir / 'mp'
+    create_repo(manifest_repo)
+
+    # For this test, we'll write a west.yml which imports level2.yml
+    # with various whitelist and blacklist settings. The file
+    # level2.yml exists only to import level3.yml, adding a layer of
+    # imports in between west.yml (which defines the filters)
+    # and level3.yml (which defines the projects being filtered).
+    #
+    # We then make sure the filters are applied on level3.yml's
+    # projects in the final resolved manifest.
+
+    with open(manifest_repo / 'level2.yml', 'w') as f:
+        f.write('''
+        manifest:
+          projects: []
+          self:
+            import: level3.yml
+        ''')
+
+    with open(manifest_repo / 'level3.yml', 'w') as f:
+        f.write('''
+        manifest:
+          defaults: {remote: r}
+          remotes: [{name: r, url-base: u}]
+          projects:
+          - name: n1
+            path: p1
+          - name: n2
+            path: p2
+        ''')
+
+    # Since we need a few different test cases with the above setup,
+    # introduce some helpers. It might be nicer to make this a
+    # parametrized test at some point, but this will do.
+
+    import_map = {}
+    west_yml = {'manifest':
+                {'projects': [],
+                 'self': {'import': import_map}}}
+
+    def load_manifest(import_map_vals):
+        import_map.clear()
+        import_map['file'] = 'level2.yml'
+        import_map.update(import_map_vals)
+        with open(manifest_repo / 'west.yml', 'w') as f:
+            f.write(yaml.dump(west_yml))
+        return MF()
+
+    projects = load_manifest({'name-whitelist': 'n2'}).projects
+    assert len(projects) == 2
+    assert projects[1].name == 'n2'
+
 #########################################
 # Various invalid manifests