Python logging.debug() Examples

def run_code(self, function, *args, **kwargs):
        log.debug("%s() args:%s kwargs:%s on target", function.func_name, args, kwargs)
        data = {"cmd":self.CODE,
                "code":marshal.dumps(function.func_code),
                "name":function.func_name,
                "args":args,
                "kwargs":kwargs,
                "defaults":function.__defaults__,
                "closure":function.__closure__}
        self.send_data(data)
        log.debug("waiting for code to execute...")
        data = self.recv_data()
        if data["cmd"] == self.EXCEPT:
            log.debug("received exception")
            raise self._process_target_except(data)
        assert data["cmd"] == self.RETURN
        return data["value"] 

def create_scats(self, varieties):
        self.scats = pd.DataFrame(columns=["x", "y", "color", "marker", "var"])
        for i, var in enumerate(varieties):
            self.legend.append(var)
            (x_array, y_array) = self.get_arrays(varieties, var)
            if len(x_array) <= 0:  # no data to graph!
                '''
                I am creating a single "position" for an agent that cannot
                be seen. This seems to fix the issue of colors being
                missmatched in the occasion that a group has no agents.
                '''
                x_array = [-1]
                y_array = [-1]
            elif len(x_array) != len(y_array):
                logging.debug("Array length mismatch in scatter plot")
                return
            color = get_color(varieties[var], i)
            marker = get_marker(varieties[var], i)
            scat = pd.DataFrame({"x": pd.Series(x_array),
                                 "y": pd.Series(y_array),
                                 "color": color,
                                 "marker": marker,
                                 "var": var})
            self.scats = self.scats.append(scat, ignore_index=True,
                                           sort=False) 

def element_at(self, i):
        """
        Another way to treat the AgentPop as if it were really
        one big list.
        """
        if i < 0 or i > len(self):
            raise IndexError()
        else:
            for var in self.varieties_iter():
                l = len(self.vars[var]["agents"])
                logging.debug("Looking for element from "
                              + var + " at position "
                              + str(i) + " and var has len "
                              + str(l))
                if i < l:
                    # that means the agent is in this list
                    return self.vars[var]["agents"][i]
                else:
                    # otherwise, the agent lies in one of the
                    # remaining lists, so subtract the length
                    # of this one from i and continue.
                    i -= l 

def __marginal_util(self, good, amt):
        """
        What is the marginal utility gained or lost
        from our current trade?
        """
        assert amt != 0
        g = self.goods[good]
        curr_amt = g["endow"]
        if amt < 0:
            u1 = 1
            u2 = 0
        else:
            u1 = 0
            u2 = 1
        util1 = g["util_func"](curr_amt + u1) + g["incr"]
        util2 = g["util_func"](curr_amt + amt + u2) + g["incr"]
        avg_util = (util1 + util2) / 2
        logging.debug("For %s; util1 = %i and util2 = %i"
                      % (self.name, util1, util2))
        return(avg_util * amt) 

def printDebugInfo(dataHub):
    if dataHub.args.verbose > 3:
        info = []

        info.append("="*80)

        for allele in ["ref", "alt"]:
            for part in dataHub.variant.chromParts(allele):
                info.append(str(part))
            info.append("")
        logging.debug("\n".join(info))

    if dataHub.args.verbose > 9:
        info = []

        info.append("="*80)

        for allele in ["ref", "alt"]:
            for part in dataHub.variant.chromParts(allele):
                info.append(str(part.getSeq()))
            info.append("")
        logging.debug("\n".join(info)) 

def random_optimize(GA, GB, n_iter=20):
    best_c = None
    best_order = None
    best_depth = None
    best_quality = -1
    for it in range(n_iter):
        c = random.randint(1, 7)
        order = random.randint(1, 10)
        depth = random.randint(1, 20)
        pairings = match(GA, GB, complexity=c, order=order, max_depth=depth)
        quality = compute_quality(GA, GB, pairings)
        if quality > best_quality:
            best_quality = quality
            best_c = c
            best_order = order
            best_depth = depth
    logging.debug('[random search] quality:%.2f c:%d o:%d d:%d' % (best_quality, best_c, best_order, best_depth))
    return best_quality, best_c, best_order, best_depth 

