2025-07-18 09:14 CEST

View Issue Details Jump to Notes ]
IDProjectCategoryView StatusLast Update
0000408Spring engineGeneralpublic2007-04-04 22:35
ReporterM2 
Assigned Tojcnossen 
PrioritynormalSeveritycrashReproducibilityalways
StatusresolvedResolutionfixed 
Product Version 
Target VersionFixed in Version 
Summary0000408: [patch] Race condition with lua
DescriptionThis patch addresses some problems caused by the current logging design.

The main issue is only caused indirectly by the logger, when it outputs a message it also calls all listening subscribers. One subscriber uses lua and if called from outside the main thread it has a reasonable good chance to run in parallel with some other lua widget from the main thread, and thus crash the game.

The straightforward way of solving this would be to guard all public functions using lua with some locking mechanism. But this would create a lot of locking for the relatively few cases when lua gets used from outside the main thread. So instead all incoming log messages get cached and later invoked from the main thread, thereby avoiding race conditions inside lua.

Additional InformationThis can easily be reproduced by using the luaui and modifying the code to spam log messages from the server thread.
TagsNo tags attached.
Checked infolog.txt for Errors
Attached Files
  • patch file icon logging.patch (7,409 bytes) 2007-02-01 19:23 -
    Index: rts/Game/PreGame.cpp
    ===================================================================
    --- rts/Game/PreGame.cpp	(revision 3368)
    +++ rts/Game/PreGame.cpp	(working copy)
    @@ -109,6 +109,8 @@
     
     CPreGame::~CPreGame()
     {
    +	delete infoConsole;
    +	infoConsole = 0;
     }
     
     int CPreGame::KeyPressed(unsigned short k,bool isRepeat)
    Index: rts/Rendering/glFont.cpp
    ===================================================================
    --- rts/Rendering/glFont.cpp	(revision 3368)
    +++ rts/Rendering/glFont.cpp	(working copy)
    @@ -207,7 +207,7 @@
     			glTexParameteri(GL_TEXTURE_2D, GL_TEXTURE_WRAP_T, GL_CLAMP);
     		}
     		glTexImage2D(GL_TEXTURE_2D, 
    -			0, GL_RGBA, 
    +			0, 2, 
     			texsize, texsize, 0, GL_LUMINANCE_ALPHA, GL_UNSIGNED_BYTE, tex);
     		
     		charWidths[ch - charstart] = g->advance_x / 2 / texsize;		
    Index: rts/System/float3.h
    ===================================================================
    --- rts/System/float3.h	(revision 3368)
    +++ rts/System/float3.h	(working copy)
    @@ -335,14 +335,14 @@
     	}
     
     	/**
    -	 * @brief distance2D between float3s (only x and y)
    +	 * @brief distance2D between float3s (only x and z)
     	 * @param f float3 to compare against
     	 * @return 2D distance between float3s
     	 * 
     	 * Calculates the distance between this float3
     	 * and another float3 2-dimensionally (that is,
    -	 * only using the x and y components).  Sums the
    -	 * differences in the x and y components, square
    +	 * only using the x and z components).  Sums the
    +	 * differences in the x and z components, square
     	 * root for pythagorean theorem
     	 */
     	inline float distance2D(const float3 &f) const{
    Index: rts/System/LogOutput.cpp
    ===================================================================
    --- rts/System/LogOutput.cpp	(revision 3368)
    +++ rts/System/LogOutput.cpp	(working copy)
    @@ -3,6 +3,7 @@
     #include "LogOutput.h"
     #include <fstream>
     #include <cstdarg>
    +#include <utility>
     #include <boost/thread/recursive_mutex.hpp>
     
     
    @@ -11,27 +12,48 @@
     #endif
     
     static std::ofstream* filelog = 0;
    -static bool initialized = false;
     static bool stdoutDebug = false;
     CLogOutput logOutput;
    -static boost::recursive_mutex tempstrMutex;
    -static std::string tempstr;
    +static boost::recursive_mutex* logMutex = 0;
     
    +typedef std::vector<std::pair<int, std::string> > messages;
    +static messages* logMessages = 0;
    +static messages* outputting = 0;
    +
    +
     static const int bufferSize = 2048;
     
    +
    +
    +CLogOutput::concatString::~concatString(){
    +		logOutput.Print(logMessage.str());
    +}
    +
    +
     CLogOutput::CLogOutput()
     {
     	assert(this == &logOutput);
     	assert(!filelog); // multiple infologs can't exist together!
    +
    +	logMutex = new boost::recursive_mutex;
    +	outputting = new messages;
    +	logMessages = new messages;
     }
     
     CLogOutput::~CLogOutput()
     {
     	End();
    +	delete logMessages;
    +	logMessages = 0;
    +	delete outputting;
    +	outputting = 0;
    +	delete logMutex;
    +	logMutex = 0;
     }
     
     void CLogOutput::End()
     {
    +	OutputMessages();
     	delete filelog;
     	filelog = 0;
     }
    @@ -41,11 +63,28 @@
     	stdoutDebug = value;
     }
     
    +void CLogOutput::OutputMessages(){
    +	boost::recursive_mutex::scoped_lock lock(*logMutex);
    +	std::swap(outputting, logMessages);
    +
    +	messages::iterator it = outputting->begin();
    +	for(;it != outputting->end(); ++it){
    +		Output(it->first, it->second.c_str());
    +	}
    +
    +	outputting->clear();
    +}
    +
    +void CLogOutput::CacheMessage(int priority, const std::string & str){
    +	boost::recursive_mutex::scoped_lock lock(*logMutex);
    +
    +	logMessages->push_back(std::make_pair(priority, str));
    +}
    +
     void CLogOutput::Output(int priority, const char *str)
     {
    -	if (!initialized) {
    +	if (!filelog) {
     		filelog = new std::ofstream("infolog.txt");
    -		initialized = true;
     	}
     
     	// Output to subscribers
    @@ -84,17 +123,24 @@
     
     void CLogOutput::AddSubscriber(ILogSubscriber* ls)
     {
    +	boost::recursive_mutex::scoped_lock lock(*logMutex);
     	subscribers.push_back(ls);
     }
     
     void CLogOutput::RemoveAllSubscribers()
     {
    +	boost::recursive_mutex::scoped_lock lock(*logMutex);
     	subscribers.clear();
     }
     
     void CLogOutput::RemoveSubscriber(ILogSubscriber *ls)
     {
    -	subscribers.erase(std::find(subscribers.begin(),subscribers.end(),ls));
    +	boost::recursive_mutex::scoped_lock lock(*logMutex);
    +
    +	std::vector<ILogSubscriber*>::iterator subscriber = std::find(subscribers.begin(),subscribers.end(),ls);
    +	if(subscriber != subscribers.end()){
    +		subscribers.erase(subscriber);
    +	}
     }
     
     // ----------------------------------------------------------------------
    @@ -110,7 +156,7 @@
     	VSNPRINTF(text, sizeof(text), fmt, ap);
     	va_end(ap);
     
    -	Output (priority,text);
    +	CacheMessage(priority,text);
     }
     
     void CLogOutput::Print(const char *fmt, ...)
    @@ -122,51 +168,16 @@
     	VSNPRINTF(text, sizeof(text), fmt, ap);
     	va_end(ap);
     
    -	Output(0, text);
    +	CacheMessage(0, text);
     }
     
     void CLogOutput::Print(const std::string& text)
     {
    -	Output(0, text.c_str());
    +	CacheMessage(0, text);
     }
     
     
     void CLogOutput::Print(int priority, const std::string& text)
     {
    -	Output(priority, text.c_str());
    +	CacheMessage(priority, text);
     }
    -
    -
    -CLogOutput& CLogOutput::operator<< (int i)
    -{
    -	char t[50];
    -	sprintf(t,"%d ",i);
    -	boost::recursive_mutex::scoped_lock scoped_lock(tempstrMutex);
    -	tempstr += t;
    -	return *this;
    -}
    -
    -
    -CLogOutput& CLogOutput::operator<< (float f)
    -{
    -	char t[50];
    -	sprintf(t,"%f ",f);
    -	boost::recursive_mutex::scoped_lock scoped_lock(tempstrMutex);
    -	tempstr += t;
    -	return *this;
    -}
    -
    -CLogOutput& CLogOutput::operator<< (const char* c)
    -{
    -	boost::recursive_mutex::scoped_lock scoped_lock(tempstrMutex);
    -
    -	for(int a=0;c[a];a++) {
    -		if (c[a] == '\n') {
    -			Output(0, tempstr.c_str());
    -			tempstr.clear();
    -			break;
    -		} else 
    -			tempstr += c[a];
    -	}
    -	return *this;
    -}
    Index: rts/System/LogOutput.h
    ===================================================================
    --- rts/System/LogOutput.h	(revision 3368)
    +++ rts/System/LogOutput.h	(working copy)
    @@ -6,6 +6,8 @@
     #ifndef LOGOUTPUT_H
     #define LOGOUTPUT_H
     
    +#include <sstream>
    +
     // format string error checking 
     #ifdef __GNUC__
     #define FORMATSTRING(n) __attribute__((format(printf, n, n + 1)))
    @@ -34,10 +36,33 @@
     	void Print(const std::string& text);
     	void Print(int priority, const std::string& text);
     
    -	CLogOutput& operator<<(int i);
    -	CLogOutput& operator<<(float f);
    -	CLogOutput& operator<<(const char* c);
     
    +private:
    +	struct concatString{
    +		template<typename T>
    +		concatString(const T & msg){
    +			logMessage<<msg;
    +		}
    +
    +		~concatString();
    +
    +		template<typename T>
    +		concatString& operator<<(const T & msg){
    +			logMessage<<msg;
    +			return *this;
    +		}
    +
    +	private:
    +		std::stringstream logMessage;
    +	};
    +
    +public:
    +	template<typename T>
    +	concatString operator<<(const T & msg){
    +		return concatString(msg);
    +	}
    +
    +
     	void SetLastMsgPos(float3 pos);
     
     	// In case the InfoConsole and other in game subscribers 
    @@ -51,7 +76,10 @@
     	
     	void SetMirrorToStdout(bool);
     
    +	void OutputMessages();
    +
     protected:
    +	void CacheMessage(int priority, const std::string & str);
     	void Output(int priority, const char *str);
     
     	std::vector<ILogSubscriber*> subscribers;
    Index: rts/System/Main.cpp
    ===================================================================
    --- rts/System/Main.cpp	(revision 3368)
    +++ rts/System/Main.cpp	(working copy)
    @@ -813,6 +813,8 @@
     		else ret = activeController->Draw();
     	}
     
    +	logOutput.OutputMessages();
    +
     #ifndef WIN32
     	if (vsyncFrames > 0) {
     		if (!GLXEW_SGI_video_sync) {
    
    patch file icon logging.patch (7,409 bytes) 2007-02-01 19:23 +

-Relationships
+Relationships

-Notes

~0000680

tvo (reporter)

forgot to attach the patch?

~0000688

trepan (reporter)

Thanks for finding this M2.
Fixed, with enhancements in SVN (r3373).

~0000689

M2 (reporter)

I apparently forgot to attach the patch to my original report and now you have fixed it, but you should still take a look at the patch because it also resolves some other small bugs.

~0000690

trepan (reporter)

The LuaUI related bug is fixed, re-assigned to jc.

~0000864

tvo (reporter)

AFAICS all chunks have been committed one way or another.

Thanks for your contribution anyway.
+Notes

-Issue History
Date Modified Username Field Change
2007-01-31 00:15 M2 New Issue
2007-01-31 22:35 tvo Note Added: 0000680
2007-02-01 00:05 trepan Assigned To => trepan
2007-02-01 00:05 trepan Status new => assigned
2007-02-01 17:35 trepan Note Added: 0000688
2007-02-01 17:35 trepan Status assigned => resolved
2007-02-01 17:35 trepan Resolution open => fixed
2007-02-01 19:23 M2 Status resolved => feedback
2007-02-01 19:23 M2 Resolution fixed => reopened
2007-02-01 19:23 M2 Note Added: 0000689
2007-02-01 19:23 M2 File Added: logging.patch
2007-02-01 19:50 trepan Note Added: 0000690
2007-02-01 19:50 trepan Assigned To trepan => jcnossen
2007-04-04 22:35 tvo Status feedback => resolved
2007-04-04 22:35 tvo Resolution reopened => fixed
2007-04-04 22:35 tvo Note Added: 0000864
+Issue History