{
    "file_diffs": [
        {
            "old_file_content": "# emacs: -*- mode: python; py-indent-offset: 4; tab-width: 4; indent-tabs-mode: nil -*-\n# ex: set sts=4 ts=4 sw=4 noet:\n# ## ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ##\n#\n#   See COPYING file distributed along with the datalad package for the\n#   copyright and license terms.\n#\n# ## ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ##\n\nimport logging\nimport os\nimport sys\nimport platform\nimport logging.handlers\n\nfrom os.path import basename, dirname\n\nfrom collections import defaultdict\n\nfrom .utils import is_interactive, optional_args\nfrom .support import ansi_colors as colors\n\n__all__ = ['ColorFormatter']\n\n# Snippets from traceback borrowed from duecredit which was borrowed from\n# PyMVPA upstream/2.4.0-39-g69ad545  MIT license (the same copyright as DataLad)\n\n\ndef mbasename(s):\n    \"\"\"Custom function to include directory name if filename is too common\n\n    Also strip .py at the end\n    \"\"\"\n    base = basename(s)\n    if base.endswith('.py'):\n        base = base[:-3]\n    if base in set(['base', '__init__']):\n        base = basename(dirname(s)) + '.' + base\n    return base\n\n\nclass TraceBack(object):\n    \"\"\"Customized traceback to be included in debug messages\n    \"\"\"\n\n    def __init__(self, limit=100, collide=False):\n        \"\"\"Initialize TraceBack metric\n\n        Parameters\n        ----------\n        collide : bool\n          if True then prefix common with previous invocation gets\n          replaced with ...\n        \"\"\"\n        self.__prev = \"\"\n        self.limit = limit\n        self.collide = collide\n\n        # delayed imports and preparing the regex substitution\n        if collide:\n            import re\n            self.__prefix_re = re.compile('>[^>]*$')\n        else:\n            self.__prefix_re = None\n\n        import traceback\n        self._extract_stack = traceback.extract_stack\n\n    def __call__(self):\n        ftb = self._extract_stack(limit=self.limit+10)[:-2]\n        entries = [[mbasename(x[0]), str(x[1])]\n                   for x in ftb if mbasename(x[0]) != 'logging.__init__']\n        entries = [e for e in entries if e[0] != 'unittest']\n\n        if len(entries) > self.limit:\n            sftb = '...>'\n            entries = entries[-self.limit:]\n        else:\n            sftb = ''\n\n        if not entries:\n            return \"\"\n\n        # lets make it more consize\n        entries_out = [entries[0]]\n        for entry in entries[1:]:\n            if entry[0] == entries_out[-1][0]:\n                entries_out[-1][1] += ',%s' % entry[1]\n            else:\n                entries_out.append(entry)\n\n        sftb += '>'.join(\n            ['%s:%s' % (mbasename(x[0]), x[1]) for x in entries_out]\n        )\n\n        if self.collide:\n            # lets remove part which is common with previous invocation\n            prev_next = sftb\n            common_prefix = os.path.commonprefix((self.__prev, sftb))\n            common_prefix2 = self.__prefix_re.sub('', common_prefix)\n\n            if common_prefix2 != \"\":\n                sftb = '...' + sftb[len(common_prefix2):]\n            self.__prev = prev_next\n\n        return sftb\n\n\nclass MemoryInfo(object):\n    def __init__(self):\n        try:\n            from psutil import Process\n            process = Process(os.getpid())\n            self.memory_info = process.memory_info \\\n                if hasattr(process, 'memory_info') \\\n                else process.get_memory_info\n        except:\n            self.memory_info = None\n\n\n    def __call__(self):\n        \"\"\"Return utilization of virtual memory\n\n        Generic implementation using psutil\n        \"\"\"\n        if not self.memory_info:\n            return \"RSS/VMS: N/A\"\n        mi = self.memory_info()\n        # in later versions of psutil mi is a named tuple.\n        # but that is not the case on Debian squeeze with psutil 0.1.3\n        rss = mi[0] / 1024\n        vms = mi[1] / 1024\n        vmem = (rss, vms)\n\n        try:\n            return \"RSS/VMS: %d/%d kB\" % vmem\n        except:\n            return \"RSS/VMS: %s\" % str(vmem)\n\n# Recipe from http://stackoverflow.com/questions/384076/how-can-i-color-python-logging-output\n# by Brandon Thomson\n# Adjusted for automagic determination whether coloring is needed and\n# prefixing of multiline log lines\nclass ColorFormatter(logging.Formatter):\n\n    def __init__(self, use_color=None, log_name=False, log_pid=False):\n        if use_color is None:\n            # if 'auto' - use color only if all streams are tty\n            use_color = is_interactive()\n        self.use_color = use_color and platform.system() != 'Windows'  # don't use color on windows\n        msg = colors.format_msg(self._get_format(log_name, log_pid),\n                                self.use_color)\n        log_env = os.environ.get('DATALAD_LOG_TRACEBACK', '')\n        collide = log_env == 'collide'\n        limit = 100 if collide else int(log_env) if log_env.isdigit() else 100\n        self._tb = TraceBack(collide=collide, limit=limit) if log_env else None\n\n        self._mem = MemoryInfo() if os.environ.get('DATALAD_LOG_VMEM', '') else None\n        logging.Formatter.__init__(self, msg)\n\n    def _get_format(self, log_name=False, log_pid=False):\n        from datalad import cfg\n        from datalad.config import anything2bool\n        show_timestamps = anything2bool(cfg.get('datalad.log.timestamp', False))\n        return ((\"\" if not show_timestamps else \"$BOLD%(asctime)-15s$RESET \") +\n                (\"%(name)-15s \" if log_name else \"\") +\n                (\"{%(process)d}\" if log_pid else \"\") +\n                \"[%(levelname)s] \"\n                \"%(message)s \")\n\n    def format(self, record):\n        if record.msg.startswith('| '):\n            # If we already log smth which supposed to go without formatting, like\n            # output for running a command, just return the message and be done\n            return record.msg\n\n        levelname = record.levelname\n\n        if self.use_color and levelname in colors.LOG_LEVEL_COLORS:\n            record.levelname = colors.color_word(\n                \"{:7}\".format(levelname),\n                colors.LOG_LEVEL_COLORS[levelname],\n                force=True)\n        record.msg = record.msg.replace(\"\\n\", \"\\n| \")\n        if self._tb:\n            if not getattr(record, 'notraceback', False):\n                record.msg = self._tb() + \"  \" + record.msg\n        if self._mem:\n            record.msg = \"%s %s\" % (self._mem(), record.msg)\n\n        return logging.Formatter.format(self, record)\n\n\nclass ProgressHandler(logging.Handler):\n    from datalad.ui import ui\n\n    def __init__(self):\n        super(self.__class__, self).__init__()\n        self.pbars = {}\n\n    def emit(self, record):\n        from datalad.ui import ui\n        pid = getattr(record, 'dlm_progress')\n        update = getattr(record, 'dlm_progress_update', None)\n        # would be an actual message, not used ATM here,\n        # and the record not passed to generic handler ATM\n        # (filtered away by NoProgressLog)\n        # so no final message is printed\n        # msg = record.getMessage()\n        if pid not in self.pbars:\n            # this is new\n            pbar = ui.get_progressbar(\n                label=getattr(record, 'dlm_progress_label', ''),\n                unit=getattr(record, 'dlm_progress_unit', ''),\n                total=getattr(record, 'dlm_progress_total', None))\n            self.pbars[pid] = pbar\n        elif update is None:\n            # not an update -> done\n            # TODO if the other logging that is happening is less frontpage\n            # we may want to actually \"print\" the completion message\n            self.pbars.pop(pid).finish()\n        else:\n            # an update\n            self.pbars[pid].update(\n                update,\n                increment=getattr(record, 'dlm_progress_increment', False))\n            # Check for an updated label.\n            label = getattr(record, 'dlm_progress_label', None)\n            if label is not None:\n                self.pbars[pid].set_desc(label)\n\n\nclass NoProgressLog(logging.Filter):\n    def filter(self, record):\n        return not hasattr(record, 'dlm_progress')\n\n\nclass OnlyProgressLog(logging.Filter):\n    def filter(self, record):\n        return hasattr(record, 'dlm_progress')\n\n\ndef log_progress(lgrcall, pid, *args, **kwargs):\n    \"\"\"Helper to emit a log message on the progress of some process\n\n    Note: Whereas this helper reports on interim progress and is to be used\n    programmatically, :class:`~datalad.ui.progressbars.LogProgressBar` replaces\n    a progress bar with a single log message upon completion and can be chosen\n    by the user (config 'datalad.ui.progressbar' set to 'log').\n\n    Parameters\n    ----------\n    lgrcall : callable\n      Something like lgr.debug or lgr.info\n    pid : str\n      Some kind of ID for the process the progress is reported on.\n    *args : str\n      Log message, and potential arguments\n    total : int\n      Max progress quantity of the process.\n    label : str\n      Process description. Should be very brief, goes in front of progress bar\n      on the same line.\n    unit : str\n      Progress report unit. Should be very brief, goes after the progress bar\n      on the same line.\n    update : int\n      To which quantity to advance the progress.\n    increment : bool\n      If set, `update` is interpreted as an incremental value, not absolute.\n    \"\"\"\n    d = dict(\n        {'dlm_progress_{}'.format(n): v for n, v in kwargs.items()\n         # initial progress might be zero, but not sending it further\n         # would signal to destroy the progress bar, hence test for 'not None'\n         if v is not None},\n        dlm_progress=pid)\n    lgrcall(*args, extra=d)\n\n\n@optional_args\ndef with_result_progress(fn, label=\"Total\", unit=\" Files\"):\n    \"\"\"Wrap a progress bar, with status counts, around a function.\n\n    Parameters\n    ----------\n    fn : generator function\n        This function should accept a collection of items as a\n        positional argument and any number of keyword arguments.  After\n        processing each item in the collection, it should yield a status\n        dict.\n    label, unit : str\n        Passed to log.log_progress.\n\n    Returns\n    -------\n    A variant of `fn` that shows a progress bar.  Note that the wrapped\n    function is not a generator function; the status dicts will be\n    returned as a list.\n    \"\"\"\n    # FIXME: This emulates annexrepo.ProcessAnnexProgressIndicators.  It'd be\n    # nice to rewire things so that it could be used directly.\n\n    def count_str(count, verb, omg=False):\n        if count:\n            msg = \"{:d} {}\".format(count, verb)\n            if omg:\n                msg = colors.color_word(msg, colors.RED)\n            return msg\n\n    pid = str(fn)\n    base_label = label\n\n    def wrapped(items, **kwargs):\n        counts = defaultdict(int)\n\n        label = base_label\n        log_progress(lgr.info, pid,\n                     \"%s: starting\", label,\n                     total=len(items), label=label, unit=unit)\n\n        results = []\n        for res in fn(items, **kwargs):\n            counts[res[\"status\"]] += 1\n            count_strs = (count_str(*args)\n                          for args in [(counts[\"notneeded\"], \"skipped\", False),\n                                       (counts[\"error\"], \"failed\", True)])\n            if counts[\"notneeded\"] or counts[\"error\"]:\n                label = \"{} ({})\".format(\n                    base_label,\n                    \", \".join(filter(None, count_strs)))\n\n            log_progress(\n                lgr.error if res[\"status\"] == \"error\" else lgr.info,\n                pid,\n                \"%s: processed result%s\", base_label,\n                \" for \" + res[\"path\"] if \"path\" in res else \"\",\n                label=label, update=1, increment=True)\n            results.append(res)\n        log_progress(lgr.info, pid, \"%s: done\", base_label)\n        return results\n    return wrapped\n\n\nclass LoggerHelper(object):\n    \"\"\"Helper to establish and control a Logger\"\"\"\n\n    def __init__(self, name='datalad', logtarget=None):\n        \"\"\"\n\n        Parameters\n        ----------\n        name :\n        logtarget : string, optional\n          If we want to use our logger for other log targets, while having\n          a uniform control over them\n        \"\"\"\n        self.name = name\n        self.logtarget = logtarget\n        self.lgr = logging.getLogger(logtarget if logtarget is not None else name)\n\n    def _get_config(self, var, default=None):\n        from datalad import cfg\n        return cfg.get(self.name.lower() + '.log.' + var, default)\n\n    def set_level(self, level=None, default='INFO'):\n        \"\"\"Helper to set loglevel for an arbitrary logger\n\n        By default operates for 'datalad'.\n        TODO: deduce name from upper module name so it could be reused without changes\n        \"\"\"\n        if level is None:\n            # see if nothing in the environment\n            level = self._get_config('level')\n        if level is None:\n            level = default\n\n        try:\n            # it might be a string which still represents an int\n            log_level = int(level)\n        except ValueError:\n            # or a string which corresponds to a constant;)\n            log_level = getattr(logging, level.upper())\n\n        self.lgr.setLevel(log_level)\n        # and set other related/used loggers to the same level to prevent their\n        # talkativity, if they are not yet known to this python session, so we\n        # have little chance to \"override\" possibly set outside levels\n        for dep in ('git',):\n            if dep not in logging.Logger.manager.loggerDict:\n                logging.getLogger(dep).setLevel(log_level)\n\n    def get_initialized_logger(self, logtarget=None):\n        \"\"\"Initialize and return the logger\n\n        Parameters\n        ----------\n        target: string, optional\n          Which log target to request logger for\n        logtarget: { 'stdout', 'stderr', str }, optional\n          Where to direct the logs.  stdout and stderr stand for standard streams.\n          Any other string is considered a filename.  Multiple entries could be\n          specified comma-separated\n\n        Returns\n        -------\n        logging.Logger\n        \"\"\"\n        # By default mimic previously talkative behavior\n        logtarget = self._get_config('target', logtarget or 'stderr')\n\n        # Allow for multiple handlers being specified, comma-separated\n        if ',' in logtarget:\n            for handler_ in logtarget.split(','):\n                self.get_initialized_logger(logtarget=handler_)\n            return self.lgr\n\n        if logtarget.lower() in ('stdout', 'stderr'):\n            loghandler = logging.StreamHandler(getattr(sys, logtarget.lower()))\n            use_color = is_interactive()  # explicitly decide here\n        else:\n            # must be a simple filename\n            # Use RotatingFileHandler for possible future parametrization to keep\n            # log succinct and rotating\n            loghandler = logging.handlers.RotatingFileHandler(logtarget)\n            use_color = False\n            # I had decided not to guard this call and just raise exception to go\n            # out happen that specified file location is not writable etc.\n\n        for names_filter in 'names', 'namesre':\n            names = self._get_config(names_filter, '')\n            if names:\n                import re\n                # add a filter which would catch those\n                class LogFilter(object):\n                    \"\"\"A log filter to filter based on the log target name(s)\"\"\"\n                    def __init__(self, names):\n                        self.target_names = set(n for n in names.split(',')) \\\n                            if names_filter == 'names' \\\n                            else re.compile(names)\n                    if names_filter == 'names':\n                        def filter(self, record):\n                            return record.name in self.target_names\n                    else:\n                        def filter(self, record):\n                            return self.target_names.match(record.name)\n\n                loghandler.addFilter(LogFilter(names))\n\n        # But now improve with colors and useful information such as time\n        loghandler.setFormatter(\n            ColorFormatter(use_color=use_color,\n                           # TODO: config log.name, pid\n                           log_name=self._get_config(\"name\", False),\n                           log_pid=self._get_config(\"pid\", False),\n                           ))\n        #  logging.Formatter('%(asctime)-15s %(levelname)-6s %(message)s'))\n        self.lgr.addHandler(loghandler)\n\n        if is_interactive():\n            phandler = ProgressHandler()\n            # progress only when interactive\n            phandler.addFilter(OnlyProgressLog())\n            # no stream logs of progress messages when interactive\n            loghandler.addFilter(NoProgressLog())\n            self.lgr.addHandler(phandler)\n\n        self.set_level()  # set default logging level\n        return self.lgr\n\n\nlgr = LoggerHelper().get_initialized_logger()\n",
            "new_file_content": "# emacs: -*- mode: python; py-indent-offset: 4; tab-width: 4; indent-tabs-mode: nil -*-\n# ex: set sts=4 ts=4 sw=4 noet:\n# ## ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ##\n#\n#   See COPYING file distributed along with the datalad package for the\n#   copyright and license terms.\n#\n# ## ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ##\n\nfrom functools import partial\nimport logging\nimport os\nimport sys\nimport platform\nimport logging.handlers\n\nfrom os.path import basename, dirname\n\nfrom collections import defaultdict\n\nfrom .utils import is_interactive, optional_args\nfrom .support import ansi_colors as colors\n\n__all__ = ['ColorFormatter']\n\n# Snippets from traceback borrowed from duecredit which was borrowed from\n# PyMVPA upstream/2.4.0-39-g69ad545  MIT license (the same copyright as DataLad)\n\n\ndef mbasename(s):\n    \"\"\"Custom function to include directory name if filename is too common\n\n    Also strip .py at the end\n    \"\"\"\n    base = basename(s)\n    if base.endswith('.py'):\n        base = base[:-3]\n    if base in set(['base', '__init__']):\n        base = basename(dirname(s)) + '.' + base\n    return base\n\n\nclass TraceBack(object):\n    \"\"\"Customized traceback to be included in debug messages\n    \"\"\"\n\n    def __init__(self, limit=100, collide=False):\n        \"\"\"Initialize TraceBack metric\n\n        Parameters\n        ----------\n        collide : bool\n          if True then prefix common with previous invocation gets\n          replaced with ...\n        \"\"\"\n        self.__prev = \"\"\n        self.limit = limit\n        self.collide = collide\n\n        # delayed imports and preparing the regex substitution\n        if collide:\n            import re\n            self.__prefix_re = re.compile('>[^>]*$')\n        else:\n            self.__prefix_re = None\n\n        import traceback\n        self._extract_stack = traceback.extract_stack\n\n    def __call__(self):\n        ftb = self._extract_stack(limit=self.limit+10)[:-2]\n        entries = [[mbasename(x[0]), str(x[1])]\n                   for x in ftb if mbasename(x[0]) != 'logging.__init__']\n        entries = [e for e in entries if e[0] != 'unittest']\n\n        if len(entries) > self.limit:\n            sftb = '...>'\n            entries = entries[-self.limit:]\n        else:\n            sftb = ''\n\n        if not entries:\n            return \"\"\n\n        # lets make it more consize\n        entries_out = [entries[0]]\n        for entry in entries[1:]:\n            if entry[0] == entries_out[-1][0]:\n                entries_out[-1][1] += ',%s' % entry[1]\n            else:\n                entries_out.append(entry)\n\n        sftb += '>'.join(\n            ['%s:%s' % (mbasename(x[0]), x[1]) for x in entries_out]\n        )\n\n        if self.collide:\n            # lets remove part which is common with previous invocation\n            prev_next = sftb\n            common_prefix = os.path.commonprefix((self.__prev, sftb))\n            common_prefix2 = self.__prefix_re.sub('', common_prefix)\n\n            if common_prefix2 != \"\":\n                sftb = '...' + sftb[len(common_prefix2):]\n            self.__prev = prev_next\n\n        return sftb\n\n\nclass MemoryInfo(object):\n    def __init__(self):\n        try:\n            from psutil import Process\n            process = Process(os.getpid())\n            self.memory_info = process.memory_info \\\n                if hasattr(process, 'memory_info') \\\n                else process.get_memory_info\n        except:\n            self.memory_info = None\n\n\n    def __call__(self):\n        \"\"\"Return utilization of virtual memory\n\n        Generic implementation using psutil\n        \"\"\"\n        if not self.memory_info:\n            return \"RSS/VMS: N/A\"\n        mi = self.memory_info()\n        # in later versions of psutil mi is a named tuple.\n        # but that is not the case on Debian squeeze with psutil 0.1.3\n        rss = mi[0] / 1024\n        vms = mi[1] / 1024\n        vmem = (rss, vms)\n\n        try:\n            return \"RSS/VMS: %d/%d kB\" % vmem\n        except:\n            return \"RSS/VMS: %s\" % str(vmem)\n\n# Recipe from http://stackoverflow.com/questions/384076/how-can-i-color-python-logging-output\n# by Brandon Thomson\n# Adjusted for automagic determination whether coloring is needed and\n# prefixing of multiline log lines\nclass ColorFormatter(logging.Formatter):\n\n    def __init__(self, use_color=None, log_name=False, log_pid=False):\n        if use_color is None:\n            # if 'auto' - use color only if all streams are tty\n            use_color = is_interactive()\n        self.use_color = use_color and platform.system() != 'Windows'  # don't use color on windows\n        msg = colors.format_msg(self._get_format(log_name, log_pid),\n                                self.use_color)\n        log_env = os.environ.get('DATALAD_LOG_TRACEBACK', '')\n        collide = log_env == 'collide'\n        limit = 100 if collide else int(log_env) if log_env.isdigit() else 100\n        self._tb = TraceBack(collide=collide, limit=limit) if log_env else None\n\n        self._mem = MemoryInfo() if os.environ.get('DATALAD_LOG_VMEM', '') else None\n        logging.Formatter.__init__(self, msg)\n\n    def _get_format(self, log_name=False, log_pid=False):\n        from datalad import cfg\n        from datalad.config import anything2bool\n        show_timestamps = anything2bool(cfg.get('datalad.log.timestamp', False))\n        return ((\"\" if not show_timestamps else \"$BOLD%(asctime)-15s$RESET \") +\n                (\"%(name)-15s \" if log_name else \"\") +\n                (\"{%(process)d}\" if log_pid else \"\") +\n                \"[%(levelname)s] \"\n                \"%(message)s \")\n\n    def format(self, record):\n        if record.msg.startswith('| '):\n            # If we already log smth which supposed to go without formatting, like\n            # output for running a command, just return the message and be done\n            return record.msg\n\n        levelname = record.levelname\n\n        if self.use_color and levelname in colors.LOG_LEVEL_COLORS:\n            record.levelname = colors.color_word(\n                \"{:7}\".format(levelname),\n                colors.LOG_LEVEL_COLORS[levelname],\n                force=True)\n        record.msg = record.msg.replace(\"\\n\", \"\\n| \")\n        if self._tb:\n            if not getattr(record, 'notraceback', False):\n                record.msg = self._tb() + \"  \" + record.msg\n        if self._mem:\n            record.msg = \"%s %s\" % (self._mem(), record.msg)\n\n        return logging.Formatter.format(self, record)\n\n\nclass ProgressHandler(logging.Handler):\n    from datalad.ui import ui\n\n    def __init__(self):\n        super(self.__class__, self).__init__()\n        self.pbars = {}\n\n    def emit(self, record):\n        from datalad.ui import ui\n        pid = getattr(record, 'dlm_progress')\n        update = getattr(record, 'dlm_progress_update', None)\n        # would be an actual message, not used ATM here,\n        # and the record not passed to generic handler ATM\n        # (filtered away by NoProgressLog)\n        # so no final message is printed\n        # msg = record.getMessage()\n        if pid not in self.pbars:\n            # this is new\n            pbar = ui.get_progressbar(\n                label=getattr(record, 'dlm_progress_label', ''),\n                unit=getattr(record, 'dlm_progress_unit', ''),\n                total=getattr(record, 'dlm_progress_total', None))\n            self.pbars[pid] = pbar\n        elif update is None:\n            # not an update -> done\n            # TODO if the other logging that is happening is less frontpage\n            # we may want to actually \"print\" the completion message\n            self.pbars.pop(pid).finish()\n        else:\n            # an update\n            self.pbars[pid].update(\n                update,\n                increment=getattr(record, 'dlm_progress_increment', False))\n            # Check for an updated label.\n            label = getattr(record, 'dlm_progress_label', None)\n            if label is not None:\n                self.pbars[pid].set_desc(label)\n\n\nclass NoProgressLog(logging.Filter):\n    def filter(self, record):\n        return not hasattr(record, 'dlm_progress')\n\n\nclass OnlyProgressLog(logging.Filter):\n    def filter(self, record):\n        return hasattr(record, 'dlm_progress')\n\n\ndef filter_noninteractive_progress(logger, record):\n    level = getattr(record, \"dlm_progress_noninteractive_level\", None)\n    return level is None or level >= logger.level\n\n\ndef log_progress(lgrcall, pid, *args, **kwargs):\n    \"\"\"Helper to emit a log message on the progress of some process\n\n    Note: Whereas this helper reports on interim progress and is to be used\n    programmatically, :class:`~datalad.ui.progressbars.LogProgressBar` replaces\n    a progress bar with a single log message upon completion and can be chosen\n    by the user (config 'datalad.ui.progressbar' set to 'log').\n\n    Parameters\n    ----------\n    lgrcall : callable\n      Something like lgr.debug or lgr.info\n    pid : str\n      Some kind of ID for the process the progress is reported on.\n    *args : str\n      Log message, and potential arguments\n    total : int\n      Max progress quantity of the process.\n    label : str\n      Process description. Should be very brief, goes in front of progress bar\n      on the same line.\n    unit : str\n      Progress report unit. Should be very brief, goes after the progress bar\n      on the same line.\n    update : int\n      To which quantity to advance the progress.\n    increment : bool\n      If set, `update` is interpreted as an incremental value, not absolute.\n    noninteractive_level : int, optional\n      When a level is specified here and progress is being logged\n      non-interactively (i.e. without progress bars), do not log the message if\n      logging is not enabled for the specified level. This is useful when you\n      want all calls to be \"logged\" via the progress bar, but non-interactively\n      showing a message at the `lgrcall` level for each step would be too much\n      noise. Note that the level here only determines if the record will be\n      dropped; it will still be logged at the level of `lgrcall`.\n    \"\"\"\n    d = dict(\n        {'dlm_progress_{}'.format(n): v for n, v in kwargs.items()\n         # initial progress might be zero, but not sending it further\n         # would signal to destroy the progress bar, hence test for 'not None'\n         if v is not None},\n        dlm_progress=pid)\n    lgrcall(*args, extra=d)\n\n\n@optional_args\ndef with_result_progress(fn, label=\"Total\", unit=\" Files\"):\n    \"\"\"Wrap a progress bar, with status counts, around a function.\n\n    Parameters\n    ----------\n    fn : generator function\n        This function should accept a collection of items as a\n        positional argument and any number of keyword arguments.  After\n        processing each item in the collection, it should yield a status\n        dict.\n    label, unit : str\n        Passed to log.log_progress.\n\n    Returns\n    -------\n    A variant of `fn` that shows a progress bar.  Note that the wrapped\n    function is not a generator function; the status dicts will be\n    returned as a list.\n    \"\"\"\n    # FIXME: This emulates annexrepo.ProcessAnnexProgressIndicators.  It'd be\n    # nice to rewire things so that it could be used directly.\n\n    def count_str(count, verb, omg=False):\n        if count:\n            msg = \"{:d} {}\".format(count, verb)\n            if omg:\n                msg = colors.color_word(msg, colors.RED)\n            return msg\n\n    pid = str(fn)\n    base_label = label\n\n    def wrapped(items, **kwargs):\n        counts = defaultdict(int)\n\n        label = base_label\n        log_progress(lgr.info, pid,\n                     \"%s: starting\", label,\n                     total=len(items), label=label, unit=unit)\n\n        results = []\n        for res in fn(items, **kwargs):\n            counts[res[\"status\"]] += 1\n            count_strs = (count_str(*args)\n                          for args in [(counts[\"notneeded\"], \"skipped\", False),\n                                       (counts[\"error\"], \"failed\", True)])\n            if counts[\"notneeded\"] or counts[\"error\"]:\n                label = \"{} ({})\".format(\n                    base_label,\n                    \", \".join(filter(None, count_strs)))\n\n            log_progress(\n                lgr.error if res[\"status\"] == \"error\" else lgr.info,\n                pid,\n                \"%s: processed result%s\", base_label,\n                \" for \" + res[\"path\"] if \"path\" in res else \"\",\n                label=label, update=1, increment=True)\n            results.append(res)\n        log_progress(lgr.info, pid, \"%s: done\", base_label)\n        return results\n    return wrapped\n\n\nclass LoggerHelper(object):\n    \"\"\"Helper to establish and control a Logger\"\"\"\n\n    def __init__(self, name='datalad', logtarget=None):\n        \"\"\"\n\n        Parameters\n        ----------\n        name :\n        logtarget : string, optional\n          If we want to use our logger for other log targets, while having\n          a uniform control over them\n        \"\"\"\n        self.name = name\n        self.logtarget = logtarget\n        self.lgr = logging.getLogger(logtarget if logtarget is not None else name)\n\n    def _get_config(self, var, default=None):\n        from datalad import cfg\n        return cfg.get(self.name.lower() + '.log.' + var, default)\n\n    def set_level(self, level=None, default='INFO'):\n        \"\"\"Helper to set loglevel for an arbitrary logger\n\n        By default operates for 'datalad'.\n        TODO: deduce name from upper module name so it could be reused without changes\n        \"\"\"\n        if level is None:\n            # see if nothing in the environment\n            level = self._get_config('level')\n        if level is None:\n            level = default\n\n        try:\n            # it might be a string which still represents an int\n            log_level = int(level)\n        except ValueError:\n            # or a string which corresponds to a constant;)\n            log_level = getattr(logging, level.upper())\n\n        self.lgr.setLevel(log_level)\n        # and set other related/used loggers to the same level to prevent their\n        # talkativity, if they are not yet known to this python session, so we\n        # have little chance to \"override\" possibly set outside levels\n        for dep in ('git',):\n            if dep not in logging.Logger.manager.loggerDict:\n                logging.getLogger(dep).setLevel(log_level)\n\n    def get_initialized_logger(self, logtarget=None):\n        \"\"\"Initialize and return the logger\n\n        Parameters\n        ----------\n        target: string, optional\n          Which log target to request logger for\n        logtarget: { 'stdout', 'stderr', str }, optional\n          Where to direct the logs.  stdout and stderr stand for standard streams.\n          Any other string is considered a filename.  Multiple entries could be\n          specified comma-separated\n\n        Returns\n        -------\n        logging.Logger\n        \"\"\"\n        # By default mimic previously talkative behavior\n        logtarget = self._get_config('target', logtarget or 'stderr')\n\n        # Allow for multiple handlers being specified, comma-separated\n        if ',' in logtarget:\n            for handler_ in logtarget.split(','):\n                self.get_initialized_logger(logtarget=handler_)\n            return self.lgr\n\n        if logtarget.lower() in ('stdout', 'stderr'):\n            loghandler = logging.StreamHandler(getattr(sys, logtarget.lower()))\n            use_color = is_interactive()  # explicitly decide here\n        else:\n            # must be a simple filename\n            # Use RotatingFileHandler for possible future parametrization to keep\n            # log succinct and rotating\n            loghandler = logging.handlers.RotatingFileHandler(logtarget)\n            use_color = False\n            # I had decided not to guard this call and just raise exception to go\n            # out happen that specified file location is not writable etc.\n\n        for names_filter in 'names', 'namesre':\n            names = self._get_config(names_filter, '')\n            if names:\n                import re\n                # add a filter which would catch those\n                class LogFilter(object):\n                    \"\"\"A log filter to filter based on the log target name(s)\"\"\"\n                    def __init__(self, names):\n                        self.target_names = set(n for n in names.split(',')) \\\n                            if names_filter == 'names' \\\n                            else re.compile(names)\n                    if names_filter == 'names':\n                        def filter(self, record):\n                            return record.name in self.target_names\n                    else:\n                        def filter(self, record):\n                            return self.target_names.match(record.name)\n\n                loghandler.addFilter(LogFilter(names))\n\n        # But now improve with colors and useful information such as time\n        loghandler.setFormatter(\n            ColorFormatter(use_color=use_color,\n                           # TODO: config log.name, pid\n                           log_name=self._get_config(\"name\", False),\n                           log_pid=self._get_config(\"pid\", False),\n                           ))\n        #  logging.Formatter('%(asctime)-15s %(levelname)-6s %(message)s'))\n        self.lgr.addHandler(loghandler)\n\n        if is_interactive():\n            phandler = ProgressHandler()\n            # progress only when interactive\n            phandler.addFilter(OnlyProgressLog())\n            # no stream logs of progress messages when interactive\n            loghandler.addFilter(NoProgressLog())\n            self.lgr.addHandler(phandler)\n        else:\n            loghandler.addFilter(partial(filter_noninteractive_progress,\n                                         self.lgr))\n\n        self.set_level()  # set default logging level\n        return self.lgr\n\n\nlgr = LoggerHelper().get_initialized_logger()\n",
            "header": {
                "file": {
                    "path": "datalad/log.py"
                },
                "misc_line": null
            },
            "index_line": {
                "old_commit_hash": "6745c5436",
                "new_commit_hash": "5e61ecd89",
                "mode": "100644"
            },
            "is_binary_file": false,
            "binary_line": null,
            "minus_file": {
                "path": "a/datalad/log.py"
            },
            "plus_file": {
                "path": "b/datalad/log.py"
            },
            "hunks": [
                {
                    "descriptor": {
                        "old_range": {
                            "start": 7,
                            "length": 6
                        },
                        "new_range": {
                            "start": 7,
                            "length": 7
                        },
                        "section": ""
                    },
                    "line_group": {
                        "all_lines": [
                            {
                                "content": "#",
                                "type": "context"
                            },
                            {
                                "content": "# ## ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ##",
                                "type": "context"
                            },
                            {
                                "content": "",
                                "type": "context"
                            },
                            {
                                "content": "from functools import partial",
                                "type": "added"
                            },
                            {
                                "content": "import logging",
                                "type": "context"
                            },
                            {
                                "content": "import os",
                                "type": "context"
                            },
                            {
                                "content": "import sys",
                                "type": "context"
                            }
                        ]
                    },
                    "modified_entities": [],
                    "added_entities": [
                        {
                            "file_name": "datalad/log.py",
                            "type": "statement",
                            "name": "",
                            "content": "from functools import partial",
                            "ast_type_str": "ImportFrom",
                            "start_lineno": 10,
                            "end_lineno": 10,
                            "parent": null
                        }
                    ],
                    "deleted_entities": []
                },
                {
                    "descriptor": {
                        "old_range": {
                            "start": 240,
                            "length": 6
                        },
                        "new_range": {
                            "start": 241,
                            "length": 11
                        },
                        "section": "class OnlyProgressLog(logging.Filter):"
                    },
                    "line_group": {
                        "all_lines": [
                            {
                                "content": "        return hasattr(record, 'dlm_progress')",
                                "type": "context"
                            },
                            {
                                "content": "",
                                "type": "context"
                            },
                            {
                                "content": "",
                                "type": "context"
                            },
                            {
                                "content": "def filter_noninteractive_progress(logger, record):",
                                "type": "added"
                            },
                            {
                                "content": "    level = getattr(record, \"dlm_progress_noninteractive_level\", None)",
                                "type": "added"
                            },
                            {
                                "content": "    return level is None or level >= logger.level",
                                "type": "added"
                            },
                            {
                                "content": "",
                                "type": "added"
                            },
                            {
                                "content": "",
                                "type": "added"
                            },
                            {
                                "content": "def log_progress(lgrcall, pid, *args, **kwargs):",
                                "type": "context"
                            },
                            {
                                "content": "    \"\"\"Helper to emit a log message on the progress of some process",
                                "type": "context"
                            },
                            {
                                "content": "",
                                "type": "context"
                            }
                        ]
                    },
                    "modified_entities": [],
                    "added_entities": [
                        {
                            "file_name": "datalad/log.py",
                            "type": "function",
                            "name": "filter_noninteractive_progress",
                            "content": "def filter_noninteractive_progress(logger, record):\n    level = getattr(record, \"dlm_progress_noninteractive_level\", None)\n    return level is None or level >= logger.level",
                            "ast_type_str": "FunctionDef",
                            "start_lineno": 244,
                            "end_lineno": 246,
                            "parent": null
                        }
                    ],
                    "deleted_entities": []
                },
                {
                    "descriptor": {
                        "old_range": {
                            "start": 268,
                            "length": 6
                        },
                        "new_range": {
                            "start": 274,
                            "length": 14
                        },
                        "section": "def log_progress(lgrcall, pid, *args, **kwargs):"
                    },
                    "line_group": {
                        "all_lines": [
                            {
                                "content": "      To which quantity to advance the progress.",
                                "type": "context"
                            },
                            {
                                "content": "    increment : bool",
                                "type": "context"
                            },
                            {
                                "content": "      If set, `update` is interpreted as an incremental value, not absolute.",
                                "type": "context"
                            },
                            {
                                "content": "    noninteractive_level : int, optional",
                                "type": "added"
                            },
                            {
                                "content": "      When a level is specified here and progress is being logged",
                                "type": "added"
                            },
                            {
                                "content": "      non-interactively (i.e. without progress bars), do not log the message if",
                                "type": "added"
                            },
                            {
                                "content": "      logging is not enabled for the specified level. This is useful when you",
                                "type": "added"
                            },
                            {
                                "content": "      want all calls to be \"logged\" via the progress bar, but non-interactively",
                                "type": "added"
                            },
                            {
                                "content": "      showing a message at the `lgrcall` level for each step would be too much",
                                "type": "added"
                            },
                            {
                                "content": "      noise. Note that the level here only determines if the record will be",
                                "type": "added"
                            },
                            {
                                "content": "      dropped; it will still be logged at the level of `lgrcall`.",
                                "type": "added"
                            },
                            {
                                "content": "    \"\"\"",
                                "type": "context"
                            },
                            {
                                "content": "    d = dict(",
                                "type": "context"
                            },
                            {
                                "content": "        {'dlm_progress_{}'.format(n): v for n, v in kwargs.items()",
                                "type": "context"
                            }
                        ]
                    },
                    "modified_entities": [
                        {
                            "file_name": "datalad/log.py",
                            "type": "function",
                            "name": "log_progress",
                            "content": "def log_progress(lgrcall, pid, *args, **kwargs):\n    \"\"\"Helper to emit a log message on the progress of some process\n\n    Note: Whereas this helper reports on interim progress and is to be used\n    programmatically, :class:`~datalad.ui.progressbars.LogProgressBar` replaces\n    a progress bar with a single log message upon completion and can be chosen\n    by the user (config 'datalad.ui.progressbar' set to 'log').\n\n    Parameters\n    ----------\n    lgrcall : callable\n      Something like lgr.debug or lgr.info\n    pid : str\n      Some kind of ID for the process the progress is reported on.\n    *args : str\n      Log message, and potential arguments\n    total : int\n      Max progress quantity of the process.\n    label : str\n      Process description. Should be very brief, goes in front of progress bar\n      on the same line.\n    unit : str\n      Progress report unit. Should be very brief, goes after the progress bar\n      on the same line.\n    update : int\n      To which quantity to advance the progress.\n    increment : bool\n      If set, `update` is interpreted as an incremental value, not absolute.\n    noninteractive_level : int, optional\n      When a level is specified here and progress is being logged\n      non-interactively (i.e. without progress bars), do not log the message if\n      logging is not enabled for the specified level. This is useful when you\n      want all calls to be \"logged\" via the progress bar, but non-interactively\n      showing a message at the `lgrcall` level for each step would be too much\n      noise. Note that the level here only determines if the record will be\n      dropped; it will still be logged at the level of `lgrcall`.\n    \"\"\"\n    d = dict(\n        {'dlm_progress_{}'.format(n): v for n, v in kwargs.items()\n         # initial progress might be zero, but not sending it further\n         # would signal to destroy the progress bar, hence test for 'not None'\n         if v is not None},\n        dlm_progress=pid)\n    lgrcall(*args, extra=d)",
                            "ast_type_str": "FunctionDef",
                            "start_lineno": 249,
                            "end_lineno": 292,
                            "parent": null
                        }
                    ],
                    "added_entities": [],
                    "deleted_entities": []
                },
                {
                    "descriptor": {
                        "old_range": {
                            "start": 464,
                            "length": 6
                        },
                        "new_range": {
                            "start": 478,
                            "length": 9
                        },
                        "section": "class LoggerHelper(object):"
                    },
                    "line_group": {
                        "all_lines": [
                            {
                                "content": "            # no stream logs of progress messages when interactive",
                                "type": "context"
                            },
                            {
                                "content": "            loghandler.addFilter(NoProgressLog())",
                                "type": "context"
                            },
                            {
                                "content": "            self.lgr.addHandler(phandler)",
                                "type": "context"
                            },
                            {
                                "content": "        else:",
                                "type": "added"
                            },
                            {
                                "content": "            loghandler.addFilter(partial(filter_noninteractive_progress,",
                                "type": "added"
                            },
                            {
                                "content": "                                         self.lgr))",
                                "type": "added"
                            },
                            {
                                "content": "",
                                "type": "context"
                            },
                            {
                                "content": "        self.set_level()  # set default logging level",
                                "type": "context"
                            },
                            {
                                "content": "        return self.lgr",
                                "type": "context"
                            }
                        ]
                    },
                    "modified_entities": [
                        {
                            "file_name": "datalad/log.py",
                            "type": "method",
                            "name": "LoggerHelper.get_initialized_logger",
                            "content": "class LoggerHelper(object):\n    \"\"\"Helper to establish and control a Logger\"\"\"\n\n    def __init__(self, name='datalad', logtarget=None):\n        \"\"\"\n\n        Parameters\n        ----------\n        name :\n        logtarget : string, optional\n          If we want to use our logger for other log targets, while having\n          a uniform control over them\n        \"\"\"\n        self.name = name\n        self.logtarget = logtarget\n        self.lgr = logging.getLogger(logtarget if logtarget is not None else name)\n\n    def _get_config(self, var, default=None):\n        from datalad import cfg\n        return cfg.get(self.name.lower() + '.log.' + var, default)\n\n    def set_level(self, level=None, default='INFO'):\n        \"\"\"Helper to set loglevel for an arbitrary logger\n\n        By default operates for 'datalad'.\n        TODO: deduce name from upper module name so it could be reused without changes\n        \"\"\"\n        if level is None:\n            # see if nothing in the environment\n            level = self._get_config('level')\n        if level is None:\n            level = default\n\n        try:\n            # it might be a string which still represents an int\n            log_level = int(level)\n        except ValueError:\n            # or a string which corresponds to a constant;)\n            log_level = getattr(logging, level.upper())\n\n        self.lgr.setLevel(log_level)\n        # and set other related/used loggers to the same level to prevent their\n        # talkativity, if they are not yet known to this python session, so we\n        # have little chance to \"override\" possibly set outside levels\n        for dep in ('git',):\n            if dep not in logging.Logger.manager.loggerDict:\n                logging.getLogger(dep).setLevel(log_level)\n\n    def get_initialized_logger(self, logtarget=None):\n        \"\"\"Initialize and return the logger\n\n        Parameters\n        ----------\n        target: string, optional\n          Which log target to request logger for\n        logtarget: { 'stdout', 'stderr', str }, optional\n          Where to direct the logs.  stdout and stderr stand for standard streams.\n          Any other string is considered a filename.  Multiple entries could be\n          specified comma-separated\n\n        Returns\n        -------\n        logging.Logger\n        \"\"\"\n        # By default mimic previously talkative behavior\n        logtarget = self._get_config('target', logtarget or 'stderr')\n\n        # Allow for multiple handlers being specified, comma-separated\n        if ',' in logtarget:\n            for handler_ in logtarget.split(','):\n                self.get_initialized_logger(logtarget=handler_)\n            return self.lgr\n\n        if logtarget.lower() in ('stdout', 'stderr'):\n            loghandler = logging.StreamHandler(getattr(sys, logtarget.lower()))\n            use_color = is_interactive()  # explicitly decide here\n        else:\n            # must be a simple filename\n            # Use RotatingFileHandler for possible future parametrization to keep\n            # log succinct and rotating\n            loghandler = logging.handlers.RotatingFileHandler(logtarget)\n            use_color = False\n            # I had decided not to guard this call and just raise exception to go\n            # out happen that specified file location is not writable etc.\n\n        for names_filter in 'names', 'namesre':\n            names = self._get_config(names_filter, '')\n            if names:\n                import re\n                # add a filter which would catch those\n                class LogFilter(object):\n                    \"\"\"A log filter to filter based on the log target name(s)\"\"\"\n                    def __init__(self, names):\n                        self.target_names = set(n for n in names.split(',')) \\\n                            if names_filter == 'names' \\\n                            else re.compile(names)\n                    if names_filter == 'names':\n                        def filter(self, record):\n                            return record.name in self.target_names\n                    else:\n                        def filter(self, record):\n                            return self.target_names.match(record.name)\n\n                loghandler.addFilter(LogFilter(names))\n\n        # But now improve with colors and useful information such as time\n        loghandler.setFormatter(\n            ColorFormatter(use_color=use_color,\n                           # TODO: config log.name, pid\n                           log_name=self._get_config(\"name\", False),\n                           log_pid=self._get_config(\"pid\", False),\n                           ))\n        #  logging.Formatter('%(asctime)-15s %(levelname)-6s %(message)s'))\n        self.lgr.addHandler(loghandler)\n\n        if is_interactive():\n            phandler = ProgressHandler()\n            # progress only when interactive\n            phandler.addFilter(OnlyProgressLog())\n            # no stream logs of progress messages when interactive\n            loghandler.addFilter(NoProgressLog())\n            self.lgr.addHandler(phandler)\n        else:\n            loghandler.addFilter(partial(filter_noninteractive_progress,\n                                         self.lgr))\n\n        self.set_level()  # set default logging level\n        return self.lgr",
                            "ast_type_str": "ClassDef",
                            "start_lineno": 407,
                            "end_lineno": 486,
                            "parent": {
                                "file_name": "datalad/log.py",
                                "type": "class",
                                "name": "LoggerHelper",
                                "content": "class LoggerHelper(object):\n    \"\"\"Helper to establish and control a Logger\"\"\"\n\n    def __init__(self, name='datalad', logtarget=None):\n        \"\"\"\n\n        Parameters\n        ----------\n        name :\n        logtarget : string, optional\n          If we want to use our logger for other log targets, while having\n          a uniform control over them\n        \"\"\"\n        self.name = name\n        self.logtarget = logtarget\n        self.lgr = logging.getLogger(logtarget if logtarget is not None else name)\n\n    def _get_config(self, var, default=None):\n        from datalad import cfg\n        return cfg.get(self.name.lower() + '.log.' + var, default)\n\n    def set_level(self, level=None, default='INFO'):\n        \"\"\"Helper to set loglevel for an arbitrary logger\n\n        By default operates for 'datalad'.\n        TODO: deduce name from upper module name so it could be reused without changes\n        \"\"\"\n        if level is None:\n            # see if nothing in the environment\n            level = self._get_config('level')\n        if level is None:\n            level = default\n\n        try:\n            # it might be a string which still represents an int\n            log_level = int(level)\n        except ValueError:\n            # or a string which corresponds to a constant;)\n            log_level = getattr(logging, level.upper())\n\n        self.lgr.setLevel(log_level)\n        # and set other related/used loggers to the same level to prevent their\n        # talkativity, if they are not yet known to this python session, so we\n        # have little chance to \"override\" possibly set outside levels\n        for dep in ('git',):\n            if dep not in logging.Logger.manager.loggerDict:\n                logging.getLogger(dep).setLevel(log_level)\n\n    def get_initialized_logger(self, logtarget=None):\n        \"\"\"Initialize and return the logger\n\n        Parameters\n        ----------\n        target: string, optional\n          Which log target to request logger for\n        logtarget: { 'stdout', 'stderr', str }, optional\n          Where to direct the logs.  stdout and stderr stand for standard streams.\n          Any other string is considered a filename.  Multiple entries could be\n          specified comma-separated\n\n        Returns\n        -------\n        logging.Logger\n        \"\"\"\n        # By default mimic previously talkative behavior\n        logtarget = self._get_config('target', logtarget or 'stderr')\n\n        # Allow for multiple handlers being specified, comma-separated\n        if ',' in logtarget:\n            for handler_ in logtarget.split(','):\n                self.get_initialized_logger(logtarget=handler_)\n            return self.lgr\n\n        if logtarget.lower() in ('stdout', 'stderr'):\n            loghandler = logging.StreamHandler(getattr(sys, logtarget.lower()))\n            use_color = is_interactive()  # explicitly decide here\n        else:\n            # must be a simple filename\n            # Use RotatingFileHandler for possible future parametrization to keep\n            # log succinct and rotating\n            loghandler = logging.handlers.RotatingFileHandler(logtarget)\n            use_color = False\n            # I had decided not to guard this call and just raise exception to go\n            # out happen that specified file location is not writable etc.\n\n        for names_filter in 'names', 'namesre':\n            names = self._get_config(names_filter, '')\n            if names:\n                import re\n                # add a filter which would catch those\n                class LogFilter(object):\n                    \"\"\"A log filter to filter based on the log target name(s)\"\"\"\n                    def __init__(self, names):\n                        self.target_names = set(n for n in names.split(',')) \\\n                            if names_filter == 'names' \\\n                            else re.compile(names)\n                    if names_filter == 'names':\n                        def filter(self, record):\n                            return record.name in self.target_names\n                    else:\n                        def filter(self, record):\n                            return self.target_names.match(record.name)\n\n                loghandler.addFilter(LogFilter(names))\n\n        # But now improve with colors and useful information such as time\n        loghandler.setFormatter(\n            ColorFormatter(use_color=use_color,\n                           # TODO: config log.name, pid\n                           log_name=self._get_config(\"name\", False),\n                           log_pid=self._get_config(\"pid\", False),\n                           ))\n        #  logging.Formatter('%(asctime)-15s %(levelname)-6s %(message)s'))\n        self.lgr.addHandler(loghandler)\n\n        if is_interactive():\n            phandler = ProgressHandler()\n            # progress only when interactive\n            phandler.addFilter(OnlyProgressLog())\n            # no stream logs of progress messages when interactive\n            loghandler.addFilter(NoProgressLog())\n            self.lgr.addHandler(phandler)\n        else:\n            loghandler.addFilter(partial(filter_noninteractive_progress,\n                                         self.lgr))\n\n        self.set_level()  # set default logging level\n        return self.lgr",
                                "ast_type_str": "ClassDef",
                                "start_lineno": 359,
                                "end_lineno": 486,
                                "parent": null
                            }
                        },
                        {
                            "file_name": "datalad/log.py",
                            "type": "class",
                            "name": "LoggerHelper",
                            "content": "class LoggerHelper(object):\n    \"\"\"Helper to establish and control a Logger\"\"\"\n\n    def __init__(self, name='datalad', logtarget=None):\n        \"\"\"\n\n        Parameters\n        ----------\n        name :\n        logtarget : string, optional\n          If we want to use our logger for other log targets, while having\n          a uniform control over them\n        \"\"\"\n        self.name = name\n        self.logtarget = logtarget\n        self.lgr = logging.getLogger(logtarget if logtarget is not None else name)\n\n    def _get_config(self, var, default=None):\n        from datalad import cfg\n        return cfg.get(self.name.lower() + '.log.' + var, default)\n\n    def set_level(self, level=None, default='INFO'):\n        \"\"\"Helper to set loglevel for an arbitrary logger\n\n        By default operates for 'datalad'.\n        TODO: deduce name from upper module name so it could be reused without changes\n        \"\"\"\n        if level is None:\n            # see if nothing in the environment\n            level = self._get_config('level')\n        if level is None:\n            level = default\n\n        try:\n            # it might be a string which still represents an int\n            log_level = int(level)\n        except ValueError:\n            # or a string which corresponds to a constant;)\n            log_level = getattr(logging, level.upper())\n\n        self.lgr.setLevel(log_level)\n        # and set other related/used loggers to the same level to prevent their\n        # talkativity, if they are not yet known to this python session, so we\n        # have little chance to \"override\" possibly set outside levels\n        for dep in ('git',):\n            if dep not in logging.Logger.manager.loggerDict:\n                logging.getLogger(dep).setLevel(log_level)\n\n    def get_initialized_logger(self, logtarget=None):\n        \"\"\"Initialize and return the logger\n\n        Parameters\n        ----------\n        target: string, optional\n          Which log target to request logger for\n        logtarget: { 'stdout', 'stderr', str }, optional\n          Where to direct the logs.  stdout and stderr stand for standard streams.\n          Any other string is considered a filename.  Multiple entries could be\n          specified comma-separated\n\n        Returns\n        -------\n        logging.Logger\n        \"\"\"\n        # By default mimic previously talkative behavior\n        logtarget = self._get_config('target', logtarget or 'stderr')\n\n        # Allow for multiple handlers being specified, comma-separated\n        if ',' in logtarget:\n            for handler_ in logtarget.split(','):\n                self.get_initialized_logger(logtarget=handler_)\n            return self.lgr\n\n        if logtarget.lower() in ('stdout', 'stderr'):\n            loghandler = logging.StreamHandler(getattr(sys, logtarget.lower()))\n            use_color = is_interactive()  # explicitly decide here\n        else:\n            # must be a simple filename\n            # Use RotatingFileHandler for possible future parametrization to keep\n            # log succinct and rotating\n            loghandler = logging.handlers.RotatingFileHandler(logtarget)\n            use_color = False\n            # I had decided not to guard this call and just raise exception to go\n            # out happen that specified file location is not writable etc.\n\n        for names_filter in 'names', 'namesre':\n            names = self._get_config(names_filter, '')\n            if names:\n                import re\n                # add a filter which would catch those\n                class LogFilter(object):\n                    \"\"\"A log filter to filter based on the log target name(s)\"\"\"\n                    def __init__(self, names):\n                        self.target_names = set(n for n in names.split(',')) \\\n                            if names_filter == 'names' \\\n                            else re.compile(names)\n                    if names_filter == 'names':\n                        def filter(self, record):\n                            return record.name in self.target_names\n                    else:\n                        def filter(self, record):\n                            return self.target_names.match(record.name)\n\n                loghandler.addFilter(LogFilter(names))\n\n        # But now improve with colors and useful information such as time\n        loghandler.setFormatter(\n            ColorFormatter(use_color=use_color,\n                           # TODO: config log.name, pid\n                           log_name=self._get_config(\"name\", False),\n                           log_pid=self._get_config(\"pid\", False),\n                           ))\n        #  logging.Formatter('%(asctime)-15s %(levelname)-6s %(message)s'))\n        self.lgr.addHandler(loghandler)\n\n        if is_interactive():\n            phandler = ProgressHandler()\n            # progress only when interactive\n            phandler.addFilter(OnlyProgressLog())\n            # no stream logs of progress messages when interactive\n            loghandler.addFilter(NoProgressLog())\n            self.lgr.addHandler(phandler)\n        else:\n            loghandler.addFilter(partial(filter_noninteractive_progress,\n                                         self.lgr))\n\n        self.set_level()  # set default logging level\n        return self.lgr",
                            "ast_type_str": "ClassDef",
                            "start_lineno": 359,
                            "end_lineno": 486,
                            "parent": null
                        }
                    ],
                    "added_entities": [],
                    "deleted_entities": []
                }
            ]
        },
        {
            "old_file_content": "# emacs: -*- mode: python-mode; py-indent-offset: 4; tab-width: 4; indent-tabs-mode: nil -*-\n# ex: set sts=4 ts=4 sw=4 noet:\n# ## ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ##\n#\n#   See COPYING file distributed along with the datalad package for the\n#   copyright and license terms.\n#\n# ## ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ##\n\"\"\"Test logging facilities \"\"\"\n\nimport logging\nimport os.path\nfrom os.path import exists\n\nfrom logging import makeLogRecord\n\nfrom unittest.mock import patch\n\nfrom datalad.log import (\n    ColorFormatter,\n    LoggerHelper,\n    TraceBack,\n)\nfrom datalad import cfg\nfrom datalad.support.constraints import EnsureBool\nfrom datalad.support import ansi_colors as colors\n\nfrom datalad.tests.utils import (\n    assert_equal,\n    assert_in,\n    assert_not_in,\n    assert_re_in,\n    known_failure_githubci_win,\n    ok_,\n    ok_endswith,\n    swallow_logs,\n    with_tempfile,\n)\n\n# pretend we are in interactive mode so we could check if coloring is\n# disabled\n@patch(\"datalad.log.is_interactive\", lambda: True)\n@with_tempfile\ndef test_logging_to_a_file(dst):\n    ok_(not exists(dst))\n\n    lgr = LoggerHelper(\"dataladtest-1\").get_initialized_logger(logtarget=dst)\n    ok_(exists(dst))  # nothing was logged -- no file created\n\n    msg = \"Oh my god, they killed Kenny\"\n    lgr.error(msg)\n    with open(dst) as f:\n        lines = f.readlines()\n    assert_equal(len(lines), 1, \"Read more than a single log line: %s\" %  lines)\n    line = lines[0]\n    ok_(msg in line)\n    ok_('\\033[' not in line,\n        msg=\"There should be no color formatting in log files. Got: %s\" % line)\n    # verify that time stamp and level are present in the log line\n    # do not want to rely on not having race conditions around date/time changes\n    # so matching just with regexp\n    # (...)? is added to swallow possible traceback logs\n    regex = \"\\[ERROR\\]\"\n    if EnsureBool()(cfg.get('datalad.log.timestamp', False)):\n        regex = \"\\d{4}-\\d{2}-\\d{2} \\d{2}:\\d{2}:\\d{2},\\d{3} \" + regex\n    if EnsureBool()(cfg.get('datalad.log.vmem', False)):\n        regex += ' RSS/VMS: \\S+/\\S+( \\S+)?\\s*'\n    regex += \"(\\s+\\S+\\s*)? \" + msg\n    assert_re_in(regex, line, match=True)\n    # Close all handlers so windows is happy -- apparently not closed fast enough\n    for handler in lgr.handlers:\n        handler.close()\n\n\n@with_tempfile\ndef test_logtarget_via_env_variable(dst):\n    with patch.dict('os.environ', {'DATALADTEST_LOG_TARGET': dst}):\n        ok_(not exists(dst))\n        lgr = LoggerHelper(\"dataladtest-2\").get_initialized_logger()\n        ok_(not exists(dst))\n    # just to see that mocking patch worked\n    ok_('DATALADTEST_LOG_TARGET' not in os.environ)\n\n\n@with_tempfile\n@with_tempfile\ndef test_mutliple_targets(dst1, dst2):\n    ok_(not exists(dst1))\n    ok_(not exists(dst2))\n    lgr = LoggerHelper(\"dataladtest-3\").get_initialized_logger(\n        logtarget=\"%s,%s\" % (dst1, dst2))\n    ok_(exists(dst1))\n    ok_(exists(dst2))\n\n    msg = \"Oh my god, they killed Kenny\"\n    lgr.error(msg)\n    for dst in (dst1, dst2):\n        with open(dst) as f:\n            lines = f.readlines()\n        assert_equal(len(lines), 1, \"Read more than a single log line: %s\" %  lines)\n        ok_(msg in lines[0])\n    # Close all handlers so windows is happy -- apparently not closed fast enough\n    for handler in lgr.handlers:\n        handler.close()\n\n\ndef check_filters(name):\n    with swallow_logs(new_level=logging.DEBUG, name=name) as cml:\n        lgr1 = logging.getLogger(name + '.goodone')\n        lgr2 = logging.getLogger(name + '.anotherone')\n        lgr3 = logging.getLogger(name + '.bad')\n        lgr1.debug('log1')\n        lgr2.info('log2')\n        lgr3.info('log3')\n        assert_in('log1', cml.out)\n        assert_in('log2', cml.out)\n        assert 'log3' not in cml.out\n\n\ndef test_filters():\n    def _mock_names(self, v, d=None):\n        return 'datalad1.goodone,datalad1.anotherone' if v == 'names' else d\n    with patch.object(LoggerHelper, '_get_config', _mock_names):\n        LoggerHelper('datalad1').get_initialized_logger()\n        check_filters('datalad1')\n\n    def _mock_namesre(self, v, d=None):\n        return 'datalad.*one' if v == 'namesre' else d\n    with patch.object(LoggerHelper, '_get_config', _mock_namesre):\n        LoggerHelper('datalad2').get_initialized_logger()\n        check_filters('datalad2')\n\n\ndef test_traceback():\n    from inspect import currentframe, getframeinfo\n    # do not move lines below among themselves -- we rely on consistent line numbers ;)\n    tb_line = getframeinfo(currentframe()).lineno + 2\n    def rec(tb, n):\n        return rec(tb, n-1) if n else tb()\n    tb1 = rec(TraceBack(), 10)\n    ok_endswith(tb1, \">test_log:%d,%s\" % (tb_line + 1, \",\".join([str(tb_line)]*10)))\n\n    # we limit to the last 100\n    tb1 = rec(TraceBack(collide=True), 110)\n    ok_endswith(tb1, \"...>test_log:%s\" % (\",\".join([str(tb_line)]*100)))\n\n\n@known_failure_githubci_win\ndef test_color_formatter():\n\n    # want to make sure that coloring doesn't get \"stuck\"\n    for use_color in False, True, False:\n        # we can't reuse the same object since it gets colored etc inplace\n        rec = makeLogRecord(\n            dict(msg='very long message',\n                 levelname='DEBUG',\n                 name='some name'))\n\n        cf = ColorFormatter(use_color=use_color)\n        (assert_in if use_color else assert_not_in)(colors.RESET_SEQ, cf.format(rec))\n\n\n# TODO: somehow test is stdout/stderr get their stuff\n",
            "new_file_content": "# emacs: -*- mode: python-mode; py-indent-offset: 4; tab-width: 4; indent-tabs-mode: nil -*-\n# ex: set sts=4 ts=4 sw=4 noet:\n# ## ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ##\n#\n#   See COPYING file distributed along with the datalad package for the\n#   copyright and license terms.\n#\n# ## ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ##\n\"\"\"Test logging facilities \"\"\"\n\nimport logging\nimport os.path\nfrom os.path import exists\n\nfrom logging import makeLogRecord\n\nfrom unittest.mock import patch\n\nfrom datalad.log import (\n    ColorFormatter,\n    LoggerHelper,\n    log_progress,\n    TraceBack,\n)\nfrom datalad import cfg\nfrom datalad.support.constraints import EnsureBool\nfrom datalad.support import ansi_colors as colors\n\nfrom datalad.tests.utils import (\n    assert_equal,\n    assert_in,\n    assert_not_in,\n    assert_re_in,\n    known_failure_githubci_win,\n    ok_,\n    ok_endswith,\n    swallow_logs,\n    with_tempfile,\n)\n\n# pretend we are in interactive mode so we could check if coloring is\n# disabled\n@patch(\"datalad.log.is_interactive\", lambda: True)\n@with_tempfile\ndef test_logging_to_a_file(dst):\n    ok_(not exists(dst))\n\n    lgr = LoggerHelper(\"dataladtest-1\").get_initialized_logger(logtarget=dst)\n    ok_(exists(dst))  # nothing was logged -- no file created\n\n    msg = \"Oh my god, they killed Kenny\"\n    lgr.error(msg)\n    with open(dst) as f:\n        lines = f.readlines()\n    assert_equal(len(lines), 1, \"Read more than a single log line: %s\" %  lines)\n    line = lines[0]\n    ok_(msg in line)\n    ok_('\\033[' not in line,\n        msg=\"There should be no color formatting in log files. Got: %s\" % line)\n    # verify that time stamp and level are present in the log line\n    # do not want to rely on not having race conditions around date/time changes\n    # so matching just with regexp\n    # (...)? is added to swallow possible traceback logs\n    regex = \"\\[ERROR\\]\"\n    if EnsureBool()(cfg.get('datalad.log.timestamp', False)):\n        regex = \"\\d{4}-\\d{2}-\\d{2} \\d{2}:\\d{2}:\\d{2},\\d{3} \" + regex\n    if EnsureBool()(cfg.get('datalad.log.vmem', False)):\n        regex += ' RSS/VMS: \\S+/\\S+( \\S+)?\\s*'\n    regex += \"(\\s+\\S+\\s*)? \" + msg\n    assert_re_in(regex, line, match=True)\n    # Close all handlers so windows is happy -- apparently not closed fast enough\n    for handler in lgr.handlers:\n        handler.close()\n\n\n@with_tempfile\ndef test_logtarget_via_env_variable(dst):\n    with patch.dict('os.environ', {'DATALADTEST_LOG_TARGET': dst}):\n        ok_(not exists(dst))\n        lgr = LoggerHelper(\"dataladtest-2\").get_initialized_logger()\n        ok_(not exists(dst))\n    # just to see that mocking patch worked\n    ok_('DATALADTEST_LOG_TARGET' not in os.environ)\n\n\n@with_tempfile\n@with_tempfile\ndef test_mutliple_targets(dst1, dst2):\n    ok_(not exists(dst1))\n    ok_(not exists(dst2))\n    lgr = LoggerHelper(\"dataladtest-3\").get_initialized_logger(\n        logtarget=\"%s,%s\" % (dst1, dst2))\n    ok_(exists(dst1))\n    ok_(exists(dst2))\n\n    msg = \"Oh my god, they killed Kenny\"\n    lgr.error(msg)\n    for dst in (dst1, dst2):\n        with open(dst) as f:\n            lines = f.readlines()\n        assert_equal(len(lines), 1, \"Read more than a single log line: %s\" %  lines)\n        ok_(msg in lines[0])\n    # Close all handlers so windows is happy -- apparently not closed fast enough\n    for handler in lgr.handlers:\n        handler.close()\n\n\ndef check_filters(name):\n    with swallow_logs(new_level=logging.DEBUG, name=name) as cml:\n        lgr1 = logging.getLogger(name + '.goodone')\n        lgr2 = logging.getLogger(name + '.anotherone')\n        lgr3 = logging.getLogger(name + '.bad')\n        lgr1.debug('log1')\n        lgr2.info('log2')\n        lgr3.info('log3')\n        assert_in('log1', cml.out)\n        assert_in('log2', cml.out)\n        assert 'log3' not in cml.out\n\n\ndef test_filters():\n    def _mock_names(self, v, d=None):\n        return 'datalad1.goodone,datalad1.anotherone' if v == 'names' else d\n    with patch.object(LoggerHelper, '_get_config', _mock_names):\n        LoggerHelper('datalad1').get_initialized_logger()\n        check_filters('datalad1')\n\n    def _mock_namesre(self, v, d=None):\n        return 'datalad.*one' if v == 'namesre' else d\n    with patch.object(LoggerHelper, '_get_config', _mock_namesre):\n        LoggerHelper('datalad2').get_initialized_logger()\n        check_filters('datalad2')\n\n\ndef test_traceback():\n    from inspect import currentframe, getframeinfo\n    # do not move lines below among themselves -- we rely on consistent line numbers ;)\n    tb_line = getframeinfo(currentframe()).lineno + 2\n    def rec(tb, n):\n        return rec(tb, n-1) if n else tb()\n    tb1 = rec(TraceBack(), 10)\n    ok_endswith(tb1, \">test_log:%d,%s\" % (tb_line + 1, \",\".join([str(tb_line)]*10)))\n\n    # we limit to the last 100\n    tb1 = rec(TraceBack(collide=True), 110)\n    ok_endswith(tb1, \"...>test_log:%s\" % (\",\".join([str(tb_line)]*100)))\n\n\n@known_failure_githubci_win\ndef test_color_formatter():\n\n    # want to make sure that coloring doesn't get \"stuck\"\n    for use_color in False, True, False:\n        # we can't reuse the same object since it gets colored etc inplace\n        rec = makeLogRecord(\n            dict(msg='very long message',\n                 levelname='DEBUG',\n                 name='some name'))\n\n        cf = ColorFormatter(use_color=use_color)\n        (assert_in if use_color else assert_not_in)(colors.RESET_SEQ, cf.format(rec))\n\n\n# TODO: somehow test is stdout/stderr get their stuff\n\n\n@patch(\"datalad.log.is_interactive\", lambda: False)\ndef test_log_progress_noninteractive_filter():\n    name = \"dl-test\"\n    lgr = LoggerHelper(name).get_initialized_logger()\n    pbar_id = \"lp_test\"\n    with swallow_logs(new_level=logging.INFO, name=name) as cml:\n        log_progress(lgr.info, pbar_id, \"Start\", label=\"testing\", total=3)\n        log_progress(lgr.info, pbar_id, \"THERE0\", update=1)\n        log_progress(lgr.info, pbar_id, \"NOT\", update=1,\n                     noninteractive_level=logging.DEBUG)\n        log_progress(lgr.info, pbar_id, \"THERE1\", update=1,\n                     noninteractive_level=logging.INFO)\n        log_progress(lgr.info, pbar_id, \"Done\")\n        for present in [\"Start\", \"THERE0\", \"THERE1\", \"Done\"]:\n            assert_in(present, cml.out)\n        assert_not_in(\"NOT\", cml.out)\n",
            "header": {
                "file": {
                    "path": "datalad/tests/test_log.py"
                },
                "misc_line": null
            },
            "index_line": {
                "old_commit_hash": "81a277cb7",
                "new_commit_hash": "90de9ef4a",
                "mode": "100644"
            },
            "is_binary_file": false,
            "binary_line": null,
            "minus_file": {
                "path": "a/datalad/tests/test_log.py"
            },
            "plus_file": {
                "path": "b/datalad/tests/test_log.py"
            },
            "hunks": [
                {
                    "descriptor": {
                        "old_range": {
                            "start": 19,
                            "length": 6
                        },
                        "new_range": {
                            "start": 19,
                            "length": 7
                        },
                        "section": "from unittest.mock import patch"
                    },
                    "line_group": {
                        "all_lines": [
                            {
                                "content": "from datalad.log import (",
                                "type": "context"
                            },
                            {
                                "content": "    ColorFormatter,",
                                "type": "context"
                            },
                            {
                                "content": "    LoggerHelper,",
                                "type": "context"
                            },
                            {
                                "content": "    log_progress,",
                                "type": "added"
                            },
                            {
                                "content": "    TraceBack,",
                                "type": "context"
                            },
                            {
                                "content": ")",
                                "type": "context"
                            },
                            {
                                "content": "from datalad import cfg",
                                "type": "context"
                            }
                        ]
                    },
                    "modified_entities": [],
                    "added_entities": [
                        {
                            "file_name": "datalad/tests/test_log.py",
                            "type": "statement",
                            "name": "",
                            "content": "from datalad.log import (\n    ColorFormatter,\n    LoggerHelper,\n    log_progress,\n    TraceBack,\n)",
                            "ast_type_str": "ImportFrom",
                            "start_lineno": 19,
                            "end_lineno": 24,
                            "parent": null
                        }
                    ],
                    "deleted_entities": []
                },
                {
                    "descriptor": {
                        "old_range": {
                            "start": 161,
                            "length": 3
                        },
                        "new_range": {
                            "start": 162,
                            "length": 21
                        },
                        "section": "def test_color_formatter():"
                    },
                    "line_group": {
                        "all_lines": [
                            {
                                "content": "",
                                "type": "context"
                            },
                            {
                                "content": "",
                                "type": "context"
                            },
                            {
                                "content": "# TODO: somehow test is stdout/stderr get their stuff",
                                "type": "context"
                            },
                            {
                                "content": "",
                                "type": "added"
                            },
                            {
                                "content": "",
                                "type": "added"
                            },
                            {
                                "content": "@patch(\"datalad.log.is_interactive\", lambda: False)",
                                "type": "added"
                            },
                            {
                                "content": "def test_log_progress_noninteractive_filter():",
                                "type": "added"
                            },
                            {
                                "content": "    name = \"dl-test\"",
                                "type": "added"
                            },
                            {
                                "content": "    lgr = LoggerHelper(name).get_initialized_logger()",
                                "type": "added"
                            },
                            {
                                "content": "    pbar_id = \"lp_test\"",
                                "type": "added"
                            },
                            {
                                "content": "    with swallow_logs(new_level=logging.INFO, name=name) as cml:",
                                "type": "added"
                            },
                            {
                                "content": "        log_progress(lgr.info, pbar_id, \"Start\", label=\"testing\", total=3)",
                                "type": "added"
                            },
                            {
                                "content": "        log_progress(lgr.info, pbar_id, \"THERE0\", update=1)",
                                "type": "added"
                            },
                            {
                                "content": "        log_progress(lgr.info, pbar_id, \"NOT\", update=1,",
                                "type": "added"
                            },
                            {
                                "content": "                     noninteractive_level=logging.DEBUG)",
                                "type": "added"
                            },
                            {
                                "content": "        log_progress(lgr.info, pbar_id, \"THERE1\", update=1,",
                                "type": "added"
                            },
                            {
                                "content": "                     noninteractive_level=logging.INFO)",
                                "type": "added"
                            },
                            {
                                "content": "        log_progress(lgr.info, pbar_id, \"Done\")",
                                "type": "added"
                            },
                            {
                                "content": "        for present in [\"Start\", \"THERE0\", \"THERE1\", \"Done\"]:",
                                "type": "added"
                            },
                            {
                                "content": "            assert_in(present, cml.out)",
                                "type": "added"
                            },
                            {
                                "content": "        assert_not_in(\"NOT\", cml.out)",
                                "type": "added"
                            },
                            {
                                "content": "",
                                "type": "context"
                            }
                        ]
                    },
                    "modified_entities": [],
                    "added_entities": [
                        {
                            "file_name": "datalad/tests/test_log.py",
                            "type": "function",
                            "name": "test_log_progress_noninteractive_filter",
                            "content": "def test_log_progress_noninteractive_filter():\n    name = \"dl-test\"\n    lgr = LoggerHelper(name).get_initialized_logger()\n    pbar_id = \"lp_test\"\n    with swallow_logs(new_level=logging.INFO, name=name) as cml:\n        log_progress(lgr.info, pbar_id, \"Start\", label=\"testing\", total=3)\n        log_progress(lgr.info, pbar_id, \"THERE0\", update=1)\n        log_progress(lgr.info, pbar_id, \"NOT\", update=1,\n                     noninteractive_level=logging.DEBUG)\n        log_progress(lgr.info, pbar_id, \"THERE1\", update=1,\n                     noninteractive_level=logging.INFO)\n        log_progress(lgr.info, pbar_id, \"Done\")\n        for present in [\"Start\", \"THERE0\", \"THERE1\", \"Done\"]:\n            assert_in(present, cml.out)\n        assert_not_in(\"NOT\", cml.out)",
                            "ast_type_str": "FunctionDef",
                            "start_lineno": 168,
                            "end_lineno": 182,
                            "parent": null
                        }
                    ],
                    "deleted_entities": []
                }
            ]
        }
    ],
    "old_commit_hash": "2b03324dc8da24884a7b262dd4f8c62a0a111f9c^",
    "new_commit_hash": "2b03324dc8da24884a7b262dd4f8c62a0a111f9c",
    "commit_message": "ENH: log_progress: Support dropping non-interactive messages\n\nlog_progress() conveniently uses plain log message instead of a\nprogress bar when operating non-interactively, but there can be a\nmismatch between what makes sense to show with a progress bar tick and\nwhat makes sense to show as a plain log message.  For operations with\na lot of ticks, log_progress(lgr.info, ...)  interactively is simply\nmoving the progress bar, but non-interactively it is dumping a level\nof information to the logs that isn't desirable for INFO level\nmessages.\n\nMake it possible to tell log_progress() machinery to filter out a\nmessage when operating non-interactively if logging isn't enabled for\nsome specified level.  To continue the example above, specifying\nlog_progress(lgr.info, ..., noninteractive_level=logging.DEBUG) leads\nto a filter rejecting the INFO-level log message when the logger is\nconfigured above logging.DEBUG.",
    "commit_date": "2020-03-13T18:45:35-04:00",
    "metadata": {}
}
{
    "repo_name": "datalad",
    "new_commit_hash": "2b03324dc8da24884a7b262dd4f8c62a0a111f9c",
    "test_file_codes": [
        "# emacs: -*- mode: python-mode; py-indent-offset: 4; tab-width: 4; indent-tabs-mode: nil -*-\n# ex: set sts=4 ts=4 sw=4 noet:\n# ## ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ##\n#\n#   See COPYING file distributed along with the datalad package for the\n#   copyright and license terms.\n#\n# ## ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ##\n\"\"\"Test logging facilities \"\"\"\n\nimport logging\nimport os.path\nfrom os.path import exists\n\nfrom logging import makeLogRecord\n\nfrom unittest.mock import patch\n\nfrom datalad.log import (\n    ColorFormatter,\n    LoggerHelper,\n    log_progress,\n    TraceBack,\n)\nfrom datalad import cfg\nfrom datalad.support.constraints import EnsureBool\nfrom datalad.support import ansi_colors as colors\n\nfrom datalad.tests.utils import (\n    assert_equal,\n    assert_in,\n    assert_not_in,\n    assert_re_in,\n    known_failure_githubci_win,\n    ok_,\n    ok_endswith,\n    swallow_logs,\n    with_tempfile,\n)\n\n# pretend we are in interactive mode so we could check if coloring is\n# disabled\n@patch(\"datalad.log.is_interactive\", lambda: True)\n@with_tempfile\ndef test_logging_to_a_file(dst):\n    ok_(not exists(dst))\n\n    lgr = LoggerHelper(\"dataladtest-1\").get_initialized_logger(logtarget=dst)\n    ok_(exists(dst))  # nothing was logged -- no file created\n\n    msg = \"Oh my god, they killed Kenny\"\n    lgr.error(msg)\n    with open(dst) as f:\n        lines = f.readlines()\n    assert_equal(len(lines), 1, \"Read more than a single log line: %s\" %  lines)\n    line = lines[0]\n    ok_(msg in line)\n    ok_('\\033[' not in line,\n        msg=\"There should be no color formatting in log files. Got: %s\" % line)\n    # verify that time stamp and level are present in the log line\n    # do not want to rely on not having race conditions around date/time changes\n    # so matching just with regexp\n    # (...)? is added to swallow possible traceback logs\n    regex = \"\\[ERROR\\]\"\n    if EnsureBool()(cfg.get('datalad.log.timestamp', False)):\n        regex = \"\\d{4}-\\d{2}-\\d{2} \\d{2}:\\d{2}:\\d{2},\\d{3} \" + regex\n    if EnsureBool()(cfg.get('datalad.log.vmem', False)):\n        regex += ' RSS/VMS: \\S+/\\S+( \\S+)?\\s*'\n    regex += \"(\\s+\\S+\\s*)? \" + msg\n    assert_re_in(regex, line, match=True)\n    # Close all handlers so windows is happy -- apparently not closed fast enough\n    for handler in lgr.handlers:\n        handler.close()\n\n\n@with_tempfile\ndef test_logtarget_via_env_variable(dst):\n    with patch.dict('os.environ', {'DATALADTEST_LOG_TARGET': dst}):\n        ok_(not exists(dst))\n        lgr = LoggerHelper(\"dataladtest-2\").get_initialized_logger()\n        ok_(not exists(dst))\n    # just to see that mocking patch worked\n    ok_('DATALADTEST_LOG_TARGET' not in os.environ)\n\n\n@with_tempfile\n@with_tempfile\ndef test_mutliple_targets(dst1, dst2):\n    ok_(not exists(dst1))\n    ok_(not exists(dst2))\n    lgr = LoggerHelper(\"dataladtest-3\").get_initialized_logger(\n        logtarget=\"%s,%s\" % (dst1, dst2))\n    ok_(exists(dst1))\n    ok_(exists(dst2))\n\n    msg = \"Oh my god, they killed Kenny\"\n    lgr.error(msg)\n    for dst in (dst1, dst2):\n        with open(dst) as f:\n            lines = f.readlines()\n        assert_equal(len(lines), 1, \"Read more than a single log line: %s\" %  lines)\n        ok_(msg in lines[0])\n    # Close all handlers so windows is happy -- apparently not closed fast enough\n    for handler in lgr.handlers:\n        handler.close()\n\n\ndef check_filters(name):\n    with swallow_logs(new_level=logging.DEBUG, name=name) as cml:\n        lgr1 = logging.getLogger(name + '.goodone')\n        lgr2 = logging.getLogger(name + '.anotherone')\n        lgr3 = logging.getLogger(name + '.bad')\n        lgr1.debug('log1')\n        lgr2.info('log2')\n        lgr3.info('log3')\n        assert_in('log1', cml.out)\n        assert_in('log2', cml.out)\n        assert 'log3' not in cml.out\n\n\ndef test_filters():\n    def _mock_names(self, v, d=None):\n        return 'datalad1.goodone,datalad1.anotherone' if v == 'names' else d\n    with patch.object(LoggerHelper, '_get_config', _mock_names):\n        LoggerHelper('datalad1').get_initialized_logger()\n        check_filters('datalad1')\n\n    def _mock_namesre(self, v, d=None):\n        return 'datalad.*one' if v == 'namesre' else d\n    with patch.object(LoggerHelper, '_get_config', _mock_namesre):\n        LoggerHelper('datalad2').get_initialized_logger()\n        check_filters('datalad2')\n\n\ndef test_traceback():\n    from inspect import currentframe, getframeinfo\n    # do not move lines below among themselves -- we rely on consistent line numbers ;)\n    tb_line = getframeinfo(currentframe()).lineno + 2\n    def rec(tb, n):\n        return rec(tb, n-1) if n else tb()\n    tb1 = rec(TraceBack(), 10)\n    ok_endswith(tb1, \">test_log:%d,%s\" % (tb_line + 1, \",\".join([str(tb_line)]*10)))\n\n    # we limit to the last 100\n    tb1 = rec(TraceBack(collide=True), 110)\n    ok_endswith(tb1, \"...>test_log:%s\" % (\",\".join([str(tb_line)]*100)))\n\n\n@known_failure_githubci_win\ndef test_color_formatter():\n\n    # want to make sure that coloring doesn't get \"stuck\"\n    for use_color in False, True, False:\n        # we can't reuse the same object since it gets colored etc inplace\n        rec = makeLogRecord(\n            dict(msg='very long message',\n                 levelname='DEBUG',\n                 name='some name'))\n\n        cf = ColorFormatter(use_color=use_color)\n        (assert_in if use_color else assert_not_in)(colors.RESET_SEQ, cf.format(rec))\n\n\n# TODO: somehow test is stdout/stderr get their stuff\n\n\n@patch(\"datalad.log.is_interactive\", lambda: False)\ndef test_log_progress_noninteractive_filter():\n    name = \"dl-test\"\n    lgr = LoggerHelper(name).get_initialized_logger()\n    pbar_id = \"lp_test\"\n    with swallow_logs(new_level=logging.INFO, name=name) as cml:\n        log_progress(lgr.info, pbar_id, \"Start\", label=\"testing\", total=3)\n        log_progress(lgr.info, pbar_id, \"THERE0\", update=1)\n        log_progress(lgr.info, pbar_id, \"NOT\", update=1,\n                     noninteractive_level=logging.DEBUG)\n        log_progress(lgr.info, pbar_id, \"THERE1\", update=1,\n                     noninteractive_level=logging.INFO)\n        log_progress(lgr.info, pbar_id, \"Done\")\n        for present in [\"Start\", \"THERE0\", \"THERE1\", \"Done\"]:\n            assert_in(present, cml.out)\n        assert_not_in(\"NOT\", cml.out)\n",
        "import pytest\nimport tempfile\nimport os\n\n\n@pytest.fixture\ndef path():\n    with tempfile.TemporaryDirectory() as tmpdir:\n        yield tmpdir\n\n\n@pytest.fixture(autouse=True)\ndef setup_git_config():\n    with tempfile.TemporaryDirectory() as home:\n        old_home = os.environ.get(\"HOME\")\n        os.environ[\"HOME\"] = home\n        os.system('git config --global user.name \"DataLad Tester\"')\n        os.system('git config --global user.email \"test@example.com\"')\n        yield\n        if old_home:\n            os.environ[\"HOME\"] = old_home\n"
    ],
    "test_file_names": [
        "test_1.py",
        "conftest.py"
    ],
    "setup_res_code": 0,
    "setup_res_stdout": "Starting Datalad installation attempts...\nVerifying installation...\nDatalad version: 0.12.2.dev516\n✅ Installation successful!\nSuccessfully installed Datalad using Python 3.9\n",
    "setup_res_stderr": "Using CPython 3.9.21\nCreating virtual environment at: .venv\nActivate with: source .venv/bin/activate\nResolved 25 packages in 44ms\nInstalled 25 packages in 6.55s\n + coverage==7.6.10\n + docopt==0.6.2\n + exceptiongroup==1.2.2\n + grabbit==0.2.6\n + importlib-resources==6.4.5\n + iniconfig==2.0.0\n + nibabel==5.3.2\n + num2words==0.5.14\n + numpy==2.0.2\n + packaging==24.2\n + pandas==2.2.3\n + patsy==1.0.1\n + pluggy==1.5.0\n + pybids==0.6.5\n + pytest==8.3.4\n + pytest-cov==6.0.0\n + python-dateutil==2.9.0.post0\n + pytz==2024.2\n + scipy==1.13.1\n + setuptools==75.6.0\n + six==1.17.0\n + tomli==2.2.1\n + typing-extensions==4.12.2\n + tzdata==2024.2\n + zipp==3.21.0\nResolved 63 packages in 4.32s\nPrepared 1 package in 1.60s\nInstalled 57 packages in 42ms\n + annexremote==1.6.6\n + appdirs==1.4.4\n + backports-tarfile==1.2.0\n + beautifulsoup4==4.12.3\n + boto==2.49.0\n + certifi==2024.12.14\n + cffi==1.17.1\n + chardet==5.2.0\n + charset-normalizer==3.4.1\n + citeproc-py==0.6.0\n + cryptography==44.0.0\n + datalad==0.12.2 (from file:///home/gcpuser/buckets/local_repoeval_bucket/repos/datalad_2b03324dc8da24884a7b262dd4f8c62a0a111f9c)\n + deprecated==1.2.15\n + distro==1.9.0\n + duecredit==0.10.2\n + exifread==3.0.0\n + fasteners==0.19\n + httpretty==1.1.4\n + humanize==4.11.0\n + idna==3.10\n + importlib-metadata==8.5.0\n + iso8601==2.1.0\n + jaraco-classes==3.4.0\n + jaraco-context==6.0.1\n + jaraco-functools==4.1.0\n + jeepney==0.8.0\n + jsmin==3.0.1\n + keyring==25.6.0\n + keyrings-alt==5.0.2\n + looseversion==1.3.0\n + lxml==5.3.0\n + more-itertools==10.5.0\n + msgpack==1.1.0\n + multidict==6.1.0\n + mutagen==1.47.0\n + nose==1.3.7\n + patool==1.15.0\n + pillow==11.0.0\n + propcache==0.2.1\n + pycparser==2.22\n + pygithub==2.5.0\n + pyjwt==2.10.1\n + pynacl==1.5.0\n + pyperclip==1.9.0\n + python-xmp-toolkit==2.0.2\n + pyyaml==6.0.2\n + requests==2.32.3\n + requests-ftp==0.3.1\n + secretstorage==3.3.3\n + simplejson==3.19.3\n + soupsieve==2.6\n + tqdm==4.67.1\n + urllib3==1.26.20\n + vcrpy==7.0.0\n + whoosh==2.7.4\n + wrapt==1.17.0\n + yarl==1.18.3\nResolved 97 packages in 75ms\nInstalled 32 packages in 71ms\n + alabaster==0.7.16\n + asv==0.6.4\n + asv-runner==0.2.1\n + babel==2.16.0\n + build==1.2.2.post1\n + distlib==0.3.9\n + docutils==0.21.2\n + filelock==3.16.1\n + gprof2dot==2024.6.6\n + imagesize==1.4.1\n + jinja2==3.1.5\n + json5==0.10.0\n + markupsafe==3.0.2\n + nose-timer==1.0.1\n + platformdirs==4.3.6\n + psutil==6.1.1\n + pygments==2.18.0\n + pympler==1.1\n + pypandoc==1.14\n + pyproject-hooks==1.2.0\n + snowballstemmer==2.2.0\n + sphinx==7.4.7\n + sphinx-rtd-theme==3.0.2\n + sphinxcontrib-applehelp==2.0.0\n + sphinxcontrib-devhelp==2.0.0\n + sphinxcontrib-htmlhelp==2.1.0\n + sphinxcontrib-jquery==4.1\n + sphinxcontrib-jsmath==1.0.1\n + sphinxcontrib-qthelp==2.0.0\n + sphinxcontrib-serializinghtml==2.0.0\n + tabulate==0.9.0\n + virtualenv==20.28.0\n",
    "new_commit_res_code": 1,
    "new_commit_res_stdout": "============================= test session starts ==============================\nplatform linux -- Python 3.9.21, pytest-8.3.4, pluggy-1.5.0\nrootdir: /home/gcpuser/buckets/local_repoeval_bucket/repos/datalad_2b03324dc8da24884a7b262dd4f8c62a0a111f9c\nplugins: cov-6.0.0\ncollected 7 items\n\nr2e_tests/test_1.py EEE.F..                                              [100%]\n\n==================================== ERRORS ====================================\n___________________ ERROR at setup of test_logging_to_a_file ___________________\nfile /home/gcpuser/buckets/local_repoeval_bucket/repos/datalad_2b03324dc8da24884a7b262dd4f8c62a0a111f9c/r2e_tests/test_1.py, line 43\n  @patch(\"datalad.log.is_interactive\", lambda: True)\n  @with_tempfile\n  def test_logging_to_a_file(dst):\nE       fixture 'dst' not found\n>       available fixtures: cache, capfd, capfdbinary, caplog, capsys, capsysbinary, cov, doctest_namespace, monkeypatch, no_cover, path, pytestconfig, record_property, record_testsuite_property, record_xml_attribute, recwarn, setup_git_config, tmp_path, tmp_path_factory, tmpdir, tmpdir_factory\n>       use 'pytest --fixtures [testpath]' for help on them.\n\n/home/gcpuser/buckets/local_repoeval_bucket/repos/datalad_2b03324dc8da24884a7b262dd4f8c62a0a111f9c/r2e_tests/test_1.py:43\n______________ ERROR at setup of test_logtarget_via_env_variable _______________\nfile /home/gcpuser/buckets/local_repoeval_bucket/repos/datalad_2b03324dc8da24884a7b262dd4f8c62a0a111f9c/r2e_tests/test_1.py, line 76\n  @with_tempfile\n  def test_logtarget_via_env_variable(dst):\nE       fixture 'dst' not found\n>       available fixtures: cache, capfd, capfdbinary, caplog, capsys, capsysbinary, cov, doctest_namespace, monkeypatch, no_cover, path, pytestconfig, record_property, record_testsuite_property, record_xml_attribute, recwarn, setup_git_config, tmp_path, tmp_path_factory, tmpdir, tmpdir_factory\n>       use 'pytest --fixtures [testpath]' for help on them.\n\n/home/gcpuser/buckets/local_repoeval_bucket/repos/datalad_2b03324dc8da24884a7b262dd4f8c62a0a111f9c/r2e_tests/test_1.py:76\n___________________ ERROR at setup of test_mutliple_targets ____________________\nfile /home/gcpuser/buckets/local_repoeval_bucket/repos/datalad_2b03324dc8da24884a7b262dd4f8c62a0a111f9c/r2e_tests/test_1.py, line 86\n  @with_tempfile\n  @with_tempfile\n  def test_mutliple_targets(dst1, dst2):\nE       fixture 'dst1' not found\n>       available fixtures: cache, capfd, capfdbinary, caplog, capsys, capsysbinary, cov, doctest_namespace, monkeypatch, no_cover, path, pytestconfig, record_property, record_testsuite_property, record_xml_attribute, recwarn, setup_git_config, tmp_path, tmp_path_factory, tmpdir, tmpdir_factory\n>       use 'pytest --fixtures [testpath]' for help on them.\n\n/home/gcpuser/buckets/local_repoeval_bucket/repos/datalad_2b03324dc8da24884a7b262dd4f8c62a0a111f9c/r2e_tests/test_1.py:86\n=================================== FAILURES ===================================\n________________________________ test_traceback ________________________________\n\n    def test_traceback():\n        from inspect import currentframe, getframeinfo\n        # do not move lines below among themselves -- we rely on consistent line numbers ;)\n        tb_line = getframeinfo(currentframe()).lineno + 2\n        def rec(tb, n):\n            return rec(tb, n-1) if n else tb()\n        tb1 = rec(TraceBack(), 10)\n>       ok_endswith(tb1, \">test_log:%d,%s\" % (tb_line + 1, \",\".join([str(tb_line)]*10)))\n\nr2e_tests/test_1.py:142: \n_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ \ndatalad/tests/utils.py:399: in ok_endswith\n    ok_(s.endswith(suffix),\n_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ \n\nexpr = False\nmsg = \"String 'runpy:197,87>__main__:9>config.__init__:201,175>_hooks:513>_manager:120>_callers:103>main:330,283,337>_hooks:...:141,140,140,140,140,140,140,140,140,140,140' doesn't end with '>test_log:141,140,140,140,140,140,140,140,140,140,140'\"\n\n    def ok_(expr, msg=None):\n        \"\"\"Shorthand for assert. Saves 3 whole characters!\n        \"\"\"\n        if not expr:\n>           raise AssertionError(msg)\nE           AssertionError: String 'runpy:197,87>__main__:9>config.__init__:201,175>_hooks:513>_manager:120>_callers:103>main:330,283,337>_hooks:513>_manager:120>_callers:103>main:362>_hooks:513>_manager:120>_callers:103>runner:113,132,241,341,242>_hooks:513>_manager:120>_callers:103>runner:174>python:1627>_hooks:513>_manager:120>_callers:103>python:159>test_1:141,140,140,140,140,140,140,140,140,140,140' doesn't end with '>test_log:141,140,140,140,140,140,140,140,140,140,140'\n\n.venv/lib/python3.9/site-packages/nose/tools/trivial.py:22: AssertionError\n==================================== PASSES ====================================\n_________________________________ test_filters _________________________________\n------------------------------ Captured log call -------------------------------\nDEBUG    datalad1.goodone:test_1.py:113 log1\nINFO     datalad1.anotherone:test_1.py:114 log2\nINFO     datalad1.bad:test_1.py:115 log3\nDEBUG    datalad2.goodone:test_1.py:113 log1\nINFO     datalad2.anotherone:test_1.py:114 log2\nINFO     datalad2.bad:test_1.py:115 log3\n___________________ test_log_progress_noninteractive_filter ____________________\n------------------------------ Captured log call -------------------------------\nINFO     dl-test:log.py:292 Start\nINFO     dl-test:log.py:292 THERE0\nINFO     dl-test:log.py:292 NOT\nINFO     dl-test:log.py:292 THERE1\nINFO     dl-test:log.py:292 Done\n=========================== short test summary info ============================\nPASSED r2e_tests/test_1.py::test_filters\nPASSED r2e_tests/test_1.py::test_color_formatter\nPASSED r2e_tests/test_1.py::test_log_progress_noninteractive_filter\nERROR r2e_tests/test_1.py::test_logging_to_a_file\nERROR r2e_tests/test_1.py::test_logtarget_via_env_variable\nERROR r2e_tests/test_1.py::test_mutliple_targets\nFAILED r2e_tests/test_1.py::test_traceback - AssertionError: String 'runpy:19...\n==================== 1 failed, 3 passed, 3 errors in 1.39s =====================\n",
    "new_commit_res_stderr": "",
    "old_commit_res_code": 1,
    "old_commit_res_stdout": "============================= test session starts ==============================\nplatform linux -- Python 3.9.21, pytest-8.3.4, pluggy-1.5.0\nrootdir: /home/gcpuser/buckets/local_repoeval_bucket/repos/datalad_2b03324dc8da24884a7b262dd4f8c62a0a111f9c\nplugins: cov-6.0.0\ncollected 7 items\n\nr2e_tests/test_1.py EEE.F.F                                              [100%]\n\n==================================== ERRORS ====================================\n___________________ ERROR at setup of test_logging_to_a_file ___________________\nfile /home/gcpuser/buckets/local_repoeval_bucket/repos/datalad_2b03324dc8da24884a7b262dd4f8c62a0a111f9c/r2e_tests/test_1.py, line 43\n  @patch(\"datalad.log.is_interactive\", lambda: True)\n  @with_tempfile\n  def test_logging_to_a_file(dst):\nE       fixture 'dst' not found\n>       available fixtures: cache, capfd, capfdbinary, caplog, capsys, capsysbinary, cov, doctest_namespace, monkeypatch, no_cover, path, pytestconfig, record_property, record_testsuite_property, record_xml_attribute, recwarn, setup_git_config, tmp_path, tmp_path_factory, tmpdir, tmpdir_factory\n>       use 'pytest --fixtures [testpath]' for help on them.\n\n/home/gcpuser/buckets/local_repoeval_bucket/repos/datalad_2b03324dc8da24884a7b262dd4f8c62a0a111f9c/r2e_tests/test_1.py:43\n______________ ERROR at setup of test_logtarget_via_env_variable _______________\nfile /home/gcpuser/buckets/local_repoeval_bucket/repos/datalad_2b03324dc8da24884a7b262dd4f8c62a0a111f9c/r2e_tests/test_1.py, line 76\n  @with_tempfile\n  def test_logtarget_via_env_variable(dst):\nE       fixture 'dst' not found\n>       available fixtures: cache, capfd, capfdbinary, caplog, capsys, capsysbinary, cov, doctest_namespace, monkeypatch, no_cover, path, pytestconfig, record_property, record_testsuite_property, record_xml_attribute, recwarn, setup_git_config, tmp_path, tmp_path_factory, tmpdir, tmpdir_factory\n>       use 'pytest --fixtures [testpath]' for help on them.\n\n/home/gcpuser/buckets/local_repoeval_bucket/repos/datalad_2b03324dc8da24884a7b262dd4f8c62a0a111f9c/r2e_tests/test_1.py:76\n___________________ ERROR at setup of test_mutliple_targets ____________________\nfile /home/gcpuser/buckets/local_repoeval_bucket/repos/datalad_2b03324dc8da24884a7b262dd4f8c62a0a111f9c/r2e_tests/test_1.py, line 86\n  @with_tempfile\n  @with_tempfile\n  def test_mutliple_targets(dst1, dst2):\nE       fixture 'dst1' not found\n>       available fixtures: cache, capfd, capfdbinary, caplog, capsys, capsysbinary, cov, doctest_namespace, monkeypatch, no_cover, path, pytestconfig, record_property, record_testsuite_property, record_xml_attribute, recwarn, setup_git_config, tmp_path, tmp_path_factory, tmpdir, tmpdir_factory\n>       use 'pytest --fixtures [testpath]' for help on them.\n\n/home/gcpuser/buckets/local_repoeval_bucket/repos/datalad_2b03324dc8da24884a7b262dd4f8c62a0a111f9c/r2e_tests/test_1.py:86\n=================================== FAILURES ===================================\n________________________________ test_traceback ________________________________\n\n    def test_traceback():\n        from inspect import currentframe, getframeinfo\n        # do not move lines below among themselves -- we rely on consistent line numbers ;)\n        tb_line = getframeinfo(currentframe()).lineno + 2\n        def rec(tb, n):\n            return rec(tb, n-1) if n else tb()\n        tb1 = rec(TraceBack(), 10)\n>       ok_endswith(tb1, \">test_log:%d,%s\" % (tb_line + 1, \",\".join([str(tb_line)]*10)))\n\nr2e_tests/test_1.py:142: \n_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ \ndatalad/tests/utils.py:399: in ok_endswith\n    ok_(s.endswith(suffix),\n_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ \n\nexpr = False\nmsg = \"String 'runpy:197,87>__main__:9>config.__init__:201,175>_hooks:513>_manager:120>_callers:103>main:330,283,337>_hooks:...:141,140,140,140,140,140,140,140,140,140,140' doesn't end with '>test_log:141,140,140,140,140,140,140,140,140,140,140'\"\n\n    def ok_(expr, msg=None):\n        \"\"\"Shorthand for assert. Saves 3 whole characters!\n        \"\"\"\n        if not expr:\n>           raise AssertionError(msg)\nE           AssertionError: String 'runpy:197,87>__main__:9>config.__init__:201,175>_hooks:513>_manager:120>_callers:103>main:330,283,337>_hooks:513>_manager:120>_callers:103>main:362>_hooks:513>_manager:120>_callers:103>runner:113,132,241,341,242>_hooks:513>_manager:120>_callers:103>runner:174>python:1627>_hooks:513>_manager:120>_callers:103>python:159>test_1:141,140,140,140,140,140,140,140,140,140,140' doesn't end with '>test_log:141,140,140,140,140,140,140,140,140,140,140'\n\n.venv/lib/python3.9/site-packages/nose/tools/trivial.py:22: AssertionError\n___________________ test_log_progress_noninteractive_filter ____________________\n\n    @patch(\"datalad.log.is_interactive\", lambda: False)\n    def test_log_progress_noninteractive_filter():\n        name = \"dl-test\"\n        lgr = LoggerHelper(name).get_initialized_logger()\n        pbar_id = \"lp_test\"\n        with swallow_logs(new_level=logging.INFO, name=name) as cml:\n            log_progress(lgr.info, pbar_id, \"Start\", label=\"testing\", total=3)\n            log_progress(lgr.info, pbar_id, \"THERE0\", update=1)\n            log_progress(lgr.info, pbar_id, \"NOT\", update=1,\n                         noninteractive_level=logging.DEBUG)\n            log_progress(lgr.info, pbar_id, \"THERE1\", update=1,\n                         noninteractive_level=logging.INFO)\n            log_progress(lgr.info, pbar_id, \"Done\")\n            for present in [\"Start\", \"THERE0\", \"THERE1\", \"Done\"]:\n                assert_in(present, cml.out)\n>           assert_not_in(\"NOT\", cml.out)\n\nr2e_tests/test_1.py:182: \n_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ \n../../../../.local/share/uv/python/cpython-3.9.21-linux-x86_64-gnu/lib/python3.9/unittest/case.py:1111: in assertNotIn\n    self.fail(self._formatMessage(msg, standardMsg))\n_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ \n\nself = <nose.tools.trivial.Dummy testMethod=nop>\nmsg = \"'NOT' unexpectedly found in '[INFO] Start\\\\n[INFO] THERE0\\\\n[INFO] NOT\\\\n[INFO] THERE1\\\\n[INFO] Done\\\\n'\"\n\n    def fail(self, msg=None):\n        \"\"\"Fail immediately, with the given message.\"\"\"\n>       raise self.failureException(msg)\nE       AssertionError: 'NOT' unexpectedly found in '[INFO] Start\\n[INFO] THERE0\\n[INFO] NOT\\n[INFO] THERE1\\n[INFO] Done\\n'\n\n../../../../.local/share/uv/python/cpython-3.9.21-linux-x86_64-gnu/lib/python3.9/unittest/case.py:676: AssertionError\n------------------------------ Captured log call -------------------------------\nINFO     dl-test:log.py:278 Start\nINFO     dl-test:log.py:278 THERE0\nINFO     dl-test:log.py:278 NOT\nINFO     dl-test:log.py:278 THERE1\nINFO     dl-test:log.py:278 Done\n==================================== PASSES ====================================\n_________________________________ test_filters _________________________________\n------------------------------ Captured log call -------------------------------\nDEBUG    datalad1.goodone:test_1.py:113 log1\nINFO     datalad1.anotherone:test_1.py:114 log2\nINFO     datalad1.bad:test_1.py:115 log3\nDEBUG    datalad2.goodone:test_1.py:113 log1\nINFO     datalad2.anotherone:test_1.py:114 log2\nINFO     datalad2.bad:test_1.py:115 log3\n=========================== short test summary info ============================\nPASSED r2e_tests/test_1.py::test_filters\nPASSED r2e_tests/test_1.py::test_color_formatter\nERROR r2e_tests/test_1.py::test_logging_to_a_file\nERROR r2e_tests/test_1.py::test_logtarget_via_env_variable\nERROR r2e_tests/test_1.py::test_mutliple_targets\nFAILED r2e_tests/test_1.py::test_traceback - AssertionError: String 'runpy:19...\nFAILED r2e_tests/test_1.py::test_log_progress_noninteractive_filter - Asserti...\n==================== 2 failed, 2 passed, 3 errors in 0.61s =====================\n",
    "old_commit_res_stderr": ""
}
datalad/log.py datalad/tests/test_log.py
We are currently solving the following issue within our repository. Here is the issue text:
--- BEGIN ISSUE ---
[ISSUE]
**Title:** Non-interactive `log_progress` Fails to Filter Messages Below Specified Logging Level