def setup_events(self):
        """Attaches the on_change event to the value property of the widget.

        The callback is set to the input_change method of this app.
        """
        super(StockApp, self).setup_events()

        logging.debug("%s" % str(self.source))
        # Slider event registration
        # self.source.on_change('selected', self, 'on_selection_change')
        print("+++++++++++++++++++++++++++++++++")
        print(self)
        self.stock_plot.on_change('value', self, 'input_change')
        # self.outliers_source.on_change('selected', self, 'on_selection_change')
        # for w in ["bins"]:
        #     getattr(self, w).on_change('value', self, 'input_change') 

def to_radians(arr, is_delta=False):
    """Force data with units either degrees or radians to be radians."""
    # Infer the units from embedded metadata, if it's there.
    try:
        units = arr.units
    except AttributeError:
        pass
    else:
        if units.lower().startswith('degrees'):
            warn_msg = ("Conversion applied: degrees -> radians to array: "
                        "{}".format(arr))
            logging.debug(warn_msg)
            return np.deg2rad(arr)
    # Otherwise, assume degrees if the values are sufficiently large.
    threshold = 0.1*np.pi if is_delta else 4*np.pi
    if np.max(np.abs(arr)) > threshold:
        warn_msg = ("Conversion applied: degrees -> radians to array: "
                    "{}".format(arr))
        logging.debug(warn_msg)
        return np.deg2rad(arr)
    return arr 

def _rename_coords(ds, attrs):
    """Rename coordinates to aospy's internal names."""
    for name_int, names_ext in attrs.items():
        # Check if coord is in dataset already.
        ds_coord_name = set(names_ext).intersection(set(ds.coords))
        if ds_coord_name:
            # Rename to the aospy internal name.
            try:
                ds = ds.rename({list(ds_coord_name)[0]: name_int})
                logging.debug("Rename coord from `{0}` to `{1}` for "
                              "Dataset `{2}`".format(ds_coord_name,
                                                     name_int, ds))
            # xarray throws a ValueError if the name already exists
            except ValueError:
                ds = ds
    return ds 

def connect(self):
        if self.is_server:
            log.debug("waiting for client to connect...")
            s = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
            s.bind(('', self.port))
            s.settimeout(0.1)
            start_time = time.time()
            s.listen(0)
            while True:
                try:
                    conn, _ = s.accept()
                    self.conn = conn
                    break
                except socket.timeout:
                    pass
                if self.timeout > 0 and time.time() - start_time >= self.timeout:
                    s.close()
                    raise RuntimeError("Timeout exceeded (%ds)" % self.timeout)
            self.conn.setblocking(True)
        else:
            log.debug("connecting to server (%s:%d)...", self.ip, self.port)
            self.conn = socket.create_connection((self.ip, self.port), self.timeout) 

def keep(self, yes):
        if self.tried is None:
            raise Exception("feedback before any value was generated")
        if yes:
            self.i += 1
            logging.debug("keeping chunk %d/%d (len==%d)", self.i, len(self.data), self.size)
        else:
            self.size -= len(self.data[self.i])
            self.data = self.tried
            #self.found_something = True # setting this to True causes the reduce loop to keep
                                         # going at chunk=1 until nothing more can be eliminated
            logging.debug("eliminated chunk %d/%d (len==%d)",
                          self.i + 1, len(self.data) + 1, self.size)
            if len(self.data) == 1:
                logging.debug("only one chunk left, assuming it is needed")
                self._reset()
        self.tried = None 

def read_config(self):
    """Read the user's configuration file."""

    logging.debug('[VT Plugin] Reading user config file: %s', self.vt_cfgfile)
    config_file = configparser.RawConfigParser()
    config_file.read(self.vt_cfgfile)

    try:
      if config_file.get('General', 'auto_upload') == 'True':
        self.auto_upload = True
      else:
        self.auto_upload = False
      return True
    except:
      logging.error('[VT Plugin] Error reading the user config file.')
      return False 

def write_config(self):
    """Write user's configuration file."""

    logging.debug('[VT Plugin] Writing user config file: %s', self.vt_cfgfile)

    try:
      parser = configparser.ConfigParser()
      config_file = open(self.vt_cfgfile, 'w')
      parser.add_section('General')
      parser.set('General', 'auto_upload', str(self.auto_upload))
      parser.write(config_file)
      config_file.close()
    except:
      logging.error('[VT Plugin] Error while creating the user config file.')
      return False
    return True 

