Singularity-Viewer/SingularityViewer
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

Add more support for debugging plugins.

Browse Source 
Added support for plugin debug messages and better error reporting
when something goes wrong during start up of SLPlugin.

Also added more debug output regarding general plugin messages
as well as debug output related to AIFilePicker.
This commit is contained in:
Aleric Inglewood
2011-05-08 15:31:51 +02:00
parent 80bbf5d083
commit 75ff0fc04d
14 changed files with 330 additions and 38 deletions
Download Patch File Download Diff File Expand all files Collapse all files

54
indra/llcommon/llerror.cpp
View File

@@ -46,6 +46,7 @@
# include <unistd.h>
#endif // !LL_WINDOWS
#include <vector>
#include <cstring>
#include "llapp.h"
#include "llapr.h"
@@ -1076,28 +1077,49 @@ namespace LLError
switch (site.mLevel)
{
case LEVEL_DEBUG: prefix << "DEBUG: "; break;
case LEVEL_INFO: prefix << "INFO: "; break;
case LEVEL_WARN: prefix << "WARNING: "; break;
case LEVEL_ERROR: prefix << "ERROR: "; break;
default: prefix << "XXX: "; break;
case LEVEL_DEBUG: prefix << "DEBUG"; break;
case LEVEL_INFO: prefix << "INFO"; break;
case LEVEL_WARN: prefix << "WARNING"; break;
case LEVEL_ERROR: prefix << "ERROR"; break;
default: prefix << "XXX"; break;
};
if (settings_w->printLocation)
bool need_function = true;
if (site.mBroadTag && *site.mBroadTag != '\0')
{
prefix << abbreviateFile(site.mFile)
<< "(" << site.mLine << ") : ";
prefix << "(\"" << site.mBroadTag << "\")";
#if LL_DEBUG
// Suppress printing mFunction if mBroadTag is set, starts with
// "Plugin " and ends with "child": a debug message from a plugin.
size_t taglen = strlen(site.mBroadTag);
if (taglen >= 12 && strncmp(site.mBroadTag, "Plugin ", 7) == 0 &&
strcmp(site.mBroadTag + taglen - 5, "child") == 0)
{
need_function = false;
}
#endif
}
prefix << ": ";
#if LL_WINDOWS
// DevStudio: __FUNCTION__ already includes the full class name
#else
if (site.mClassInfo != typeid(NoClassInfo))
if (need_function)
{
prefix << className(site.mClassInfo) << "::";
if (settings_w->printLocation)
{
prefix << abbreviateFile(site.mFile)
<< "(" << site.mLine << ") : ";
}
#if LL_WINDOWS
// DevStudio: __FUNCTION__ already includes the full class name
#else
if (need_function && site.mClassInfo != typeid(NoClassInfo))
{
prefix << className(site.mClassInfo) << "::";
}
#endif
prefix << site.mFunction << ": ";
}
#endif
prefix << site.mFunction << ": ";
if (site.mPrintOnce)
{

179
indra/llcommon/llprocesslauncher.cpp
View File

@@ -32,7 +32,11 @@
#include "linden_common.h"
#include <cassert>
#include <apr_file_io.h>
#include <apr_thread_proc.h>
#include "llprocesslauncher.h"
#include "aiaprpool.h"
#include <iostream>
#if LL_DARWIN || LL_LINUX
@@ -142,6 +146,7 @@ bool LLProcessLauncher::isRunning(void)
return (mProcessHandle != 0);
}
bool LLProcessLauncher::kill(void)
{
bool result = true;
@@ -201,6 +206,79 @@ static bool reap_pid(pid_t pid)
return result;
}
#if LL_DEBUG
// Define this to create a temporary pipe(2) between parent and child process, so
// that the child process can report error messages that it encounters when
// trying to execve(2). Most notably failing to start due to missing libraries
// or undefined symbols.
#define DEBUG_PIPE_CHILD_ERROR_REPORTING 1
#endif
#ifdef DEBUG_PIPE_CHILD_ERROR_REPORTING
// Called by child process.
static void write_pipe(apr_file_t* out, char const* message)
{
apr_size_t const bytes_to_write = strlen(message) + 1; // +1 for the length byte.
assert(bytes_to_write < 256);
char buf[256];
strncpy(buf + 1, message, sizeof(buf) - 1);
*reinterpret_cast<unsigned char*>(buf) = bytes_to_write - 1;
apr_size_t bytes_written;
apr_status_t status = apr_file_write_full(out, buf, bytes_to_write, &bytes_written);
if (status != APR_SUCCESS)
{
std::cerr << "apr_file_write_full: " << apr_strerror(status, buf, sizeof(buf)) << std::endl;
}
else if (bytes_written != bytes_to_write)
{
std::cerr << "apr_file_write_full: bytes_written (" << bytes_written << ") != bytes_to_write (" << bytes_to_write << ")!" << std::endl;
}
status = apr_file_flush(out);
if (status != APR_SUCCESS)
{
std::cerr << "apr_file_flush: " << apr_strerror(status, buf, sizeof(buf)) << std::endl;
}
#ifdef _DEBUG
std::cerr << "apr_file_write_full: Wrote " << bytes_written << " bytes to the pipe." << std::endl;
#endif
}
// Called by parent process.
static std::string read_pipe(apr_file_t* in, bool timeout_ok = false)
{
char buf[256];
unsigned char bytes_to_read;
apr_size_t bytes_read;
apr_status_t status = apr_file_read_full(in, &bytes_to_read, 1, &bytes_read);
if (status != APR_SUCCESS)
{
if (APR_STATUS_IS_TIMEUP(status) && timeout_ok)
{
return "TIMEOUT";
}
llwarns << "apr_file_read_full: " << apr_strerror(status, buf, sizeof(buf)) << llendl;
assert(APR_STATUS_IS_EOF(status));
return "END OF FILE";
}
assert(bytes_read == 1);
status = apr_file_read_full(in, buf, bytes_to_read, &bytes_read);
if (status != APR_SUCCESS)
{
llwarns << "apr_file_read_full: " << apr_strerror(status, buf, sizeof(buf)) << llendl;
assert(status == APR_SUCCESS); // Fail
}
assert(bytes_read == bytes_to_read);
std::string received(buf, bytes_read);
llinfos << "Received: \"" << received << "\" (bytes read: " << bytes_read << ")" << llendl;
return received;
}
#endif // DEBUG_PIPE_CHILD_ERROR_REPORTING
int LLProcessLauncher::launch(void)
{
// If there was already a process associated with this object, kill it.
@@ -237,23 +315,96 @@ int LLProcessLauncher::launch(void)
}
}
// flush all buffers before the child inherits them
::fflush(NULL);
pid_t id = vfork();
if(id == 0)
pid_t id;
{
// child process
::execv(mExecutable.c_str(), (char * const *)fake_argv);
// If we reach this point, the exec failed.
// Use _exit() instead of exit() per the vfork man page.
_exit(0);
#ifdef DEBUG_PIPE_CHILD_ERROR_REPORTING
// Set up a pipe to the child process for error reporting.
apr_file_t* in;
apr_file_t* out;
AIAPRPool pool;
pool.create();
apr_status_t status = apr_file_pipe_create_ex(&in, &out, APR_FULL_BLOCK, pool());
assert(status == APR_SUCCESS);
bool success = (status == APR_SUCCESS);
if (success)
{
apr_interval_time_t const timeout = 10000000; // 10 seconds.
status = apr_file_pipe_timeout_set(in, timeout);
assert(status == APR_SUCCESS);
success = (status == APR_SUCCESS);
}
#endif // DEBUG_PIPE_CHILD_ERROR_REPORTING
// flush all buffers before the child inherits them
::fflush(NULL);
id = vfork();
if (id == 0)
{
// child process
#ifdef DEBUG_PIPE_CHILD_ERROR_REPORTING
// Tell parent process we're about to call execv.
write_pipe(out, "CALLING EXECV");
#ifdef _DEBUG
char const* display = getenv("DISPLAY");
std::cerr << "Calling ::execv(\"" << mExecutable << '"';
for(int j = 0; j < i; ++j)
std::cerr << ", \"" << fake_argv[j] << '"';
std::cerr << ") with DISPLAY=\"" << (display ? display : "NULL") << '"' << std::endl;
#endif
#endif // DEBUG_PIPE_CHILD_ERROR_REPORTING
::execv(mExecutable.c_str(), (char * const *)fake_argv);
#ifdef DEBUG_PIPE_CHILD_ERROR_REPORTING
status = APR_FROM_OS_ERROR(apr_get_os_error());
char message[256];
char errbuf[128];
apr_strerror(status, errbuf, sizeof(errbuf));
snprintf(message, sizeof(message), "Child process: execv: %s: %s", mExecutable.c_str(), errbuf);
write_pipe(out, message);
#ifdef _DEBUG
std::cerr << "::execv() failed." << std::endl;
#endif
#endif // DEBUG_PIPE_CHILD_ERROR_REPORTING
// If we reach this point, the exec failed.
// Use _exit() instead of exit() per the vfork man page.
_exit(0);
}
// parent process
#ifdef DEBUG_PIPE_CHILD_ERROR_REPORTING
// Close unused pipe end.
apr_file_close(out);
if (success)
{
// Attempt to do error reporting.
std::string message = read_pipe(in);
success = (message == "CALLING EXECV");
assert(success);
if (success)
{
status = apr_file_pipe_timeout_set(in, 2000000); // Only wait 2 seconds.
message = read_pipe(in, true);
if (message != "TIMEOUT" && message != "END OF FILE")
{
// Most likely execv failed.
llwarns << message << llendl;
assert(false); // Fail in debug mode.
}
}
}
// Clean up.
apr_file_close(in);
#endif // DEBUG_PIPE_CHILD_ERROR_REPORTING
}
// parent process
if(current_wd >= 0)
{
// restore the previous working directory

2
indra/llplugin/llpluginclassmedia.cpp
View File

@@ -674,7 +674,7 @@ void LLPluginClassMedia::receivePluginMessage(const LLPluginMessage &message)
mDirtyRect.unionWith(newDirtyRect);
}
LL_DEBUGS("Plugin") << "adjusted incoming rect is: ("
LL_DEBUGS("PluginUpdated") << "adjusted incoming rect is: ("
<< newDirtyRect.mLeft << ", "
<< newDirtyRect.mTop << ", "
<< newDirtyRect.mRight << ", "