**Description:**
When using `log_progress` in non-interactive mode, messages that are intended to be filtered based on their logging level are still being logged, resulting in unnecessary log noise.

**Example Buggy Code:**
```python
from unittest.mock import patch
import logging
from datalad.log import LoggerHelper, log_progress

@patch("datalad.log.is_interactive", lambda: False)
def test_log_progress_noninteractive_filter():
    name = "dl-test"
    lgr = LoggerHelper(name).get_initialized_logger()
    pbar_id = "lp_test"
    
    log_progress(lgr.info, pbar_id, "Start", label="testing", total=3)
    log_progress(lgr.info, pbar_id, "THERE0", update=1)
    log_progress(lgr.info, pbar_id, "NOT", update=1, noninteractive_level=logging.DEBUG)
    log_progress(lgr.info, pbar_id, "THERE1", update=1, noninteractive_level=logging.INFO)
    log_progress(lgr.info, pbar_id, "Done")
    
    # Expected: "Start", "THERE0", "THERE1", and "Done" are logged
    # "NOT" should be filtered out
```

**Expected Behavior:**
Messages passed to `log_progress` with a `noninteractive_level` lower than the logger's current level should be excluded from the logs when operating non-interactively. In the example above, the message "NOT" with `noninteractive_level=logging.DEBUG` should not appear in the logs if the logger is set above the DEBUG level.