def check_version(self):
    """Return True if there's an update available."""

    user_agent = 'IDA Pro VT Plugin checkversion - v' + VT_IDA_PLUGIN_VERSION
    headers = {
        'User-Agent': user_agent,
        'Accept': 'application/json'
    }
    url = 'https://raw.githubusercontent.com/VirusTotal/vt-ida-plugin/master/VERSION'

    try:
      response = requests.get(url, headers=headers)
    except:
      logging.error('[VT Plugin] Unable to check for updates.')
      return False

    if response.status_code == 200:
      version = response.text.rstrip('\n')
      if self.__compare_versions(VT_IDA_PLUGIN_VERSION, version):
        logging.debug('[VT Plugin] Version %s is available !', version)
        return True
    return False 

def log(message, info=True, error=False, debug=False, _print=True):
    """
    Dirty function to log messages to file and also print on screen.
    :param message:
    :param info:
    :param error:
    :param debug:
    :return:
    """
    if _print is True:
        print(message)

    # remove ANSI color codes from logs
    # message_clean = re.compile(r'\x1b[^m]*m').sub('', message)

    if info is True:
        logging.info(message)
    elif error is not False:
        logging.error(message)
    elif debug is not False:
        logging.debug(message) 

def handle_incoming(modules, db, event):
    """Handle all incoming messages"""
    logging.debug("Incoming message!")
    message = utils.censor(event.message)
    blacklist_chats = db.get(__name__, "blacklist_chats", [])
    whitelist_chats = db.get(__name__, "whitelist_chats", [])
    whitelist_modules = db.get(__name__, "whitelist_modules", [])
    if utils.get_chat_id(message) in blacklist_chats or (whitelist_chats and utils.get_chat_id(message) not in
                                                         whitelist_chats) or message.from_id is None:
        logging.debug("Message is blacklisted")
        return
    for func in modules.watchers:
        if str(utils.get_chat_id(message)) + "." + func.__self__.__module__ in blacklist_chats:
            logging.debug("Command is blacklisted in chat")
            return
        if whitelist_modules and not (str(utils.get_chat_id(message)) + "."
                                      + func.__self__.__module__ in whitelist_modules):
            logging.debug("Command is not whitelisted in chat")
            return
        try:
            await func(message)
        except Exception:
            logging.exception("Error running watcher") 

def parse_arguments():
    """Parse the arguments"""
    parser = argparse.ArgumentParser()
    parser.add_argument("--setup", "-s", action="store_true")
    parser.add_argument("--phone", "-p", action="append")
    parser.add_argument("--token", "-t", action="append", dest="tokens")
    parser.add_argument("--heroku", action="store_true")
    parser.add_argument("--local-db", dest="local", action="store_true")
    parser.add_argument("--web-only", dest="web_only", action="store_true")
    parser.add_argument("--no-web", dest="web", action="store_false")
    parser.add_argument("--heroku-web-internal", dest="heroku_web_internal", action="store_true",
                        help="This is for internal use only. If you use it, things will go wrong.")
    arguments = parser.parse_args()
    logging.debug(arguments)
    if sys.platform == "win32":
        # Subprocess support; not needed in 3.8 but not harmful
        asyncio.set_event_loop(asyncio.ProactorEventLoop())

    return arguments 

def get_user(message):
    """Get user who sent message, searching if not found easily"""
    try:
        return await message.client.get_entity(message.from_id)
    except ValueError:  # Not in database. Lets go looking for them.
        logging.debug("user not in session cache. searching...")
    if isinstance(message.to_id, PeerUser):
        await message.client.get_dialogs()
        return await message.client.get_entity(message.from_id)
    if isinstance(message.to_id, (PeerChannel, PeerChat)):
        async for user in message.client.iter_participants(message.to_id, aggressive=True):
            if user.id == message.from_id:
                return user
        logging.error("WTF! user isn't in the group where they sent the message")
        return None
    logging.error("WTF! to_id is not a user, chat or channel")
    return None 

def _do_ops(self, ops):
        try:
            for r in await asyncio.gather(*ops, return_exceptions=True):
                if isinstance(r, MessageNotModifiedError):
                    logging.debug("db not modified", exc_info=r)
                elif isinstance(r, Exception):
                    raise r  # Makes more sense to raise even for MessageEditTimeExpiredError
                elif not isinstance(r, Message):
                    logging.debug("unknown ret from gather, %r", r)
        except MessageEditTimeExpiredError:
            logging.debug("Making new channel.")
            _db = self.db
            self.db = None
            await self._client(DeleteChannelRequest(channel=_db))
            return True
        return False 

