diff --git a/indra/llcommon/llerror.cpp b/indra/llcommon/llerror.cpp index a9c4380a1..73ec354bc 100644 --- a/indra/llcommon/llerror.cpp +++ b/indra/llcommon/llerror.cpp @@ -46,6 +46,7 @@ # include #endif // !LL_WINDOWS #include +#include #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) { diff --git a/indra/llcommon/llprocesslauncher.cpp b/indra/llcommon/llprocesslauncher.cpp index e27aaa3c5..ee120fc94 100644 --- a/indra/llcommon/llprocesslauncher.cpp +++ b/indra/llcommon/llprocesslauncher.cpp @@ -32,7 +32,11 @@ #include "linden_common.h" +#include +#include +#include #include "llprocesslauncher.h" +#include "aiaprpool.h" #include #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(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 diff --git a/indra/llplugin/llpluginclassmedia.cpp b/indra/llplugin/llpluginclassmedia.cpp index 2bbad6011..c8b903e58 100644 --- a/indra/llplugin/llpluginclassmedia.cpp +++ b/indra/llplugin/llpluginclassmedia.cpp @@ -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 << ", " diff --git a/indra/llplugin/llpluginmessage.h b/indra/llplugin/llpluginmessage.h index 3c7b91750..7bc4ea12d 100644 --- a/indra/llplugin/llpluginmessage.h +++ b/indra/llplugin/llpluginmessage.h @@ -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; } diff --git a/indra/llplugin/llpluginprocesschild.cpp b/indra/llplugin/llpluginprocesschild.cpp index f844c5a2b..3ba765bf6 100644 --- a/indra/llplugin/llpluginprocesschild.cpp +++ b/indra/llplugin/llpluginprocesschild.cpp @@ -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; } diff --git a/indra/llplugin/llpluginprocessparent.cpp b/indra/llplugin/llpluginprocessparent.cpp index df2f0b512..fc94ee849 100644 --- a/indra/llplugin/llpluginprocessparent.cpp +++ b/indra/llplugin/llpluginprocessparent.cpp @@ -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")< ShaderLoading Openjpeg + + Plugin + Plugin child + + PluginRaw child + + + + diff --git a/indra/newview/llviewermedia.cpp b/indra/newview/llviewermedia.cpp index ca21f6d0c..ced145d34 100644 --- a/indra/newview/llviewermedia.cpp +++ b/indra/newview/llviewermedia.cpp @@ -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 { diff --git a/indra/newview/statemachine/aifilepicker.cpp b/indra/newview/statemachine/aifilepicker.cpp index 35d875dfd..33ef0c16c 100644 --- a/indra/newview/statemachine/aifilepicker.cpp +++ b/indra/newview/statemachine/aifilepicker.cpp @@ -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) diff --git a/indra/newview/statemachine/aifilepicker.h b/indra/newview/statemachine/aifilepicker.h index fd5bd0cc2..b1caf4701 100644 --- a/indra/newview/statemachine/aifilepicker.h +++ b/indra/newview/statemachine/aifilepicker.h @@ -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"; } diff --git a/indra/plugins/base_basic/basic_plugin_base.cpp b/indra/plugins/base_basic/basic_plugin_base.cpp index d7d486502..f791b5887 100755 --- a/indra/plugins/base_basic/basic_plugin_base.cpp +++ b/indra/plugins/base_basic/basic_plugin_base.cpp @@ -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. * diff --git a/indra/plugins/base_basic/basic_plugin_base.h b/indra/plugins/base_basic/basic_plugin_base.h index f615fce87..492b408e7 100755 --- a/indra/plugins/base_basic/basic_plugin_base.h +++ b/indra/plugins/base_basic/basic_plugin_base.h @@ -38,6 +38,8 @@ #include +#include + #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 diff --git a/indra/plugins/filepicker/basic_plugin_filepicker.cpp b/indra/plugins/filepicker/basic_plugin_filepicker.cpp index 498dff3f1..b30131479 100644 --- a/indra/plugins/filepicker/basic_plugin_filepicker.cpp +++ b/indra/plugins/filepicker/basic_plugin_filepicker.cpp @@ -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; diff --git a/indra/plugins/filepicker/llfilepicker.cpp b/indra/plugins/filepicker/llfilepicker.cpp index 1b54265ff..b9c616195 100644 --- a/indra/plugins/filepicker/llfilepicker.cpp +++ b/indra/plugins/filepicker/llfilepicker.cpp @@ -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; } }