def _format_string(self, formatter, arguments): """Searches for the formatter string in the debug information. Also checks the downloadable capabilities. Args: string_ptr: Pointer to the formatter string. arguments: Arguments for the formatter string. Note this can change. """ try: # python can't handle the '%p' format specifier, apparently. formatter = re.sub(r'%([0-9]*)p', r'0x%\g<1>x', formatter) formattedstr = formatter % tuple( arguments) # works for an empty list too except TypeError as exception: # TypeError: %d format: a number is required, not str # Nasty special case: if we incorrectly interpreted a large number # as a string, the format specifier won't match here. if re.search("arguments number is required", str(exception)): specifiers = re.findall(r"%([\d\w]+)", formatter) # if len(specifiers) != len(arguments) bad case for idx, val in enumerate(specifiers): # If the specifier isn't a string, but we have a string in # args, try to correct our mistake. cs_available = re.search("[cs]", val) if not cs_available and isinstance(arguments[idx], str): # Replace the string with the original large number. # That requires a search through all the debug strings # to work out what the number was. debug_strings = self.debuginfo.get_kymera_debuginfo( ).debug_strings for addr, string in debug_strings.items(): if string == arguments[idx]: arguments[idx] = addr formattedstr = formatter % tuple(arguments) else: formattedstr = ("\n@@@@ ERROR:" + str(exception) + "\n" + " formatter string: %s\n" % (formatter) + " arguments: %s\n" % (cu.list_to_string(arguments))) return formattedstr
def _decode_log(self): """Same as decode_log, but is not thread safe.""" # Form the list on a temporary list so we don't duplicate old entries tmp_debug_log = [] # Read all the debug variables. buffer_wrp = self.chipdata.get_data(self.p_buffer_wrp) debug_buffer = self.chipdata.get_data(self.p_buffer, self.buffer_size) if buffer_wrp == self.last_read + 1: # Nothing new in the log so don't bother reading it return # The debug buffer looks like this: # # [appppaapapaa...............ppp] # ^ ^ ^ # debug_buffer buffer_wrp len(debug_buffer) # # p = string pointer, arguments = string argument # Decoding is more complicated than you might think, because: # * We can't assume that a value > $flash.debugdata.__Base is a string # pointer (it could just be a large number) # * String pointers can in some circumstances be arguments to other # strings (more details below). # * The buffer may not be completely full # * The buffer may have wrapped unevenly, so that the first few # arguments after buffer_wrp are orphaned from the corresponding # string. # # So what we need to do is work backwards from buffer_wrp, find the # last string pointer, and count the number of format specifiers # in it to check that it matches the number of arguments. arguments = [] # list of args for each log statement i = buffer_wrp - 1 # start with the newest entry in the buffer last_read = i # record how far we will read up to this time wrapped = False while True: # Check for a wrap/repeat if i < 0: i = len(debug_buffer) - 1 wrapped = True if wrapped and i <= buffer_wrp: # we've parsed the whole buffer break # We need to look for things that look like pointers to debug # strings. region = Arch.get_dm_region(debug_buffer[i], False) if region == 'DEBUG' or region == 'DBG_DWL' or region == 'DBG_PTCH': mystr = self._get_formatter_string(debug_buffer[i], arguments) # Now it could just so happen that this value is an argument # to printf AND a valid debug string pointer, like: # AUDIO_LOG_STRING(hi, "hello"); # L0_DBG_MSG1("foo: %s", (DBG_STR)hi); # (This construct is especially prevalent in isp_router). # # We can check that the string pointed-to has the same number # of arguments as we have in a[], but that doesn't actually # help in this case since it doesn't allow us to distinguish # between a string that simply has no arguments, and a string # that is an argument to another string. # To avoid painful look-ahead, the simple way to solve this # is to just assume every complete-looking string is actually # complete, and put it into tmp_debug_log[]. If we then come # across a string that doesn't seem to have enough # arguments, we backtrack. Note that we only support one # level of nesting here; if someone has put a formatted # string inside a formatted string then all bets are off. if mystr.count('%') == 0 and arguments: # This could happen if you had something like: # L0_DBG_MSG1("foo: %s %d", (DBG_STR)hi, 0x1234) # This string is clearly just actually an argument. arguments.append(mystr) i -= 1 continue if mystr.count('%') > len(arguments): # We're missing some arguments. We probably put them into # tmp_debug_log[], thinking they were complete strings. num_args_missing = mystr.count('%') - len(arguments) if num_args_missing == mystr.count('%s'): temp_arguments = tmp_debug_log[-num_args_missing:] if Arch.addr_per_word != 4: # For Hydra platforms, like Crescendo and Aura # the arguments in tmp_debug_log[] are in the # right order, because the order in which the # arguments are stored. For Blucore platforms, # like Gordon and Rick, the array slice is in # the wrong order. temp_arguments.reverse() arguments = temp_arguments + arguments # now arguments[] contains what it would have held, # had we not put the missing args into # tmp_debug_log[]. Last thing to do is disavow them. tmp_debug_log[-num_args_missing:] = [] # Now we should have the right number of arguments! str_cnt = mystr.count('%') # Assume this is a complete log. # shrink-wrap the string we just read, and save it. arguments.reverse() # because we added args in reverse order. # format the string. formatter_error = False if str_cnt == len(arguments): try: formatted_str = self._format_string(mystr, arguments) except ValueError: # ValueError can be caused by erroneous formatting # string like a "0x%08" formatter_error = True else: formatter_error = True if formatter_error: formatted_str = ( "\n@@@@ ERROR: Wrong number of arguments! " + "This could be caused by buffer tear. \n" + "Buffer tear happens when messages are " + "written too fast to the log buffer\n" + "and the debug interface cannot keep up in reading them. \n" + " formatter string: %s\n" % (mystr.replace("\n", "")) + " arguments: %s\n" % (cu.list_to_string(arguments))) # Add the formatted string to the debug log. tmp_debug_log.append(formatted_str) # Clear the arguments for the next run. arguments = [] else: # Found an argument. arguments.append(debug_buffer[i]) i -= 1 # next if i == self.last_read: # We've reached where we got to break self.last_read = last_read # invert the debug log so it is printed in the correct order tmp_debug_log.reverse() return tmp_debug_log