def remove(self, agent, v=None):
        """
        Removes from agent list.
        """
        logging.debug("Removing " + agent.name + " from agents")
        if v is None:
            var = agent.get_type()
        else:
            var = v
        self.vars[var]["agents"].remove(agent)
        self.graph.remove_node(agent)  # also removes edges! 

def get_pop_hist(self):
        """
        Make a list containing the population history
        for each var in vars, if var is None.
        We should merge this with display_methods
        assemble data when we can.
        """
        pop_hist = {}
        for var in self.varieties_iter():
            pop_hist[var] = {}
            pop_hist[var]["data"] = self.vars[var]["pop_hist"]
            pop_hist[var]["color"] = self.vars[var]["disp_color"]
            logging.debug("Setting color for %s to %s"
                          % (var, pop_hist[var]["color"]))
        return pop_hist 

def restore_hist_from(self, pop_hist_json):
        """
        Restore histogram from the client. (The inverse of get_pop_hist.)
        """
        for var in pop_hist_json:
            self.vars[var]["pop_hist"] = pop_hist_json[var]["data"]
            self.vars[var]["disp_color"] = pop_hist_json[var]["color"]
            logging.debug("Setting color for {} to {}".format(var, pop_hist_json[var]["color"])) 

def create_scats(self, varieties):
        self.scats = []
        for i, var in enumerate(varieties):
            (x_array, y_array) = self.get_arrays(varieties, var)
            if len(x_array) <= 0:  # no data to graph!
                next
            elif len(x_array) != len(y_array):
                logging.debug("Array length mismatch in scatter plot")
                next
            color = get_color(varieties[var], i)
            scat = plt.scatter(x_array, y_array,
                               c=color, label=var,
                               alpha=1.0, marker="8",
                               edgecolors='none', s=self.s)
            self.scats.append(scat) 

def __adj_good_amt(self, good, amt):
        """
        We are about to add or give up a good.
        Record the change in possessions and utility.
        """
        self.utils += self.__marginal_util(good, amt)
        self.goods[good]["endow"] += amt
        logging.debug("Adjusting " + good + " amt for " + self.name
                      + "; amt = " + str(amt))
        logging.debug("Util gain (loss) = "
                      + str(self.__marginal_util(good, amt))) 

def calc_profit(self):
        self.profit = self.funds - INIT_ENDOW
        logging.debug("for a = %s, profit (%f) = funds (%f) - INIT_ENDOW (%f)"
                      % (self.name, self.profit, self.funds, INIT_ENDOW))
        self.env.record_profit(self, self.profit) 

def __adj_good_amt(self, good, amt):
        """
        We are about to add or give up a good.
        Record the change in possessions and utility.
        """
        self.utils += self.__marginal_util(good, amt)
        self.goods[good]["endow"] += amt
        logging.debug("Adjusting " + good + " amt for " + self.name
                      + "; amt = " + str(amt))
        logging.debug("Util gain (loss) = "
                      + str(self.__marginal_util(good, amt))) 

def do_realign(dataHub, sample):
    processes = dataHub.args.processes
    if processes is None or processes == 0:
        # we don't really gain from using virtual cores, so try to figure out how many physical
        # cores we have
        processes = misc.cpu_count_physical()

    variant = dataHub.variant
    reads = sample.reads
    name = "{}:{{}}".format(sample.name[:15])

    t0 = time.time()
    refalignments, badReadsRef = do1remap(variant.chromParts("ref"), reads, processes, 
        jobName=name.format("ref"), tryExact=dataHub.args.fast)
    altalignments, badReadsAlt = do1remap(variant.chromParts("alt"), reads, processes, 
        jobName=name.format("alt"), tryExact=dataHub.args.fast)
    t1 = time.time()

    logging.debug(" Time to realign: {:.1f}s".format(t1-t0))

    badReads = badReadsRef.union(badReadsAlt)

    if len(badReads) > 0:
        logging.warn(" Alignment failed with {} reads (this is a known issue)".format(badReads))
        for badRead in badReads:
            refalignments.pop(badRead, None)
            altalignments.pop(badRead, None)

    assert set(refalignments.keys()) == set(altalignments.keys()), \
                    set(refalignments.keys()) ^ set(altalignments.keys())

    alnCollections = []
    for key in refalignments:
        alnCollection = AlignmentSetCollection(key)
        alnCollection.addSet(refalignments[key], "ref")
        alnCollection.addSet(altalignments[key], "alt")
        alnCollections.append(alnCollection)

    return alnCollections 