**Actual Behavior:**
All messages, including "NOT", are logged even when they should be filtered out based on the specified `noninteractive_level`, leading to excessive and undesired log entries.
[/ISSUE]
--- END ISSUE ---

Below are some code segments, each from a relevant file. One or more of these files may contain bugs.

--- BEGIN FILE ---
```
### datalad/log.py
# emacs: -*- mode: python; py-indent-offset: 4; tab-width: 4; indent-tabs-mode: nil -*-
# ex: set sts=4 ts=4 sw=4 noet:
# ## ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ##
#
#   See COPYING file distributed along with the datalad package for the
#   copyright and license terms.
#
# ## ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ##

import logging
import os
import sys
import platform
import logging.handlers

from os.path import basename, dirname

from collections import defaultdict

from .utils import is_interactive, optional_args
from .support import ansi_colors as colors

__all__ = ['ColorFormatter']

# Snippets from traceback borrowed from duecredit which was borrowed from
# PyMVPA upstream/2.4.0-39-g69ad545  MIT license (the same copyright as DataLad)


def mbasename(s):
    """Custom function to include directory name if filename is too common

    Also strip .py at the end
    """
    base = basename(s)
    if base.endswith('.py'):
        base = base[:-3]
    if base in set(['base', '__init__']):
        base = basename(dirname(s)) + '.' + base
    return base


class TraceBack(object):
    """Customized traceback to be included in debug messages
    """

    def __init__(self, limit=100, collide=False):
        """Initialize TraceBack metric

        Parameters
        ----------
        collide : bool
          if True then prefix common with previous invocation gets
          replaced with ...
        """
        self.__prev = ""
        self.limit = limit
        self.collide = collide

        # delayed imports and preparing the regex substitution
        if collide:
            import re
            self.__prefix_re = re.compile('>[^>]*$')
        else:
            self.__prefix_re = None

        import traceback
        self._extract_stack = traceback.extract_stack

    def __call__(self):
        ftb = self._extract_stack(limit=self.limit+10)[:-2]
        entries = [[mbasename(x[0]), str(x[1])]
                   for x in ftb if mbasename(x[0]) != 'logging.__init__']
        entries = [e for e in entries if e[0] != 'unittest']

        if len(entries) > self.limit:
            sftb = '...>'
            entries = entries[-self.limit:]
        else:
            sftb = ''

        if not entries:
            return ""

        # lets make it more consize
        entries_out = [entries[0]]
        for entry in entries[1:]:
            if entry[0] == entries_out[-1][0]:
                entries_out[-1][1] += ',%s' % entry[1]
            else:
                entries_out.append(entry)

        sftb += '>'.join(
            ['%s:%s' % (mbasename(x[0]), x[1]) for x in entries_out]
        )

        if self.collide:
            # lets remove part which is common with previous invocation
            prev_next = sftb
            common_prefix = os.path.commonprefix((self.__prev, sftb))
            common_prefix2 = self.__prefix_re.sub('', common_prefix)

            if common_prefix2 != "":
                sftb = '...' + sftb[len(common_prefix2):]
            self.__prev = prev_next

        return sftb


class MemoryInfo(object):
    def __init__(self):
        try:
            from psutil import Process
            process = Process(os.getpid())
            self.memory_info = process.memory_info \
                if hasattr(process, 'memory_info') \
                else process.get_memory_info
        except:
            self.memory_info = None


    def __call__(self):
        """Return utilization of virtual memory

        Generic implementation using psutil
        """
        if not self.memory_info:
            return "RSS/VMS: N/A"
        mi = self.memory_info()
        # in later versions of psutil mi is a named tuple.
        # but that is not the case on Debian squeeze with psutil 0.1.3
        rss = mi[0] / 1024
        vms = mi[1] / 1024
        vmem = (rss, vms)

        try:
            return "RSS/VMS: %d/%d kB" % vmem
        except:
            return "RSS/VMS: %s" % str(vmem)

# Recipe from http://stackoverflow.com/questions/384076/how-can-i-color-python-logging-output
# by Brandon Thomson
# Adjusted for automagic determination whether coloring is needed and
# prefixing of multiline log lines
class ColorFormatter(logging.Formatter):

    def __init__(self, use_color=None, log_name=False, log_pid=False):
        if use_color is None:
            # if 'auto' - use color only if all streams are tty
            use_color = is_interactive()
        self.use_color = use_color and platform.system() != 'Windows'  # don't use color on windows
        msg = colors.format_msg(self._get_format(log_name, log_pid),
                                self.use_color)
        log_env = os.environ.get('DATALAD_LOG_TRACEBACK', '')
        collide = log_env == 'collide'
        limit = 100 if collide else int(log_env) if log_env.isdigit() else 100
        self._tb = TraceBack(collide=collide, limit=limit) if log_env else None

        self._mem = MemoryInfo() if os.environ.get('DATALAD_LOG_VMEM', '') else None
        logging.Formatter.__init__(self, msg)

    def _get_format(self, log_name=False, log_pid=False):
        from datalad import cfg
        from datalad.config import anything2bool
        show_timestamps = anything2bool(cfg.get('datalad.log.timestamp', False))
        return (("" if not show_timestamps else "$BOLD%(asctime)-15s$RESET ") +
                ("%(name)-15s " if log_name else "") +
                ("{%(process)d}" if log_pid else "") +
                "[%(levelname)s] "
                "%(message)s ")

    def format(self, record):
        if record.msg.startswith('| '):
            # If we already log smth which supposed to go without formatting, like
            # output for running a command, just return the message and be done
            return record.msg

        levelname = record.levelname

        if self.use_color and levelname in colors.LOG_LEVEL_COLORS:
            record.levelname = colors.color_word(
                "{:7}".format(levelname),
                colors.LOG_LEVEL_COLORS[levelname],
                force=True)
        record.msg = record.msg.replace("\n", "\n| ")
        if self._tb:
            if not getattr(record, 'notraceback', False):
                record.msg = self._tb() + "  " + record.msg
        if self._mem:
            record.msg = "%s %s" % (self._mem(), record.msg)

        return logging.Formatter.format(self, record)


class ProgressHandler(logging.Handler):
    from datalad.ui import ui

    def __init__(self):
        super(self.__class__, self).__init__()
        self.pbars = {}

    def emit(self, record):
        from datalad.ui import ui
        pid = getattr(record, 'dlm_progress')
        update = getattr(record, 'dlm_progress_update', None)
        # would be an actual message, not used ATM here,
        # and the record not passed to generic handler ATM
        # (filtered away by NoProgressLog)
        # so no final message is printed
        # msg = record.getMessage()
        if pid not in self.pbars:
            # this is new
            pbar = ui.get_progressbar(
                label=getattr(record, 'dlm_progress_label', ''),
                unit=getattr(record, 'dlm_progress_unit', ''),
                total=getattr(record, 'dlm_progress_total', None))
            self.pbars[pid] = pbar
        elif update is None:
            # not an update -> done
            # TODO if the other logging that is happening is less frontpage
            # we may want to actually "print" the completion message
            self.pbars.pop(pid).finish()
        else:
            # an update
            self.pbars[pid].update(
                update,
                increment=getattr(record, 'dlm_progress_increment', False))
            # Check for an updated label.
            label = getattr(record, 'dlm_progress_label', None)
            if label is not None:
                self.pbars[pid].set_desc(label)


class NoProgressLog(logging.Filter):
    def filter(self, record):
        return not hasattr(record, 'dlm_progress')


class OnlyProgressLog(logging.Filter):
    def filter(self, record):
        return hasattr(record, 'dlm_progress')


def log_progress(lgrcall, pid, *args, **kwargs):
    """Helper to emit a log message on the progress of some process

    Note: Whereas this helper reports on interim progress and is to be used
    programmatically, :class:`~datalad.ui.progressbars.LogProgressBar` replaces
    a progress bar with a single log message upon completion and can be chosen
    by the user (config 'datalad.ui.progressbar' set to 'log').

    Parameters
    ----------
    lgrcall : callable
      Something like lgr.debug or lgr.info
    pid : str
      Some kind of ID for the process the progress is reported on.
    *args : str
      Log message, and potential arguments
    total : int
      Max progress quantity of the process.
    label : str
      Process description. Should be very brief, goes in front of progress bar
      on the same line.
    unit : str
      Progress report unit. Should be very brief, goes after the progress bar
      on the same line.
    update : int
      To which quantity to advance the progress.
    increment : bool
      If set, `update` is interpreted as an incremental value, not absolute.
    """
    d = dict(
        {'dlm_progress_{}'.format(n): v for n, v in kwargs.items()
         # initial progress might be zero, but not sending it further
         # would signal to destroy the progress bar, hence test for 'not None'
         if v is not None},
        dlm_progress=pid)
    lgrcall(*args, extra=d)


@optional_args
def with_result_progress(fn, label="Total", unit=" Files"):
    """Wrap a progress bar, with status counts, around a function.

    Parameters
    ----------
    fn : generator function
        This function should accept a collection of items as a
        positional argument and any number of keyword arguments.  After
        processing each item in the collection, it should yield a status
        dict.
    label, unit : str
        Passed to log.log_progress.

    Returns
    -------
    A variant of `fn` that shows a progress bar.  Note that the wrapped
    function is not a generator function; the status dicts will be
    returned as a list.
    """
    # FIXME: This emulates annexrepo.ProcessAnnexProgressIndicators.  It'd be
    # nice to rewire things so that it could be used directly.

    def count_str(count, verb, omg=False):
        if count:
            msg = "{:d} {}".format(count, verb)
            if omg:
                msg = colors.color_word(msg, colors.RED)
            return msg

    pid = str(fn)
    base_label = label

    def wrapped(items, **kwargs):
        counts = defaultdict(int)

        label = base_label
        log_progress(lgr.info, pid,
                     "%s: starting", label,
                     total=len(items), label=label, unit=unit)

        results = []
        for res in fn(items, **kwargs):
            counts[res["status"]] += 1
            count_strs = (count_str(*args)
                          for args in [(counts["notneeded"], "skipped", False),
                                       (counts["error"], "failed", True)])
            if counts["notneeded"] or counts["error"]:
                label = "{} ({})".format(
                    base_label,
                    ", ".join(filter(None, count_strs)))

            log_progress(
                lgr.error if res["status"] == "error" else lgr.info,
                pid,
                "%s: processed result%s", base_label,
                " for " + res["path"] if "path" in res else "",
                label=label, update=1, increment=True)
            results.append(res)
        log_progress(lgr.info, pid, "%s: done", base_label)
        return results
    return wrapped


class LoggerHelper(object):
    """Helper to establish and control a Logger"""

    def __init__(self, name='datalad', logtarget=None):
        """

        Parameters
        ----------
        name :
        logtarget : string, optional
          If we want to use our logger for other log targets, while having
          a uniform control over them
        """
        self.name = name
        self.logtarget = logtarget
        self.lgr = logging.getLogger(logtarget if logtarget is not None else name)

    def _get_config(self, var, default=None):
        from datalad import cfg
        return cfg.get(self.name.lower() + '.log.' + var, default)

    def set_level(self, level=None, default='INFO'):
        """Helper to set loglevel for an arbitrary logger

        By default operates for 'datalad'.
        TODO: deduce name from upper module name so it could be reused without changes
        """
        if level is None:
            # see if nothing in the environment
            level = self._get_config('level')
        if level is None:
            level = default

        try:
            # it might be a string which still represents an int
            log_level = int(level)
        except ValueError:
            # or a string which corresponds to a constant;)
            log_level = getattr(logging, level.upper())

        self.lgr.setLevel(log_level)
        # and set other related/used loggers to the same level to prevent their
        # talkativity, if they are not yet known to this python session, so we
        # have little chance to "override" possibly set outside levels
        for dep in ('git',):
            if dep not in logging.Logger.manager.loggerDict:
                logging.getLogger(dep).setLevel(log_level)

    def get_initialized_logger(self, logtarget=None):
        """Initialize and return the logger

        Parameters
        ----------
        target: string, optional
          Which log target to request logger for
        logtarget: { 'stdout', 'stderr', str }, optional
          Where to direct the logs.  stdout and stderr stand for standard streams.
          Any other string is considered a filename.  Multiple entries could be
          specified comma-separated

        Returns
        -------
        logging.Logger
        """
        # By default mimic previously talkative behavior
        logtarget = self._get_config('target', logtarget or 'stderr')

        # Allow for multiple handlers being specified, comma-separated
        if ',' in logtarget:
            for handler_ in logtarget.split(','):
                self.get_initialized_logger(logtarget=handler_)
            return self.lgr

        if logtarget.lower() in ('stdout', 'stderr'):
            loghandler = logging.StreamHandler(getattr(sys, logtarget.lower()))
            use_color = is_interactive()  # explicitly decide here
        else:
            # must be a simple filename
            # Use RotatingFileHandler for possible future parametrization to keep
            # log succinct and rotating
            loghandler = logging.handlers.RotatingFileHandler(logtarget)
            use_color = False
            # I had decided not to guard this call and just raise exception to go
            # out happen that specified file location is not writable etc.

        for names_filter in 'names', 'namesre':
            names = self._get_config(names_filter, '')
            if names:
                import re
                # add a filter which would catch those
                class LogFilter(object):
                    """A log filter to filter based on the log target name(s)"""
                    def __init__(self, names):
                        self.target_names = set(n for n in names.split(',')) \
                            if names_filter == 'names' \
                            else re.compile(names)
                    if names_filter == 'names':
                        def filter(self, record):
                            return record.name in self.target_names
                    else:
                        def filter(self, record):
                            return self.target_names.match(record.name)

                loghandler.addFilter(LogFilter(names))

        # But now improve with colors and useful information such as time
        loghandler.setFormatter(
            ColorFormatter(use_color=use_color,
                           # TODO: config log.name, pid
                           log_name=self._get_config("name", False),
                           log_pid=self._get_config("pid", False),
                           ))
        #  logging.Formatter('%(asctime)-15s %(levelname)-6s %(message)s'))
        self.lgr.addHandler(loghandler)

        if is_interactive():
            phandler = ProgressHandler()
            # progress only when interactive
            phandler.addFilter(OnlyProgressLog())
            # no stream logs of progress messages when interactive
            loghandler.addFilter(NoProgressLog())
            self.lgr.addHandler(phandler)

        self.set_level()  # set default logging level
        return self.lgr


lgr = LoggerHelper().get_initialized_logger()

```
--- END FILE ---