7
indra/llplugin/llpluginmessage.h
View File

@@ -100,6 +100,13 @@ public:
// Returns -1 on failure, otherwise returns the number of key/value pairs in the message.
int parse(const std::string &message);
enum LLPLUGIN_LOG_LEVEL {
LOG_LEVEL_DEBUG,
LOG_LEVEL_INFO,
LOG_LEVEL_WARN,
LOG_LEVEL_ERR,
};
// For debugging purposes.
friend std::ostream& operator<<(std::ostream& os, LLPluginMessage const& message) { return os << message.mMessage; }

1
indra/llplugin/llpluginprocesschild.cpp
View File

@@ -227,6 +227,7 @@ void LLPluginProcessChild::idle(void)
case STATE_DONE:
// just sit here.
LL_WARNS("Plugin") << "Calling LLPluginProcessChild::idle while in STATE_DONE!" << LL_ENDL;
break;
}

40
indra/llplugin/llpluginprocessparent.cpp
View File

@@ -598,7 +598,16 @@ void LLPluginProcessParent::sendMessage(const LLPluginMessage &message)
}
std::string buffer = message.generate();
LL_DEBUGS("Plugin") << "Sending: " << buffer << LL_ENDL;
#if LL_DEBUG
if (message.getName() == "mouse_event")
{
LL_DEBUGS("PluginMouseEvent") << "Sending: " << buffer << LL_ENDL;
}
else
{
LL_DEBUGS("Plugin") << "Sending: " << buffer << LL_ENDL;
}
#endif
writeMessageRaw(buffer);
// Try to send message immediately.
@@ -876,7 +885,7 @@ void LLPluginProcessParent::servicePoll()
// It parses the message and passes it on to LLPluginProcessParent::receiveMessage.
void LLPluginProcessParent::receiveMessageRaw(const std::string &message)
{
LL_DEBUGS("Plugin") << "Received: " << message << LL_ENDL;
LL_DEBUGS("PluginRaw") << "Received: " << message << LL_ENDL;
LLPluginMessage parsed;
if(parsed.parse(message) != -1)
@@ -998,8 +1007,7 @@ void LLPluginProcessParent::receiveMessage(const LLPluginMessage &message)
mCPUUsage = message.getValueReal("cpu_usage");
LL_DEBUGS("Plugin") << "cpu usage reported as " << mCPUUsage << LL_ENDL;
LL_DEBUGS("PluginHeartbeat") << "cpu usage reported as " << mCPUUsage << LL_ENDL;
}
else if(message_name == "shutdown")
{
@@ -1024,6 +1032,30 @@ void LLPluginProcessParent::receiveMessage(const LLPluginMessage &message)
mSharedMemoryRegions.erase(iter);
}
}
else if(message_name == "log_message")
{
std::string msg=message.getValue("message");
S32 level=message.getValueS32("log_level");
switch(level)
{
case LLPluginMessage::LOG_LEVEL_DEBUG:
LL_DEBUGS("Plugin child")<<msg<<LL_ENDL;
break;
case LLPluginMessage::LOG_LEVEL_INFO:
LL_INFOS("Plugin child")<<msg<<LL_ENDL;
break;
case LLPluginMessage::LOG_LEVEL_WARN:
LL_WARNS("Plugin child")<<msg<<LL_ENDL;
break;
case LLPluginMessage::LOG_LEVEL_ERR:
LL_ERRS("Plugin child")<<msg<<LL_ENDL;
break;
default:
break;
}
}
else
{
LL_WARNS("Plugin") << "Unknown internal message from child: " << message_name << LL_ENDL;

9
indra/newview/app_settings/logcontrol.xml
View File

@@ -42,6 +42,15 @@
<array>
<string>ShaderLoading</string>
<string>Openjpeg</string>
<!-- Debug output about messages received from plugins: -->
<string>Plugin</string> <!-- Everything except what is listed below -->
<string>Plugin child</string> <!-- Plugin log messages from the plugin child process -->
<!--<string>PluginRaw</string>--> <!-- The raw LLSD data -->
<string>PluginRaw child</string> <!-- The raw LLSD data from the plugin child process -->
<!--<string>PluginHeartbeat</string>--> <!-- One second interval CPU usage reports -->
<!--<string>PluginUpdated</string>--> <!-- The mouse "updated" message -->
<!-- Debug output about messages sent to plugins: -->
<!--<string>PluginMouseEvent</string>--> <!-- Mouse event data sent to plugins -->
</array>
</map>
</array>

2
indra/newview/llviewermedia.cpp
View File

@@ -399,10 +399,12 @@ LLPluginClassMedia* LLViewerMediaImpl::newSourceFromMediaType(std::string media_
if(LLFile::stat(launcher_name, &s))
{
LL_WARNS("Media") << "Couldn't find launcher at " << launcher_name << LL_ENDL;
llassert(false); // Fail in debugging mode.
}
else if(LLFile::stat(plugin_name, &s))
{
LL_WARNS("Media") << "Couldn't find plugin at " << plugin_name << LL_ENDL;
llassert(false); // Fail in debugging mode.
}
else
{

2
indra/newview/statemachine/aifilepicker.cpp
View File

@@ -338,10 +338,12 @@ void AIFilePicker::receivePluginMessage(const LLPluginMessage &message)
std::string message_name = message.getName();
if (message_name == "canceled")
{
LL_DEBUGS("Plugin") << "received message \"canceled\"" << LL_ENDL;
set_state(AIFilePicker_canceled);
}
else if (message_name == "done")
{
LL_DEBUGS("Plugin") << "received message \"done\"" << LL_ENDL;
LLSD filenames = message.getValueLLSD("filenames");
mFilenames.clear();
for(LLSD::array_iterator filename = filenames.beginArray(); filename != filenames.endArray(); ++filename)

4
indra/newview/statemachine/aifilepicker.h
View File

@@ -175,6 +175,9 @@ private:
std::string get_folder(std::string const& default_path, std::string const& context);
protected:
// Call deleteMe(), not delete.
/*virtual*/ ~AIFilePicker() { LL_DEBUGS("Plugin") << "Calling AIFilePicker::~AIFilePicker()" << LL_ENDL; }
// Handle initializing the object.
/*virtual*/ void initialize_impl(void);
@@ -197,6 +200,7 @@ class AIPluginFilePicker : public LLPluginClassBasic {
LOG_CLASS(AIPluginFilePicker);
public:
AIPluginFilePicker(AIFilePicker* state_machine) : mStateMachine(state_machine) { }
/*virtual*/ ~AIPluginFilePicker() { LL_DEBUGS("Plugin") << "Calling AIPluginFilePicker::~AIPluginFilePicker()" << LL_ENDL; }
static std::string launcher_name(void) { return gDirUtilp->getLLPluginLauncher(); }
static char const* plugin_basename(void) { return "basic_plugin_filepicker"; }

21
indra/plugins/base_basic/basic_plugin_base.cpp
View File

@@ -41,6 +41,9 @@
// TODO: Make sure that the only symbol exported from this library is LLPluginInitEntryPoint
// Used for logging.
BasicPluginBase* BasicPluginBase::sPluginBase;
////////////////////////////////////////////////////////////////////////////////
/// Basic plugin constructor.
///
@@ -49,6 +52,8 @@
BasicPluginBase::BasicPluginBase(LLPluginInstance::sendMessageFunction send_message_function, LLPluginInstance* plugin_instance) :
mPluginInstance(plugin_instance), mSendMessageFunction(send_message_function), mDeleteMe(false)
{
llassert(!sPluginBase);
sPluginBase = this;
}
/**
@@ -93,9 +98,25 @@ void BasicPluginBase::staticReceiveMessage(char const* message_string, BasicPlug
void BasicPluginBase::sendMessage(const LLPluginMessage &message)
{
std::string output = message.generate();
PLS_DEBUGS << "BasicPluginBase::sendMessage: Sending: " << output << PLS_ENDL;
mSendMessageFunction(output.c_str(), &mPluginInstance);
}
/**
* Send debug log message to plugin loader shell.
*
* @param[in] message Log message being sent to plugin loader shell
* @param[in] level Log message level, enum of LLPluginMessage::LLPLUGIN_LOG_LEVEL
*
*/
void BasicPluginBase::sendLogMessage(std::string const& message, LLPluginMessage::LLPLUGIN_LOG_LEVEL level)
{
LLPluginMessage logmessage(LLPLUGIN_MESSAGE_CLASS_INTERNAL, "log_message");
logmessage.setValue("message", message);
logmessage.setValueS32("log_level",level);
mSendMessageFunction(logmessage.generate().c_str(), &mPluginInstance);
}
/**
* Send shutdown message to the plugin loader shell.
*

43
indra/plugins/base_basic/basic_plugin_base.h
View File

@@ -38,6 +38,8 @@
#include <sstream>
#include <sstream>
#include "linden_common.h"
#include "llplugininstance.h"
@@ -49,7 +51,7 @@ class BasicPluginBase
public:
BasicPluginBase(LLPluginInstance::sendMessageFunction send_message_function, LLPluginInstance* plugin_instance);
//! Basic plugin destructor.
virtual ~BasicPluginBase() {}
virtual ~BasicPluginBase() { sPluginBase = NULL; }
//! Handle received message from plugin loader shell.
virtual void receiveMessage(char const* message_string) = 0;
@@ -57,6 +59,12 @@ public:
// This function is actually called and then calls the member function above.
static void staticReceiveMessage(char const* message_string, BasicPluginBase** self_ptr);
// Pointer to self used for logging (this object should be a singleton).
static BasicPluginBase* sPluginBase;
// Used for log messages. Use macros below.
void sendLogMessage(std::string const& message, LLPluginMessage::LLPLUGIN_LOG_LEVEL level);
// Shoot down the whole process.
void sendShutdownMessage(void);
@@ -87,5 +95,38 @@ int create_plugin(
LLPluginInstance* plugin_instance,
BasicPluginBase** plugin_object);
#if LL_DEBUG
#define LL_DEBUG_PLUGIN_MESSAGES 1
#else
#define LL_DEBUG_PLUGIN_MESSAGES 0
#endif
/** Convenience macros for calling BasicPluginBase::sendLogMessage.
* To log a message, use one of:
* @code
* PLS_DEBUGS << "Hello debug!" << PLS_ENDL;
* PLS_INFOS << "Hello info!" << PLS_ENDL;
* PLS_WARNS << "Hello warning!" << PLS_ENDL;
* PLS_ERRS << "Hello error!" << PLS_ENDL;
* @endcode
*/
#define PLS_LOG_MESSAGE(level, generate_code) \
do { \
if (generate_code && BasicPluginBase::sPluginBase) \
{ \
LLPluginMessage::LLPLUGIN_LOG_LEVEL _pls_log_msg_level = level;\
std::ostringstream _pls_log_msg_stream; \
_pls_log_msg_stream
#define PLS_ENDL \
LLError::End(); \
BasicPluginBase::sPluginBase->sendLogMessage(_pls_log_msg_stream.str(), _pls_log_msg_level); \
} \
} while(0)
// Only send plugin log messages of level info and lower when compiled with debugging.
#define PLS_DEBUGS PLS_LOG_MESSAGE(LLPluginMessage::LOG_LEVEL_DEBUG, LL_DEBUG_PLUGIN_MESSAGES)
#define PLS_INFOS PLS_LOG_MESSAGE(LLPluginMessage::LOG_LEVEL_INFO, LL_DEBUG_PLUGIN_MESSAGES)
#define PLS_WARNS PLS_LOG_MESSAGE(LLPluginMessage::LOG_LEVEL_WARN, 1)
#define PLS_ERRS PLS_LOG_MESSAGE(LLPluginMessage::LOG_LEVEL_ERR, 1)
#endif // BASIC_PLUGIN_BASE

2
indra/plugins/filepicker/basic_plugin_filepicker.cpp
View File

@@ -140,7 +140,7 @@ void FilepickerPlugin::receiveMessage(char const* message_string)
{
if (message_name == "init")
{
LLPluginMessage message("base", "init_response");
LLPluginMessage message(LLPLUGIN_MESSAGE_CLASS_BASE, "init_response");
LLSD versions = LLSD::emptyMap();
versions[LLPLUGIN_MESSAGE_CLASS_BASE] = LLPLUGIN_MESSAGE_CLASS_BASE_VERSION;
versions[LLPLUGIN_MESSAGE_CLASS_BASIC] = LLPLUGIN_MESSAGE_CLASS_BASIC_VERSION;

2
indra/plugins/filepicker/llfilepicker.cpp
View File

@@ -56,7 +56,7 @@ namespace translation
void add(std::string const& key, std::string const& translation)
{
PLS_INFOS << "Adding translation \"" << key << "\" --> \"" << translation << "\"" << PLS_ENDL;
PLS_DEBUGS << "Adding translation \"" << key << "\" --> \"" << translation << "\"" << PLS_ENDL;
translation_map[key] = translation;
}
}