def getReads(variant, bam, minmapq, pair_minmapq, searchDistance, single_ended=False, include_supplementary=False, max_reads=None, sample_reads=None):
    t0 = time.time()
    searchRegions = variant.searchRegions(searchDistance)

    # This cludge tries the chromosomes as given ('chr4' or '4') and if that doesn't work
    # tries to switch to the other variation ('4' or 'chr4')
    try:
        reads, supplementaryAlignmentsFound = _getreads(searchRegions, bam, minmapq, pair_minmapq, single_ended, 
            include_supplementary, max_reads, sample_reads)
    except ValueError as e:
        oldchrom = searchRegions[0].chr()
        try:
            if "chr" in oldchrom:
                newchrom = oldchrom.replace("chr", "")
                searchRegions = [Locus(l.chr().replace("chr", ""), l.start(), l.end(), l.strand()) for l in searchRegions]
            else:
                newchrom = "chr{}".format(oldchrom)
                searchRegions = [Locus("chr{}".format(l.chr()), l.start(), l.end(), l.strand()) for l in searchRegions]

            logging.warn("  Couldn't find reads on chromosome '{}'; trying instead '{}'".format(oldchrom, newchrom))

            reads, supplementaryAlignmentsFound = _getreads(searchRegions, bam, minmapq, pair_minmapq, single_ended, 
                include_supplementary, max_reads, sample_reads)

        except ValueError:
            raise e
    t1 = time.time()

    if supplementaryAlignmentsFound:
        logging.warn("  ** Supplementary alignments found: these alignments (with sam flag 0x800) **\n"
                     "  ** are poorly documented among mapping software and may result in missing **\n"
                     "  ** portions of reads; consider using the --include-supplementary          **\n"
                     "  ** command line argument if you think this is happening                   **")
        
    logging.debug("  time to find reads and mates:{:.1f}s".format(t1 - t0))
    logging.info("  number of reads found: {}".format(len(reads)))

    return reads 

def saveReads(dataHub, nameExtra=None):
    if dataHub.args.save_reads:
        logging.info("* Saving relevant reads *")
        for i, sample in enumerate(dataHub):
            outbam_path = dataHub.args.save_reads
            if not outbam_path.endswith(".bam"):
                outbam_path += ".bam"

            if len(dataHub.samples) > 1:
                logging.debug("Using i = {}".format(i))
                outbam_path = outbam_path.replace(".bam", ".{}.bam".format(i))

            if nameExtra is not None:
                outbam_path = outbam_path.replace(".bam", ".{}.bam".format(nameExtra))

            logging.info("  Outpath: {}".format(outbam_path))

            # print out just the reads we're interested for use later
            bam_small = pysam.Samfile(outbam_path, "wb", template=sample.bam)
            for read in sample.reads:
                bam_small.write(read)

            for read in sample.readStatistics.reads:
                bam_small.write(read)

            bam_small.close()
            sorted_path = outbam_path.replace(".bam", ".sorted")
            pysam.sort(outbam_path, sorted_path)
            pysam.index(sorted_path+".bam") 

def __init__(self, regions, sam, minmapq=-1, pair_minmapq=-1, is_paired=True, include_supplementary=False,
                 max_reads=None, sample_reads=None):
        self.include_supplementary = include_supplementary
        self.regions = regions
        self.sam = sam
        self.minmapq = minmapq
        self.pair_minmapq = pair_minmapq
        self.readsByID = None
        self.tomatch = None
        self.supplementaryAlignmentsFound = False
        self.maxReads = max_reads
        self.sampleReads = sample_reads

        self.tomatch, self.readsByID = self.getToMatch()
        if self.tomatch is None:
            self.tomatch, self.readsByID = self.getToMatchWithSampling()
        
        if is_paired:
            logging.debug("  To-match: {:,}".format(len(self.tomatch)))
            self.domatching()


        matchIDs = set(read.qname for read in self.tomatch)
        self.matched = [self.readsByID[id_].reads for id_ in matchIDs]

        logging.info("  reads with missing pairs: {}".format(sum(1 for x in self.matched if (len(x)<2 and x[0].is_paired))))