Please first localize the bug based on the issue statement, and then generate *SEARCH/REPLACE* edits to fix the issue.

Every *SEARCH/REPLACE* edit must use this format:
1. The file path
2. The start of search block: <<<<<<< SEARCH
3. A contiguous chunk of lines to search for in the existing source code
4. The dividing line: =======
5. The lines to replace into the source code
6. The end of the replace block: >>>>>>> REPLACE

Here is an example:

```python
### mathweb/flask/app.py
<<<<<<< SEARCH
from flask import Flask
=======
import math
from flask import Flask
>>>>>>> REPLACE
```
</solution>

Please note that the *SEARCH/REPLACE* edit REQUIRES PROPER INDENTATION. If you would like to add the line '        print(x)', you must fully write that out, with all those spaces before the code!
Wrap each *SEARCH/REPLACE* edit in a code block as shown in the example above. If you have multiple *SEARCH/REPLACE* edits, use a separate code block for each one.
[ISSUE]
**Title:** Non-interactive `log_progress` Fails to Filter Messages Below Specified Logging Level

**Description:**
When using `log_progress` in non-interactive mode, messages that are intended to be filtered based on their logging level are still being logged, resulting in unnecessary log noise.

**Example Buggy Code:**
```python
from unittest.mock import patch
import logging
from datalad.log import LoggerHelper, log_progress

@patch("datalad.log.is_interactive", lambda: False)
def test_log_progress_noninteractive_filter():
    name = "dl-test"
    lgr = LoggerHelper(name).get_initialized_logger()
    pbar_id = "lp_test"
    
    log_progress(lgr.info, pbar_id, "Start", label="testing", total=3)
    log_progress(lgr.info, pbar_id, "THERE0", update=1)
    log_progress(lgr.info, pbar_id, "NOT", update=1, noninteractive_level=logging.DEBUG)
    log_progress(lgr.info, pbar_id, "THERE1", update=1, noninteractive_level=logging.INFO)
    log_progress(lgr.info, pbar_id, "Done")
    
    # Expected: "Start", "THERE0", "THERE1", and "Done" are logged
    # "NOT" should be filtered out
```

