Pull adb logcat from renderdoc into log on host machine

* This makes post-mortem debugging easier. It's only active while a remote
  server connection is running, so e.g. it will miss crashes of the remote
  server itself, this could be improved by adding a margin where it will still
  check for messages after the connection is dropped - perhaps on a separate
  thread.
This commit is contained in:
baldurk
2018-08-02 15:09:57 +01:00
parent dad5d6e074
commit c6b02c4d0c
14 changed files with 525 additions and 27 deletions
+4
View File
@@ -40,4 +40,8 @@ Process::ProcessResult adbExecCommand(const std::string &deviceID, const std::st
void initAdb();
void shutdownAdb();
bool InjectWithJDWP(const std::string &deviceID, uint16_t jdwpport);
void ResetLogcat();
void TickDeviceLogcat();
void ProcessLogcat(std::string deviceID);
};
+460 -1
View File
@@ -173,6 +173,356 @@ std::string GetFriendlyName(std::string deviceID)
return combined;
}
static uint64_t getTimeMS()
{
static uint64_t freq = (uint64_t)Timing::GetTickFrequency();
return uint64_t(Timing::GetTick() / freq);
}
// the last time on the host that we processed android logcat, to avoid polling too often
uint64_t lastLogcatProcessTimeMS = 0;
// the last log line we saw, so we start printing after that point. If we ever have a line here and
// we don't see it in the backlog.
std::string lastLogcatLine;
void ResetLogcat()
{
// reset last expected line so we restart from scratch next time
lastLogcatLine.clear();
}
// on android only when we hit this function we write a marker that isn't a standard log. The
// purpose is to always try and have a unique message in the last N lines so that we can detect if
// we ever lose messages.
void TickDeviceLogcat()
{
#if ENABLED(RDOC_ANDROID)
OSUtility::WriteOutput(
OSUtility::Output_DebugMon,
StringFormat::Fmt("__rdoc_internal_android_logcat %llu", getTimeMS()).c_str());
#endif
}
struct LogLine
{
time_t timestamp = 0;
uint32_t pid = 0;
LogType logtype = LogType::Comment;
std::string filename;
uint32_t line_number = 0;
std::string message;
bool parse(const std::string &line)
{
#define EXPECT_CHAR(c) \
if(idx >= line.length() || line[idx] != c) \
return false; \
idx++;
// Parse out mostly our own log files, but also output that looks like crash callstacks
//
// Example lines:
//
// clang-format off
//
// 0 1 2 3 4 5 6 7 8 9 10
// 1234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456
// I/renderdoc( 1234): @1234567812345678@ RDOC 001234: [01:02:03] filename.cpp( 123) - Log - Hello
//
// F/libc (11519): Fatal signal 11 (SIGSEGV), code 1, fault addr 0x4 in tid 11618 (FooBar), pid 11519 (blah)
// F/DEBUG (12061): backtrace:
// F/DEBUG (12061): #00 pc 000485ec /system/lib/libc.so (pthread_mutex_lock+1)
// F/DEBUG (12061): #01 pc 00137449 /data/app/org.renderdoc.renderdoccmd.arm32==/lib/arm/libVkLayer_GLES_RenderDoc.so
// F/DEBUG (12061): #02 pc 0013bbf1 /data/app/org.renderdoc.renderdoccmd.arm32==/lib/arm/libVkLayer_GLES_RenderDoc.so
//
// clang-format on
//
size_t idx = 0;
// too short - minimum is 22 for prefix. Could be longer if PID is over 5 digits
// saves on length checks below
if(line.length() <= 20)
return false;
// skip past priority character
idx++;
EXPECT_CHAR('/');
// we assume that the logcat filters have worked, so ignore the logcat tag here. Just check if
// it's ours or not
bool ownLog = !strncmp(&line[idx], "renderdoc", 9);
while(idx < line.length() && line[idx] != '(')
idx++;
size_t tagEnd = idx;
EXPECT_CHAR('(');
// skip spaces
while(idx < line.length() && isspace(line[idx]))
idx++;
// process this PID field - we'll override it with our own if this is one of our logs
pid = 0;
while(idx < line.length() && isdigit(line[idx]))
{
pid *= 10;
pid += int(line[idx] - '0');
idx++;
}
EXPECT_CHAR(')');
EXPECT_CHAR(':');
EXPECT_CHAR(' ');
if(!ownLog)
{
// don't know anything more about the format, this whole thing is the message.
message = line.substr(idx);
// use current host time, it's not accurate but it's close enough.
timestamp = Timing::GetUTCTime();
filename = line.substr(2, tagEnd - 2);
line_number = 0;
logtype = LogType::Comment;
switch(line[0])
{
case 'V': // VERBOSE
case 'D': // DEBUG
logtype = LogType::Debug;
break;
case 'I': // INFO
logtype = LogType::Comment;
break;
case 'W': // WARN
logtype = LogType::Warning;
break;
case 'E': // ERROR
logtype = LogType::Error;
break;
case 'F': // FATAL
logtype = LogType::Fatal;
break;
case 'S': // SILENT
default: logtype = LogType::Comment; break;
}
// remove any padding spaces
while(!filename.empty() && isspace(filename.back()))
filename.pop_back();
// if adb gave us DOS newlines, remove the \r
if(message.back() == '\r')
message.pop_back();
return true;
}
// skip past digits and '@', this field is only so that we don't ever get duplicates in the
// output even if the same message is printed
while(idx < line.length() && (line[idx] == '@' || isalnum(line[idx])))
idx++;
EXPECT_CHAR(' ');
// should be at least 64 more characters
if(idx + 64 > line.length())
return false;
if(strncmp(&line[idx], "RDOC ", 5))
return false;
idx += 5;
pid = 0;
while(idx < line.length() && isdigit(line[idx]))
{
pid *= 10;
pid += int(line[idx] - '0');
idx++;
}
EXPECT_CHAR(':');
EXPECT_CHAR(' ');
EXPECT_CHAR('[');
// expect HH:MM:SS
if(idx + 8 >= line.length())
return false;
// we only need the time part, so just take it from the epoch
uint32_t h = 0, m = 0, s = 0;
h = int(line[idx + 0] - '0') * 10 + int(line[idx + 1] - '0');
m = int(line[idx + 3] - '0') * 10 + int(line[idx + 4] - '0');
s = int(line[idx + 6] - '0') * 10 + int(line[idx + 7] - '0');
if(line[idx + 2] != ':' || line[idx + 5] != ':')
return false;
timestamp = (h * 60 + m) * 60 + s;
idx += 8;
EXPECT_CHAR(']');
while(idx < line.length() && line[idx] != '(')
{
filename.push_back(line[idx]);
idx++;
}
// strip spaces
while(!filename.empty() && isspace(filename[0]))
filename.erase(0, 1);
while(!filename.empty() && isspace(filename.back()))
filename.pop_back();
if(filename.empty())
return false;
EXPECT_CHAR('(');
while(idx < line.length() && isspace(line[idx]))
idx++;
line_number = 0;
while(idx < line.length() && isdigit(line[idx]))
{
line_number *= 10;
line_number += int(line[idx] - '0');
idx++;
}
EXPECT_CHAR(')');
EXPECT_CHAR(' ');
EXPECT_CHAR('-');
EXPECT_CHAR(' ');
std::string logtype_str;
while(idx < line.length() && line[idx] != '-')
{
logtype_str.push_back(line[idx]);
idx++;
}
// strip spaces
while(!logtype_str.empty() && isspace(logtype_str[0]))
logtype_str.erase(0);
while(!logtype_str.empty() && isspace(logtype_str.back()))
logtype_str.pop_back();
if(logtype_str == "Debug")
logtype = LogType::Debug;
else if(logtype_str == "Log")
logtype = LogType::Comment;
else if(logtype_str == "Warning")
logtype = LogType::Warning;
else if(logtype_str == "Error")
logtype = LogType::Error;
else if(logtype_str == "Fatal")
logtype = LogType::Fatal;
else
return false;
EXPECT_CHAR('-');
EXPECT_CHAR(' ');
if(idx >= line.length())
return false;
message = line.substr(idx);
// if adb gave us DOS newlines, remove the \r
if(message.back() == '\r')
message.pop_back();
#undef EXPECT_CHAR
return true;
}
};
void ProcessLogcat(std::string deviceID)
{
uint64_t curTimeMS = getTimeMS();
// only check for logcat every 500ms, because adb can take ~250ms to run
if(lastLogcatProcessTimeMS + 400 > curTimeMS)
return;
lastLogcatProcessTimeMS = curTimeMS;
// adb is extremely unreliable, so although it supposedly contains functionality to filter for
// everything after a certain timestamp, this can actually drop messages. Instead we just always
// grab the last 750 lines and hope that the device doesn't ever peak over 1 line per millisecond
// such that we'd miss something. Note another joy of adb - the line count is applied *before*
// the filter, so if something else spams 1000 lines we won't see our own.
const uint32_t lineBacklog = 750;
// logcat
// -t N // always the last N messages, and (implied -d) stop after doing so
// -v brief // print the 'brief' format
// -s // silence everything as a default
// renderdoc:* // print logcats from our tag.
// libc:* // or from libc (prints crash messages)
// DEBUG:* // or from DEBUG (prints crash messages)
//
// This gives us all messages from renderdoc since the last timestamp.
std::string command =
StringFormat::Fmt("logcat -t %u -v brief -s renderdoc:* libc:* DEBUG:*", lineBacklog);
std::string logcat = trim(Android::adbExecCommand(deviceID, command, ".", true).strStdout);
std::vector<std::string> lines;
split(logcat, lines, '\n');
// remove \n from any lines right now to prevent it breaking further processing
for(std::string &line : lines)
if(!line.empty() && line.back() == '\r')
line.pop_back();
// only do any processing if we had a line last time that we know to start from.
if(!lastLogcatLine.empty())
{
auto it = std::find(lines.begin(), lines.end(), lastLogcatLine);
if(it != lines.end())
{
// remove everything up to and including that line
lines.erase(lines.begin(), it + 1);
}
else
{
RDCWARN("Couldn't find last line. Potentially missed logcat messages.");
}
for(const std::string &line : lines)
{
LogLine logline;
if(logline.parse(line))
{
rdclog_direct(logline.timestamp, logline.pid, logline.logtype, "ADRD",
logline.filename.c_str(), logline.line_number, "%s", logline.message.c_str());
rdclog_flush();
}
}
}
// store the last line (if we have one) to search for and start from next time
if(!lines.empty())
lastLogcatLine = lines.back();
}
};
template <>
@@ -187,4 +537,113 @@ std::string DoStringise(const Android::ABI &el)
STRINGISE_ENUM_CLASS(x86_64);
}
END_ENUM_STRINGISE();
}
}
#if ENABLED(ENABLE_UNIT_TESTS)
#undef None
#include "3rdparty/catch/catch.hpp"
TEST_CASE("Test that log line parsing is robust", "[android]")
{
using namespace Android;
SECTION("Empty string")
{
LogLine line;
CHECK(line.parse("") == false);
};
SECTION("Invalid strings")
{
LogLine line1;
CHECK(line1.parse("--------- beginning of main") == false);
LogLine line2;
CHECK(
line2.parse("Lorem ipsum dolor sit amet, consectetur adipiscing elit. Nullam lacus lacus, "
"egestas vitae elementum sit amet, venenatis ac nunc.") == false);
};
SECTION("Valid strings")
{
LogLine line;
const char *valid_text =
R"(I/renderdoc( 1234): @1234567812345678@ RDOC 001234: [01:02:03] filename.cpp( 123) - Warning - Hello)";
CHECK(line.parse(valid_text) == true);
CHECK(line.filename == "filename.cpp");
CHECK(line.line_number == 123);
CHECK((line.logtype == LogType::Warning));
CHECK(line.message == "Hello");
CHECK(line.pid == 1234);
CHECK(line.timestamp == 3723);
LogLine highpid;
const char *highpid_text =
R"(I/renderdoc(12345678): @1234567812345678@ RDOC 12345678: [01:02:03] filename.cpp( 123) - Warning - Hello)";
CHECK(highpid.parse(highpid_text) == true);
CHECK(highpid.filename == "filename.cpp");
CHECK(highpid.line_number == 123);
CHECK((highpid.logtype == LogType::Warning));
CHECK(highpid.message == "Hello");
CHECK(highpid.pid == 12345678);
CHECK(highpid.timestamp == 3723);
LogLine longname;
const char *longname_text =
R"(I/renderdoc( 1234): @1234567812345678@ RDOC 001234: [01:02:03] a_very_long_source_filename.cpp( 123) - Warning - Hello)";
CHECK(longname.parse(longname_text) == true);
CHECK(longname.filename == "a_very_long_source_filename.cpp");
CHECK(longname.line_number == 123);
CHECK((longname.logtype == LogType::Warning));
CHECK(longname.message == "Hello");
CHECK(longname.pid == 1234);
CHECK(longname.timestamp == 3723);
LogLine longlinenum;
const char *longlinenum_text =
R"(I/renderdoc( 1234): @1234567812345678@ RDOC 001234: [01:02:03] filename.cpp(12345678) - Warning - Hello)";
CHECK(longlinenum.parse(longlinenum_text) == true);
CHECK(longlinenum.filename == "filename.cpp");
CHECK(longlinenum.line_number == 12345678);
CHECK((longlinenum.logtype == LogType::Warning));
CHECK(longlinenum.message == "Hello");
CHECK(longlinenum.pid == 1234);
CHECK(longlinenum.timestamp == 3723);
};
SECTION("Invalid strings - truncated")
{
std::string truncated =
R"(I/renderdoc( 1234): @1234567812345678@ RDOC 001234: [01:02:03] filename.cpp( 123) - Warning - H)";
LogLine working;
CHECK(working.parse(truncated) == true);
while(!truncated.empty())
{
truncated.pop_back();
LogLine broken;
CHECK(broken.parse(truncated) == false);
}
};
}
#endif
+7 -7
View File
@@ -81,7 +81,8 @@ float SRGB8_lookuptable[256] = {
void rdcassert(const char *msg, const char *file, unsigned int line, const char *func)
{
rdclog_int(LogType::Error, RDCLOG_PROJECT, file, line, "Assertion failed: %s", msg);
rdclog_direct(Timing::GetUTCTime(), Process::GetCurrentPID(), LogType::Error, RDCLOG_PROJECT,
file, line, "Assertion failed: %s", msg);
}
#if 0
@@ -387,8 +388,8 @@ static void write_newline(char *output)
*output = 0;
}
void rdclog_int(LogType type, const char *project, const char *file, unsigned int line,
const char *fmt, ...)
void rdclog_direct(time_t utcTime, uint32_t pid, LogType type, const char *project,
const char *file, unsigned int line, const char *fmt, ...)
{
va_list args;
va_start(args, fmt);
@@ -399,7 +400,7 @@ void rdclog_int(LogType type, const char *project, const char *file, unsigned in
char timestamp[64] = {0};
#if ENABLED(INCLUDE_TIMESTAMP_IN_LOG)
StringFormat::sntimef(timestamp, 63, "[%H:%M:%S] ");
StringFormat::sntimef(utcTime, timestamp, 63, "[%H:%M:%S] ");
#endif
char location[64] = {0};
@@ -424,9 +425,8 @@ void rdclog_int(LogType type, const char *project, const char *file, unsigned in
char *base = output;
int numWritten = StringFormat::snprintf(output, available, "% 4s %06u: %s%s%s - ", project,
Process::GetCurrentPID(), timestamp, location,
typestr[(uint32_t)type]);
int numWritten = StringFormat::snprintf(output, available, "% 4s %06u: %s%s%s - ", project, pid,
timestamp, location, typestr[(uint32_t)type]);
if(numWritten < 0)
{
+5 -3
View File
@@ -296,10 +296,12 @@ void rdclogprint_int(LogType type, const char *fullMsg, const char *msg);
#endif
// printf() style main logger function
void rdclog_int(LogType type, const char *project, const char *file, unsigned int line,
const char *fmt, ...);
void rdclog_direct(time_t utcTime, uint32_t pid, LogType type, const char *project,
const char *file, unsigned int line, const char *fmt, ...);
#define rdclog(type, ...) rdclog_int(type, RDCLOG_PROJECT, __FILE__, __LINE__, __VA_ARGS__)
#define rdclog(type, ...) \
rdclog_direct(Timing::GetUTCTime(), Process::GetCurrentPID(), type, RDCLOG_PROJECT, __FILE__, \
__LINE__, __VA_ARGS__)
const char *rdclog_getfilename();
void rdclog_filename(const char *filename);
+3 -2
View File
@@ -125,8 +125,9 @@ public:
~ScopedTimer()
{
rdclog_int(LogType::Comment, RDCLOG_PROJECT, m_File, m_Line, "Timer %s - %.3lf ms",
m_Message.c_str(), m_Timer.GetMilliseconds());
rdclog_direct(Timing::GetUTCTime(), Process::GetCurrentPID(), LogType::Comment, RDCLOG_PROJECT,
m_File, m_Line, "Timer %s - %.3lf ms", m_Message.c_str(),
m_Timer.GetMilliseconds());
}
private:
+15
View File
@@ -236,6 +236,9 @@ static void ActiveRemoteClientThread(ClientThread *threadData,
if(proxy)
proxy->RefreshPreviewWindow();
// insert a dummy line into our logcat so we can keep track of our progress
Android::TickDeviceLogcat();
WRITE_DATA_SCOPE();
SCOPED_SERIALISE_CHUNK(eRemoteServer_Ping);
}
@@ -1061,6 +1064,16 @@ public:
if(!Connected())
return false;
const char *host = hostname().c_str();
if(Android::IsHostADB(host))
{
int index = 0;
std::string deviceID;
Android::ExtractDeviceIDAndIndex(m_hostname, index, deviceID);
Android::ProcessLogcat(deviceID);
}
{
WRITE_DATA_SCOPE();
SCOPED_SERIALISE_CHUNK(eRemoteServer_Ping);
@@ -1829,6 +1842,8 @@ RENDERDOC_CreateRemoteServerConnection(const char *host, uint32_t port, IRemoteS
{
s = "127.0.0.1";
Android::ResetLogcat();
int index = 0;
std::string deviceID;
Android::ExtractDeviceIDAndIndex(host, index, deviceID);
+5
View File
@@ -45,6 +45,11 @@ int snprintf(char *str, size_t bufSize, const char *fmt, ...)
return ret;
}
void sntimef(char *str, size_t bufSize, const char *format)
{
StringFormat::sntimef(Timing::GetUTCTime(), str, bufSize, format);
}
int vsnprintf(char *str, size_t bufSize, const char *format, va_list args)
{
return ::utf8printf(str, bufSize, format, args);
+4 -1
View File
@@ -88,6 +88,7 @@ namespace Timing
double GetTickFrequency();
uint64_t GetTick();
uint64_t GetUnixTimestamp();
time_t GetUTCTime();
};
namespace Threading
@@ -365,7 +366,7 @@ bool PlatformHasKeyInput();
// implemented per-platform
namespace StringFormat
{
void sntimef(char *str, size_t bufSize, const char *format);
void sntimef(time_t utcTime, char *str, size_t bufSize, const char *format);
string Wide2UTF8(const std::wstring &s);
@@ -379,6 +380,8 @@ namespace StringFormat
int vsnprintf(char *str, size_t bufSize, const char *format, va_list v);
int snprintf(char *str, size_t bufSize, const char *format, ...);
void sntimef(char *str, size_t bufSize, const char *format);
string Fmt(const char *format, ...);
int Wide2UTF8(wchar_t chr, char mbchr[4]);
@@ -117,12 +117,15 @@ namespace OSUtility
{
void WriteOutput(int channel, const char *str)
{
static uint32_t seq = 0;
seq++;
if(channel == OSUtility::Output_StdOut)
fprintf(stdout, "%s", str);
else if(channel == OSUtility::Output_StdErr)
fprintf(stderr, "%s", str);
else if(channel == OSUtility::Output_DebugMon)
__android_log_print(ANDROID_LOG_INFO, LOGCAT_TAG, "%s", str);
__android_log_print(ANDROID_LOG_INFO, LOGCAT_TAG, "@%08x%08x@ %s",
uint32_t(Timing::GetUTCTime()), seq, str);
}
uint64_t GetMachineIdent()
+2 -5
View File
@@ -575,12 +575,9 @@ void logfile_close(const char *filename)
namespace StringFormat
{
void sntimef(char *str, size_t bufSize, const char *format)
void sntimef(time_t utcTime, char *str, size_t bufSize, const char *format)
{
time_t tim;
time(&tim);
tm *tmv = localtime(&tim);
tm *tmv = localtime(&utcTime);
strftime(str, bufSize, format, tmv);
}
+5
View File
@@ -33,6 +33,11 @@ uint64_t Timing::GetUnixTimestamp()
return (uint64_t)time(NULL);
}
time_t Timing::GetUTCTime()
{
return time(NULL);
}
namespace Atomic
{
int32_t Inc32(volatile int32_t *i)
+2 -5
View File
@@ -776,13 +776,10 @@ void logfile_close(const char *filename)
namespace StringFormat
{
void sntimef(char *str, size_t bufSize, const char *format)
void sntimef(time_t utcTime, char *str, size_t bufSize, const char *format)
{
time_t tim;
time(&tim);
tm tmv;
localtime_s(&tmv, &tim);
localtime_s(&tmv, &utcTime);
wchar_t *buf = new wchar_t[bufSize + 1];
buf[bufSize] = 0;
+5
View File
@@ -46,6 +46,11 @@ uint64_t Timing::GetUnixTimestamp()
return (uint64_t)time(NULL);
}
time_t Timing::GetUTCTime()
{
return time(NULL);
}
namespace Atomic
{
int32_t Inc32(volatile int32_t *i)
+4 -2
View File
@@ -221,14 +221,16 @@ extern "C" RENDERDOC_API void RENDERDOC_CC RENDERDOC_SetDebugLogFile(const char
extern "C" RENDERDOC_API void RENDERDOC_CC RENDERDOC_LogText(const char *text)
{
rdclog_int(LogType::Comment, "EXT", "external", 0, "%s", text);
rdclog_direct(Timing::GetUTCTime(), Process::GetCurrentPID(), LogType::Comment, "EXT", "external",
0, "%s", text);
}
extern "C" RENDERDOC_API void RENDERDOC_CC RENDERDOC_LogMessage(LogType type, const char *project,
const char *file, unsigned int line,
const char *text)
{
rdclog_int(type, project ? project : "UNK?", file ? file : "unknown", line, "%s", text);
rdclog_direct(Timing::GetUTCTime(), Process::GetCurrentPID(), type, project ? project : "UNK?",
file ? file : "unknown", line, "%s", text);
#if ENABLED(DEBUGBREAK_ON_ERROR_LOG)
if(type == LogType::Error)