**Expected Behavior:**
Messages passed to `log_progress` with a `noninteractive_level` lower than the logger's current level should be excluded from the logs when operating non-interactively. In the example above, the message "NOT" with `noninteractive_level=logging.DEBUG` should not appear in the logs if the logger is set above the DEBUG level.

**Actual Behavior:**
All messages, including "NOT", are logged even when they should be filtered out based on the specified `noninteractive_level`, leading to excessive and undesired log entries.
[/ISSUE]
{
    "test_filters": "PASSED",
    "test_color_formatter": "PASSED",
    "test_log_progress_noninteractive_filter": "PASSED",
    "test_logging_to_a_file": "ERROR",
    "test_logtarget_via_env_variable": "ERROR",
    "test_mutliple_targets": "ERROR",
    "test_traceback": "FAILED"
}
diff --git a/datalad/log.py b/datalad/log.py
index 6745c5436..5e61ecd89 100644
--- a/datalad/log.py
+++ b/datalad/log.py
@@ -7,6 +7,7 @@
 #
 # ## ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ##
 
+from functools import partial
 import logging
 import os
 import sys
@@ -240,6 +241,11 @@ class OnlyProgressLog(logging.Filter):
         return hasattr(record, 'dlm_progress')
 
 
+def filter_noninteractive_progress(logger, record):
+    level = getattr(record, "dlm_progress_noninteractive_level", None)
+    return level is None or level >= logger.level
+
+
 def log_progress(lgrcall, pid, *args, **kwargs):
     """Helper to emit a log message on the progress of some process
 
@@ -268,6 +274,14 @@ def log_progress(lgrcall, pid, *args, **kwargs):
       To which quantity to advance the progress.
     increment : bool
       If set, `update` is interpreted as an incremental value, not absolute.
+    noninteractive_level : int, optional
+      When a level is specified here and progress is being logged
+      non-interactively (i.e. without progress bars), do not log the message if
+      logging is not enabled for the specified level. This is useful when you
+      want all calls to be "logged" via the progress bar, but non-interactively
+      showing a message at the `lgrcall` level for each step would be too much
+      noise. Note that the level here only determines if the record will be
+      dropped; it will still be logged at the level of `lgrcall`.
     """
     d = dict(
         {'dlm_progress_{}'.format(n): v for n, v in kwargs.items()
@@ -464,6 +478,9 @@ class LoggerHelper(object):
             # no stream logs of progress messages when interactive
             loghandler.addFilter(NoProgressLog())
             self.lgr.addHandler(phandler)
+        else:
+            loghandler.addFilter(partial(filter_noninteractive_progress,
+                                         self.lgr))
 
         self.set_level()  # set default logging level
         return self.lgr

{"datalad/log.py": "# emacs: -*- mode: python; py-indent-offset: 4; tab-width: 4; indent-tabs-mode: nil -*-\n# ex: set sts=4 ts=4 sw=4 noet:\n# ## ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ##\n#\n#   See COPYING file distributed along with the datalad package for the\n#   copyright and license terms.\n#\n# ## ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ##\n\nimport logging\nimport os\nimport sys\nimport platform\nimport logging.handlers\n\nfrom os.path import basename, dirname\n\nfrom collections import defaultdict\n\nfrom .utils import is_interactive, optional_args\nfrom .support import ansi_colors as colors\n\n__all__ = ['ColorFormatter']\n\n# Snippets from traceback borrowed from duecredit which was borrowed from\n# PyMVPA upstream/2.4.0-39-g69ad545  MIT license (the same copyright as DataLad)\n\n\ndef mbasename(s):\n    \"\"\"Custom function to include directory name if filename is too common\n\n    Also strip .py at the end\n    \"\"\"\n    base = basename(s)\n    if base.endswith('.py'):\n        base = base[:-3]\n    if base in set(['base', '__init__']):\n        base = basename(dirname(s)) + '.' + base\n    return base\n\n\nclass TraceBack(object):\n    \"\"\"Customized traceback to be included in debug messages\n    \"\"\"\n\n    def __init__(self, limit=100, collide=False):\n        \"\"\"Initialize TraceBack metric\n\n        Parameters\n        ----------\n        collide : bool\n          if True then prefix common with previous invocation gets\n          replaced with ...\n        \"\"\"\n        self.__prev = \"\"\n        self.limit = limit\n        self.collide = collide\n\n        # delayed imports and preparing the regex substitution\n        if collide:\n            import re\n            self.__prefix_re = re.compile('>[^>]*$')\n        else:\n            self.__prefix_re = None\n\n        import traceback\n        self._extract_stack = traceback.extract_stack\n\n    def __call__(self):\n        ftb = self._extract_stack(limit=self.limit+10)[:-2]\n        entries = [[mbasename(x[0]), str(x[1])]\n                   for x in ftb if mbasename(x[0]) != 'logging.__init__']\n        entries = [e for e in entries if e[0] != 'unittest']\n\n        if len(entries) > self.limit:\n            sftb = '...>'\n            entries = entries[-self.limit:]\n        else:\n            sftb = ''\n\n        if not entries:\n            return \"\"\n\n        # lets make it more consize\n        entries_out = [entries[0]]\n        for entry in entries[1:]:\n            if entry[0] == entries_out[-1][0]:\n                entries_out[-1][1] += ',%s' % entry[1]\n            else:\n                entries_out.append(entry)\n\n        sftb += '>'.join(\n            ['%s:%s' % (mbasename(x[0]), x[1]) for x in entries_out]\n        )\n\n        if self.collide:\n            # lets remove part which is common with previous invocation\n            prev_next = sftb\n            common_prefix = os.path.commonprefix((self.__prev, sftb))\n            common_prefix2 = self.__prefix_re.sub('', common_prefix)\n\n            if common_prefix2 != \"\":\n                sftb = '...' + sftb[len(common_prefix2):]\n            self.__prev = prev_next\n\n        return sftb\n\n\nclass MemoryInfo(object):\n    def __init__(self):\n        try:\n            from psutil import Process\n            process = Process(os.getpid())\n            self.memory_info = process.memory_info \\\n                if hasattr(process, 'memory_info') \\\n                else process.get_memory_info\n        except:\n            self.memory_info = None\n\n\n    def __call__(self):\n        \"\"\"Return utilization of virtual memory\n\n        Generic implementation using psutil\n        \"\"\"\n        if not self.memory_info:\n            return \"RSS/VMS: N/A\"\n        mi = self.memory_info()\n        # in later versions of psutil mi is a named tuple.\n        # but that is not the case on Debian squeeze with psutil 0.1.3\n        rss = mi[0] / 1024\n        vms = mi[1] / 1024\n        vmem = (rss, vms)\n\n        try:\n            return \"RSS/VMS: %d/%d kB\" % vmem\n        except:\n            return \"RSS/VMS: %s\" % str(vmem)\n\n# Recipe from http://stackoverflow.com/questions/384076/how-can-i-color-python-logging-output\n# by Brandon Thomson\n# Adjusted for automagic determination whether coloring is needed and\n# prefixing of multiline log lines\nclass ColorFormatter(logging.Formatter):\n\n    def __init__(self, use_color=None, log_name=False, log_pid=False):\n        if use_color is None:\n            # if 'auto' - use color only if all streams are tty\n            use_color = is_interactive()\n        self.use_color = use_color and platform.system() != 'Windows'  # don't use color on windows\n        msg = colors.format_msg(self._get_format(log_name, log_pid),\n                                self.use_color)\n        log_env = os.environ.get('DATALAD_LOG_TRACEBACK', '')\n        collide = log_env == 'collide'\n        limit = 100 if collide else int(log_env) if log_env.isdigit() else 100\n        self._tb = TraceBack(collide=collide, limit=limit) if log_env else None\n\n        self._mem = MemoryInfo() if os.environ.get('DATALAD_LOG_VMEM', '') else None\n        logging.Formatter.__init__(self, msg)\n\n    def _get_format(self, log_name=False, log_pid=False):\n        from datalad import cfg\n        from datalad.config import anything2bool\n        show_timestamps = anything2bool(cfg.get('datalad.log.timestamp', False))\n        return ((\"\" if not show_timestamps else \"$BOLD%(asctime)-15s$RESET \") +\n                (\"%(name)-15s \" if log_name else \"\") +\n                (\"{%(process)d}\" if log_pid else \"\") +\n                \"[%(levelname)s] \"\n                \"%(message)s \")\n\n    def format(self, record):\n        if record.msg.startswith('| '):\n            # If we already log smth which supposed to go without formatting, like\n            # output for running a command, just return the message and be done\n            return record.msg\n\n        levelname = record.levelname\n\n        if self.use_color and levelname in colors.LOG_LEVEL_COLORS:\n            record.levelname = colors.color_word(\n                \"{:7}\".format(levelname),\n                colors.LOG_LEVEL_COLORS[levelname],\n                force=True)\n        record.msg = record.msg.replace(\"\\n\", \"\\n| \")\n        if self._tb:\n            if not getattr(record, 'notraceback', False):\n                record.msg = self._tb() + \"  \" + record.msg\n        if self._mem:\n            record.msg = \"%s %s\" % (self._mem(), record.msg)\n\n        return logging.Formatter.format(self, record)\n\n\nclass ProgressHandler(logging.Handler):\n    from datalad.ui import ui\n\n    def __init__(self):\n        super(self.__class__, self).__init__()\n        self.pbars = {}\n\n    def emit(self, record):\n        from datalad.ui import ui\n        pid = getattr(record, 'dlm_progress')\n        update = getattr(record, 'dlm_progress_update', None)\n        # would be an actual message, not used ATM here,\n        # and the record not passed to generic handler ATM\n        # (filtered away by NoProgressLog)\n        # so no final message is printed\n        # msg = record.getMessage()\n        if pid not in self.pbars:\n            # this is new\n            pbar = ui.get_progressbar(\n                label=getattr(record, 'dlm_progress_label', ''),\n                unit=getattr(record, 'dlm_progress_unit', ''),\n                total=getattr(record, 'dlm_progress_total', None))\n            self.pbars[pid] = pbar\n        elif update is None:\n            # not an update -> done\n            # TODO if the other logging that is happening is less frontpage\n            # we may want to actually \"print\" the completion message\n            self.pbars.pop(pid).finish()\n        else:\n            # an update\n            self.pbars[pid].update(\n                update,\n                increment=getattr(record, 'dlm_progress_increment', False))\n            # Check for an updated label.\n            label = getattr(record, 'dlm_progress_label', None)\n            if label is not None:\n                self.pbars[pid].set_desc(label)\n\n\nclass NoProgressLog(logging.Filter):\n    def filter(self, record):\n        return not hasattr(record, 'dlm_progress')\n\n\nclass OnlyProgressLog(logging.Filter):\n    def filter(self, record):\n        return hasattr(record, 'dlm_progress')\n\n\ndef log_progress(lgrcall, pid, *args, **kwargs):\n    \"\"\"Helper to emit a log message on the progress of some process\n\n    Note: Whereas this helper reports on interim progress and is to be used\n    programmatically, :class:`~datalad.ui.progressbars.LogProgressBar` replaces\n    a progress bar with a single log message upon completion and can be chosen\n    by the user (config 'datalad.ui.progressbar' set to 'log').\n\n    Parameters\n    ----------\n    lgrcall : callable\n      Something like lgr.debug or lgr.info\n    pid : str\n      Some kind of ID for the process the progress is reported on.\n    *args : str\n      Log message, and potential arguments\n    total : int\n      Max progress quantity of the process.\n    label : str\n      Process description. Should be very brief, goes in front of progress bar\n      on the same line.\n    unit : str\n      Progress report unit. Should be very brief, goes after the progress bar\n      on the same line.\n    update : int\n      To which quantity to advance the progress.\n    increment : bool\n      If set, `update` is interpreted as an incremental value, not absolute.\n    \"\"\"\n    d = dict(\n        {'dlm_progress_{}'.format(n): v for n, v in kwargs.items()\n         # initial progress might be zero, but not sending it further\n         # would signal to destroy the progress bar, hence test for 'not None'\n         if v is not None},\n        dlm_progress=pid)\n    lgrcall(*args, extra=d)\n\n\n@optional_args\ndef with_result_progress(fn, label=\"Total\", unit=\" Files\"):\n    \"\"\"Wrap a progress bar, with status counts, around a function.\n\n    Parameters\n    ----------\n    fn : generator function\n        This function should accept a collection of items as a\n        positional argument and any number of keyword arguments.  After\n        processing each item in the collection, it should yield a status\n        dict.\n    label, unit : str\n        Passed to log.log_progress.\n\n    Returns\n    -------\n    A variant of `fn` that shows a progress bar.  Note that the wrapped\n    function is not a generator function; the status dicts will be\n    returned as a list.\n    \"\"\"\n    # FIXME: This emulates annexrepo.ProcessAnnexProgressIndicators.  It'd be\n    # nice to rewire things so that it could be used directly.\n\n    def count_str(count, verb, omg=False):\n        if count:\n            msg = \"{:d} {}\".format(count, verb)\n            if omg:\n                msg = colors.color_word(msg, colors.RED)\n            return msg\n\n    pid = str(fn)\n    base_label = label\n\n    def wrapped(items, **kwargs):\n        counts = defaultdict(int)\n\n        label = base_label\n        log_progress(lgr.info, pid,\n                     \"%s: starting\", label,\n                     total=len(items), label=label, unit=unit)\n\n        results = []\n        for res in fn(items, **kwargs):\n            counts[res[\"status\"]] += 1\n            count_strs = (count_str(*args)\n                          for args in [(counts[\"notneeded\"], \"skipped\", False),\n                                       (counts[\"error\"], \"failed\", True)])\n            if counts[\"notneeded\"] or counts[\"error\"]:\n                label = \"{} ({})\".format(\n                    base_label,\n                    \", \".join(filter(None, count_strs)))\n\n            log_progress(\n                lgr.error if res[\"status\"] == \"error\" else lgr.info,\n                pid,\n                \"%s: processed result%s\", base_label,\n                \" for \" + res[\"path\"] if \"path\" in res else \"\",\n                label=label, update=1, increment=True)\n            results.append(res)\n        log_progress(lgr.info, pid, \"%s: done\", base_label)\n        return results\n    return wrapped\n\n\nclass LoggerHelper(object):\n    \"\"\"Helper to establish and control a Logger\"\"\"\n\n    def __init__(self, name='datalad', logtarget=None):\n        \"\"\"\n\n        Parameters\n        ----------\n        name :\n        logtarget : string, optional\n          If we want to use our logger for other log targets, while having\n          a uniform control over them\n        \"\"\"\n        self.name = name\n        self.logtarget = logtarget\n        self.lgr = logging.getLogger(logtarget if logtarget is not None else name)\n\n    def _get_config(self, var, default=None):\n        from datalad import cfg\n        return cfg.get(self.name.lower() + '.log.' + var, default)\n\n    def set_level(self, level=None, default='INFO'):\n        \"\"\"Helper to set loglevel for an arbitrary logger\n\n        By default operates for 'datalad'.\n        TODO: deduce name from upper module name so it could be reused without changes\n        \"\"\"\n        if level is None:\n            # see if nothing in the environment\n            level = self._get_config('level')\n        if level is None:\n            level = default\n\n        try:\n            # it might be a string which still represents an int\n            log_level = int(level)\n        except ValueError:\n            # or a string which corresponds to a constant;)\n            log_level = getattr(logging, level.upper())\n\n        self.lgr.setLevel(log_level)\n        # and set other related/used loggers to the same level to prevent their\n        # talkativity, if they are not yet known to this python session, so we\n        # have little chance to \"override\" possibly set outside levels\n        for dep in ('git',):\n            if dep not in logging.Logger.manager.loggerDict:\n                logging.getLogger(dep).setLevel(log_level)\n\n    def get_initialized_logger(self, logtarget=None):\n        \"\"\"Initialize and return the logger\n\n        Parameters\n        ----------\n        target: string, optional\n          Which log target to request logger for\n        logtarget: { 'stdout', 'stderr', str }, optional\n          Where to direct the logs.  stdout and stderr stand for standard streams.\n          Any other string is considered a filename.  Multiple entries could be\n          specified comma-separated\n\n        Returns\n        -------\n        logging.Logger\n        \"\"\"\n        # By default mimic previously talkative behavior\n        logtarget = self._get_config('target', logtarget or 'stderr')\n\n        # Allow for multiple handlers being specified, comma-separated\n        if ',' in logtarget:\n            for handler_ in logtarget.split(','):\n                self.get_initialized_logger(logtarget=handler_)\n            return self.lgr\n\n        if logtarget.lower() in ('stdout', 'stderr'):\n            loghandler = logging.StreamHandler(getattr(sys, logtarget.lower()))\n            use_color = is_interactive()  # explicitly decide here\n        else:\n            # must be a simple filename\n            # Use RotatingFileHandler for possible future parametrization to keep\n            # log succinct and rotating\n            loghandler = logging.handlers.RotatingFileHandler(logtarget)\n            use_color = False\n            # I had decided not to guard this call and just raise exception to go\n            # out happen that specified file location is not writable etc.\n\n        for names_filter in 'names', 'namesre':\n            names = self._get_config(names_filter, '')\n            if names:\n                import re\n                # add a filter which would catch those\n                class LogFilter(object):\n                    \"\"\"A log filter to filter based on the log target name(s)\"\"\"\n                    def __init__(self, names):\n                        self.target_names = set(n for n in names.split(',')) \\\n                            if names_filter == 'names' \\\n                            else re.compile(names)\n                    if names_filter == 'names':\n                        def filter(self, record):\n                            return record.name in self.target_names\n                    else:\n                        def filter(self, record):\n                            return self.target_names.match(record.name)\n\n                loghandler.addFilter(LogFilter(names))\n\n        # But now improve with colors and useful information such as time\n        loghandler.setFormatter(\n            ColorFormatter(use_color=use_color,\n                           # TODO: config log.name, pid\n                           log_name=self._get_config(\"name\", False),\n                           log_pid=self._get_config(\"pid\", False),\n                           ))\n        #  logging.Formatter('%(asctime)-15s %(levelname)-6s %(message)s'))\n        self.lgr.addHandler(loghandler)\n\n        if is_interactive():\n            phandler = ProgressHandler()\n            # progress only when interactive\n            phandler.addFilter(OnlyProgressLog())\n            # no stream logs of progress messages when interactive\n            loghandler.addFilter(NoProgressLog())\n            self.lgr.addHandler(phandler)\n\n        self.set_level()  # set default logging level\n        return self.lgr\n\n\nlgr = LoggerHelper().get_initialized_logger()\n"}
A user will ask you to solve a task. You should first draft your thinking process (inner monologue). Then, generate the solution.

Your response format must follow the template below:
<think>
Your thoughts or/and draft, like working through an exercise on scratch paper. Be as casual and as long as you want until you are confident to generate a correct solution.
</think>
<solution>
Final solution presented to the user.
</solution>
system
We are currently solving the following issue within our repository. Here is the issue text:
--- BEGIN ISSUE ---
[ISSUE]
**Title:** Non-interactive `log_progress` Fails to Filter Messages Below Specified Logging Level

**Description:**
When using `log_progress` in non-interactive mode, messages that are intended to be filtered based on their logging level are still being logged, resulting in unnecessary log noise.

**Example Buggy Code:**
```python
from unittest.mock import patch
import logging
from datalad.log import LoggerHelper, log_progress

@patch("datalad.log.is_interactive", lambda: False)
def test_log_progress_noninteractive_filter():
    name = "dl-test"
    lgr = LoggerHelper(name).get_initialized_logger()
    pbar_id = "lp_test"
    
    log_progress(lgr.info, pbar_id, "Start", label="testing", total=3)
    log_progress(lgr.info, pbar_id, "THERE0", update=1)
    log_progress(lgr.info, pbar_id, "NOT", update=1, noninteractive_level=logging.DEBUG)
    log_progress(lgr.info, pbar_id, "THERE1", update=1, noninteractive_level=logging.INFO)
    log_progress(lgr.info, pbar_id, "Done")
    
    # Expected: "Start", "THERE0", "THERE1", and "Done" are logged
    # "NOT" should be filtered out
```

**Expected Behavior:**
Messages passed to `log_progress` with a `noninteractive_level` lower than the logger's current level should be excluded from the logs when operating non-interactively. In the example above, the message "NOT" with `noninteractive_level=logging.DEBUG` should not appear in the logs if the logger is set above the DEBUG level.

**Actual Behavior:**
All messages, including "NOT", are logged even when they should be filtered out based on the specified `noninteractive_level`, leading to excessive and undesired log entries.
[/ISSUE]
--- END ISSUE ---

Below are some code segments, each from a relevant file. One or more of these files may contain bugs.

--- BEGIN FILE ---
```
### datalad/log.py
# emacs: -*- mode: python; py-indent-offset: 4; tab-width: 4; indent-tabs-mode: nil -*-
# ex: set sts=4 ts=4 sw=4 noet:
# ## ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ##
#
#   See COPYING file distributed along with the datalad package for the
#   copyright and license terms.
#
# ## ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ##

import logging
import os
import sys
import platform
import logging.handlers

from os.path import basename, dirname

from collections import defaultdict

from .utils import is_interactive, optional_args
from .support import ansi_colors as colors

__all__ = ['ColorFormatter']

# Snippets from traceback borrowed from duecredit which was borrowed from
# PyMVPA upstream/2.4.0-39-g69ad545  MIT license (the same copyright as DataLad)


def mbasename(s):
    """Custom function to include directory name if filename is too common

    Also strip .py at the end
    """
    base = basename(s)
    if base.endswith('.py'):
        base = base[:-3]
    if base in set(['base', '__init__']):
        base = basename(dirname(s)) + '.' + base
    return base


class TraceBack(object):
    """Customized traceback to be included in debug messages
    """

    def __init__(self, limit=100, collide=False):
        """Initialize TraceBack metric

        Parameters
        ----------
        collide : bool
          if True then prefix common with previous invocation gets
          replaced with ...
        """
        self.__prev = ""
        self.limit = limit
        self.collide = collide

        # delayed imports and preparing the regex substitution
        if collide:
            import re
            self.__prefix_re = re.compile('>[^>]*$')
        else:
            self.__prefix_re = None

        import traceback
        self._extract_stack = traceback.extract_stack

    def __call__(self):
        ftb = self._extract_stack(limit=self.limit+10)[:-2]
        entries = [[mbasename(x[0]), str(x[1])]
                   for x in ftb if mbasename(x[0]) != 'logging.__init__']
        entries = [e for e in entries if e[0] != 'unittest']

        if len(entries) > self.limit:
            sftb = '...>'
            entries = entries[-self.limit:]
        else:
            sftb = ''

        if not entries:
            return ""

        # lets make it more consize
        entries_out = [entries[0]]
        for entry in entries[1:]:
            if entry[0] == entries_out[-1][0]:
                entries_out[-1][1] += ',%s' % entry[1]
            else:
                entries_out.append(entry)

        sftb += '>'.join(
            ['%s:%s' % (mbasename(x[0]), x[1]) for x in entries_out]
        )

        if self.collide:
            # lets remove part which is common with previous invocation
            prev_next = sftb
            common_prefix = os.path.commonprefix((self.__prev, sftb))
            common_prefix2 = self.__prefix_re.sub('', common_prefix)

            if common_prefix2 != "":
                sftb = '...' + sftb[len(common_prefix2):]
            self.__prev = prev_next

        return sftb


class MemoryInfo(object):
    def __init__(self):
        try:
            from psutil import Process
            process = Process(os.getpid())
            self.memory_info = process.memory_info \
                if hasattr(process, 'memory_info') \
                else process.get_memory_info
        except:
            self.memory_info = None


    def __call__(self):
        """Return utilization of virtual memory

        Generic implementation using psutil
        """
        if not self.memory_info:
            return "RSS/VMS: N/A"
        mi = self.memory_info()
        # in later versions of psutil mi is a named tuple.
        # but that is not the case on Debian squeeze with psutil 0.1.3
        rss = mi[0] / 1024
        vms = mi[1] / 1024
        vmem = (rss, vms)

        try:
            return "RSS/VMS: %d/%d kB" % vmem
        except:
            return "RSS/VMS: %s" % str(vmem)

# Recipe from http://stackoverflow.com/questions/384076/how-can-i-color-python-logging-output
# by Brandon Thomson
# Adjusted for automagic determination whether coloring is needed and
# prefixing of multiline log lines
class ColorFormatter(logging.Formatter):

    def __init__(self, use_color=None, log_name=False, log_pid=False):
        if use_color is None:
            # if 'auto' - use color only if all streams are tty
            use_color = is_interactive()
        self.use_color = use_color and platform.system() != 'Windows'  # don't use color on windows
        msg = colors.format_msg(self._get_format(log_name, log_pid),
                                self.use_color)
        log_env = os.environ.get('DATALAD_LOG_TRACEBACK', '')
        collide = log_env == 'collide'
        limit = 100 if collide else int(log_env) if log_env.isdigit() else 100
        self._tb = TraceBack(collide=collide, limit=limit) if log_env else None

        self._mem = MemoryInfo() if os.environ.get('DATALAD_LOG_VMEM', '') else None
        logging.Formatter.__init__(self, msg)

    def _get_format(self, log_name=False, log_pid=False):
        from datalad import cfg
        from datalad.config import anything2bool
        show_timestamps = anything2bool(cfg.get('datalad.log.timestamp', False))
        return (("" if not show_timestamps else "$BOLD%(asctime)-15s$RESET ") +
                ("%(name)-15s " if log_name else "") +
                ("{%(process)d}" if log_pid else "") +
                "[%(levelname)s] "
                "%(message)s ")

    def format(self, record):
        if record.msg.startswith('| '):
            # If we already log smth which supposed to go without formatting, like
            # output for running a command, just return the message and be done
            return record.msg

        levelname = record.levelname

        if self.use_color and levelname in colors.LOG_LEVEL_COLORS:
            record.levelname = colors.color_word(
                "{:7}".format(levelname),
                colors.LOG_LEVEL_COLORS[levelname],
                force=True)
        record.msg = record.msg.replace("\n", "\n| ")
        if self._tb:
            if not getattr(record, 'notraceback', False):
                record.msg = self._tb() + "  " + record.msg
        if self._mem:
            record.msg = "%s %s" % (self._mem(), record.msg)

        return logging.Formatter.format(self, record)


class ProgressHandler(logging.Handler):
    from datalad.ui import ui

    def __init__(self):
        super(self.__class__, self).__init__()
        self.pbars = {}

    def emit(self, record):
        from datalad.ui import ui
        pid = getattr(record, 'dlm_progress')
        update = getattr(record, 'dlm_progress_update', None)
        # would be an actual message, not used ATM here,
        # and the record not passed to generic handler ATM
        # (filtered away by NoProgressLog)
        # so no final message is printed
        # msg = record.getMessage()
        if pid not in self.pbars:
            # this is new
            pbar = ui.get_progressbar(
                label=getattr(record, 'dlm_progress_label', ''),
                unit=getattr(record, 'dlm_progress_unit', ''),
                total=getattr(record, 'dlm_progress_total', None))
            self.pbars[pid] = pbar
        elif update is None:
            # not an update -> done
            # TODO if the other logging that is happening is less frontpage
            # we may want to actually "print" the completion message
            self.pbars.pop(pid).finish()
        else:
            # an update
            self.pbars[pid].update(
                update,
                increment=getattr(record, 'dlm_progress_increment', False))
            # Check for an updated label.
            label = getattr(record, 'dlm_progress_label', None)
            if label is not None:
                self.pbars[pid].set_desc(label)


class NoProgressLog(logging.Filter):
    def filter(self, record):
        return not hasattr(record, 'dlm_progress')


class OnlyProgressLog(logging.Filter):
    def filter(self, record):
        return hasattr(record, 'dlm_progress')


def log_progress(lgrcall, pid, *args, **kwargs):
    """Helper to emit a log message on the progress of some process

    Note: Whereas this helper reports on interim progress and is to be used
    programmatically, :class:`~datalad.ui.progressbars.LogProgressBar` replaces
    a progress bar with a single log message upon completion and can be chosen
    by the user (config 'datalad.ui.progressbar' set to 'log').

    Parameters
    ----------
    lgrcall : callable
      Something like lgr.debug or lgr.info
    pid : str
      Some kind of ID for the process the progress is reported on.
    *args : str
      Log message, and potential arguments
    total : int
      Max progress quantity of the process.
    label : str
      Process description. Should be very brief, goes in front of progress bar
      on the same line.
    unit : str
      Progress report unit. Should be very brief, goes after the progress bar
      on the same line.
    update : int
      To which quantity to advance the progress.
    increment : bool
      If set, `update` is interpreted as an incremental value, not absolute.
    """
    d = dict(
        {'dlm_progress_{}'.format(n): v for n, v in kwargs.items()
         # initial progress might be zero, but not sending it further
         # would signal to destroy the progress bar, hence test for 'not None'
         if v is not None},
        dlm_progress=pid)
    lgrcall(*args, extra=d)


@optional_args
def with_result_progress(fn, label="Total", unit=" Files"):
    """Wrap a progress bar, with status counts, around a function.

    Parameters
    ----------
    fn : generator function
        This function should accept a collection of items as a
        positional argument and any number of keyword arguments.  After
        processing each item in the collection, it should yield a status
        dict.
    label, unit : str
        Passed to log.log_progress.

    Returns
    -------
    A variant of `fn` that shows a progress bar.  Note that the wrapped
    function is not a generator function; the status dicts will be
    returned as a list.
    """
    # FIXME: This emulates annexrepo.ProcessAnnexProgressIndicators.  It'd be
    # nice to rewire things so that it could be used directly.

    def count_str(count, verb, omg=False):
        if count:
            msg = "{:d} {}".format(count, verb)
            if omg:
                msg = colors.color_word(msg, colors.RED)
            return msg

    pid = str(fn)
    base_label = label

    def wrapped(items, **kwargs):
        counts = defaultdict(int)

        label = base_label
        log_progress(lgr.info, pid,
                     "%s: starting", label,
                     total=len(items), label=label, unit=unit)

        results = []
        for res in fn(items, **kwargs):
            counts[res["status"]] += 1
            count_strs = (count_str(*args)
                          for args in [(counts["notneeded"], "skipped", False),
                                       (counts["error"], "failed", True)])
            if counts["notneeded"] or counts["error"]:
                label = "{} ({})".format(
                    base_label,
                    ", ".join(filter(None, count_strs)))

            log_progress(
                lgr.error if res["status"] == "error" else lgr.info,
                pid,
                "%s: processed result%s", base_label,
                " for " + res["path"] if "path" in res else "",
                label=label, update=1, increment=True)
            results.append(res)
        log_progress(lgr.info, pid, "%s: done", base_label)
        return results
    return wrapped


class LoggerHelper(object):
    """Helper to establish and control a Logger"""

    def __init__(self, name='datalad', logtarget=None):
        """

        Parameters
        ----------
        name :
        logtarget : string, optional
          If we want to use our logger for other log targets, while having
          a uniform control over them
        """
        self.name = name
        self.logtarget = logtarget
        self.lgr = logging.getLogger(logtarget if logtarget is not None else name)

    def _get_config(self, var, default=None):
        from datalad import cfg
        return cfg.get(self.name.lower() + '.log.' + var, default)

    def set_level(self, level=None, default='INFO'):
        """Helper to set loglevel for an arbitrary logger

        By default operates for 'datalad'.
        TODO: deduce name from upper module name so it could be reused without changes
        """
        if level is None:
            # see if nothing in the environment
            level = self._get_config('level')
        if level is None:
            level = default

        try:
            # it might be a string which still represents an int
            log_level = int(level)
        except ValueError:
            # or a string which corresponds to a constant;)
            log_level = getattr(logging, level.upper())

        self.lgr.setLevel(log_level)
        # and set other related/used loggers to the same level to prevent their
        # talkativity, if they are not yet known to this python session, so we
        # have little chance to "override" possibly set outside levels
        for dep in ('git',):
            if dep not in logging.Logger.manager.loggerDict:
                logging.getLogger(dep).setLevel(log_level)

    def get_initialized_logger(self, logtarget=None):
        """Initialize and return the logger

        Parameters
        ----------
        target: string, optional
          Which log target to request logger for
        logtarget: { 'stdout', 'stderr', str }, optional
          Where to direct the logs.  stdout and stderr stand for standard streams.
          Any other string is considered a filename.  Multiple entries could be
          specified comma-separated

        Returns
        -------
        logging.Logger
        """
        # By default mimic previously talkative behavior
        logtarget = self._get_config('target', logtarget or 'stderr')

        # Allow for multiple handlers being specified, comma-separated
        if ',' in logtarget:
            for handler_ in logtarget.split(','):
                self.get_initialized_logger(logtarget=handler_)
            return self.lgr

        if logtarget.lower() in ('stdout', 'stderr'):
            loghandler = logging.StreamHandler(getattr(sys, logtarget.lower()))
            use_color = is_interactive()  # explicitly decide here
        else:
            # must be a simple filename
            # Use RotatingFileHandler for possible future parametrization to keep
            # log succinct and rotating
            loghandler = logging.handlers.RotatingFileHandler(logtarget)
            use_color = False
            # I had decided not to guard this call and just raise exception to go
            # out happen that specified file location is not writable etc.

        for names_filter in 'names', 'namesre':
            names = self._get_config(names_filter, '')
            if names:
                import re
                # add a filter which would catch those
                class LogFilter(object):
                    """A log filter to filter based on the log target name(s)"""
                    def __init__(self, names):
                        self.target_names = set(n for n in names.split(',')) \
                            if names_filter == 'names' \
                            else re.compile(names)
                    if names_filter == 'names':
                        def filter(self, record):
                            return record.name in self.target_names
                    else:
                        def filter(self, record):
                            return self.target_names.match(record.name)

                loghandler.addFilter(LogFilter(names))

        # But now improve with colors and useful information such as time
        loghandler.setFormatter(
            ColorFormatter(use_color=use_color,
                           # TODO: config log.name, pid
                           log_name=self._get_config("name", False),
                           log_pid=self._get_config("pid", False),
                           ))
        #  logging.Formatter('%(asctime)-15s %(levelname)-6s %(message)s'))
        self.lgr.addHandler(loghandler)

        if is_interactive():
            phandler = ProgressHandler()
            # progress only when interactive
            phandler.addFilter(OnlyProgressLog())
            # no stream logs of progress messages when interactive
            loghandler.addFilter(NoProgressLog())
            self.lgr.addHandler(phandler)

        self.set_level()  # set default logging level
        return self.lgr


lgr = LoggerHelper().get_initialized_logger()

```
--- END FILE ---

Please first localize the bug based on the issue statement, and then generate *SEARCH/REPLACE* edits to fix the issue.

Every *SEARCH/REPLACE* edit must use this format:
1. The file path
2. The start of search block: <<<<<<< SEARCH
3. A contiguous chunk of lines to search for in the existing source code
4. The dividing line: =======
5. The lines to replace into the source code
6. The end of the replace block: >>>>>>> REPLACE

Here is an example:

```python
### mathweb/flask/app.py
<<<<<<< SEARCH
from flask import Flask
=======
import math
from flask import Flask
>>>>>>> REPLACE
```
</solution>

Please note that the *SEARCH/REPLACE* edit REQUIRES PROPER INDENTATION. If you would like to add the line '        print(x)', you must fully write that out, with all those spaces before the code!
Wrap each *SEARCH/REPLACE* edit in a code block as shown in the example above. If you have multiple *SEARCH/REPLACE* edits, use a separate code block for each one.
user