From 51b21cf1ff5ea45832882bfc8c7ba5e1e6d8cb13 Mon Sep 17 00:00:00 2001 From: Jan Rydzewski Date: Wed, 20 May 2026 16:06:13 +0000 Subject: [PATCH] log: expand each message once before handing it to backends MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit log_t::custom_fatal passed its buffer to ::syslog(LOG_ERR, buffer) as the format argument. By then log_t::fatal had already expanded the caller's format with vsprintf, so any % directives still present in the text — for example from a %s argument holding bytes read from a file — were interpreted a second time by syslog with no further arguments to consume. scenario_t::rdwr reaches this with savegame-controlled data: it formats the persistent-data string with %s into a fatal message. The effect ranges from garbled output to a read of unintended memory; %n could in principle write, though many libc builds reject it in a writable format string. It only applies when compiled with SIMUTRANS_USE_SYSLOG and run with -syslog. The vsyslog branches in pakset/debug/message/warning/error and the matching __android_log_vprint branches concatenate the caller's format into another format string the same way. Every current caller passes a string literal, so these are not known to be reachable, but the shape is easy to misuse later. Each logger now expands (format, ...) once into a cbuffer_t and hands the result to log, tee, syslog and android as a "%s" argument. While here, log_t::fatal's two static buffers become locals so a re-entrant fatal cannot overwrite them, and warning's Android line is labelled "Warning:" instead of "Debug:". --- src/makeobj/CMakeLists.txt | 1 + src/makeobj/Makefile | 1 + src/nettool/CMakeLists.txt | 1 + src/nettool/Makefile | 1 + src/simutrans/sys/simsys.cc | 2 +- src/simutrans/utils/log.cc | 246 +++++++++++------------------------- 6 files changed, 77 insertions(+), 175 deletions(-) diff --git a/src/makeobj/CMakeLists.txt b/src/makeobj/CMakeLists.txt index 6f93e1fa01..f7787dce2f 100644 --- a/src/makeobj/CMakeLists.txt +++ b/src/makeobj/CMakeLists.txt @@ -65,6 +65,7 @@ target_sources(makeobj PRIVATE ../simutrans/simio.cc ../simutrans/simdebug.cc ../simutrans/simmem.cc + ../simutrans/utils/cbuffer.cc ../simutrans/utils/simstring.cc ../simutrans/utils/searchfolder.cc ) diff --git a/src/makeobj/Makefile b/src/makeobj/Makefile index c0dd6817f0..29eef5f37b 100644 --- a/src/makeobj/Makefile +++ b/src/makeobj/Makefile @@ -123,6 +123,7 @@ SHARED_SOURCES += ../simutrans/io/raw_image.cc SHARED_SOURCES += ../simutrans/simio.h SHARED_SOURCES += ../simutrans/simdebug.cc SHARED_SOURCES += ../simutrans/simmem.cc +SHARED_SOURCES += ../simutrans/utils/cbuffer.cc SHARED_SOURCES += ../simutrans/utils/simstring.cc SHARED_SOURCES += ../simutrans/utils/searchfolder.cc VARIANT_SOURCES += ../simutrans/dataobj/tabfile.cc diff --git a/src/nettool/CMakeLists.txt b/src/nettool/CMakeLists.txt index 79a49e3176..5c4fd85f12 100644 --- a/src/nettool/CMakeLists.txt +++ b/src/nettool/CMakeLists.txt @@ -34,6 +34,7 @@ target_sources(nettool PRIVATE ../simutrans/network/network_socket_list.cc ../simutrans/simdebug.cc ../simutrans/simmem.cc + ../simutrans/utils/cbuffer.cc ../simutrans/utils/simstring.cc ../simutrans/utils/fetchopt.cc ../simutrans/utils/sha1.cc diff --git a/src/nettool/Makefile b/src/nettool/Makefile index 4ea444b242..47f00cbb34 100644 --- a/src/nettool/Makefile +++ b/src/nettool/Makefile @@ -81,6 +81,7 @@ SHARED_SOURCES += ../simutrans/network/network_packet.cc SHARED_SOURCES += ../simutrans/network/network_socket_list.cc SHARED_SOURCES += ../simutrans/simdebug.cc SHARED_SOURCES += ../simutrans/simmem.cc +SHARED_SOURCES += ../simutrans/utils/cbuffer.cc SHARED_SOURCES += ../simutrans/utils/simstring.cc SHARED_SOURCES += ../simutrans/utils/fetchopt.cc SHARED_SOURCES += ../simutrans/utils/sha1.cc diff --git a/src/simutrans/sys/simsys.cc b/src/simutrans/sys/simsys.cc index 5e1f66d418..540fd4023d 100644 --- a/src/simutrans/sys/simsys.cc +++ b/src/simutrans/sys/simsys.cc @@ -1382,7 +1382,7 @@ void dr_fatal_notify(char const* const msg) #endif #ifdef __ANDROID__ - dbg->error(__FUNCTION__, msg); + dbg->error(__FUNCTION__, "%s", msg); #endif } diff --git a/src/simutrans/utils/log.cc b/src/simutrans/utils/log.cc index abe852112d..72f137454c 100644 --- a/src/simutrans/utils/log.cc +++ b/src/simutrans/utils/log.cc @@ -13,6 +13,7 @@ #endif #include "log.h" +#include "cbuffer.h" #include "../simdebug.h" #include "../sys/simsys.h" @@ -37,7 +38,6 @@ #ifdef __ANDROID__ # include -# include "cbuffer.h" # define LOG_TAG "com.simutrans" #endif @@ -51,35 +51,21 @@ void log_t::pakset(const char* who, const char* format, ...) if (env_t::pakset_debug) { va_list argptr; va_start(argptr, format); - - if (log) { /* only log when a log */ - fprintf(log, "%s", who); /* is already open */ - vfprintf(log, format, argptr); - fprintf(log, "\n"); - - if (force_flush) { - fflush(log); - } - } + cbuffer_t msg; + msg.vprintf(format, argptr); va_end(argptr); - va_start(argptr, format); - if (tee) { /* only log when a log */ - fprintf(tee, "%s", who); /* is already open */ - vfprintf(tee, format, argptr); - fprintf(tee, "\n"); + if (log) { + fprintf(log, "%s%s\n", who, (const char *)msg); + if (force_flush) fflush(log); + } + if (tee) { + fprintf(tee, "%s%s\n", who, (const char *)msg); } - va_end(argptr); - #ifdef SYSLOG - va_start(argptr, format); if (syslog) { - // Replace with dynamic memory allocation - char buffer[4096]; - sprintf(buffer, "%s%s", who, format); - vsyslog(LOG_INFO, buffer, argptr); + ::syslog(LOG_INFO, "%s%s", who, (const char *)msg); } - va_end(argptr); #endif } #else @@ -97,43 +83,24 @@ void log_t::debug(const char *who, const char *format, ...) if(log_debug && debuglevel >= log_t::LEVEL_DEBUG) { va_list argptr; va_start(argptr, format); - - if( log ) { /* only log when a log */ - fprintf(log ,"Debug: %s:\t",who); /* is already open */ - vfprintf(log, format, argptr); - fprintf(log,"\n"); - - if( force_flush ) { - fflush(log); - } - } + cbuffer_t msg; + msg.vprintf(format, argptr); va_end(argptr); - va_start(argptr, format); - if( tee ) { /* only log when a log */ - fprintf(tee, "Debug: %s:\t",who); /* is already open */ - vfprintf(tee, format, argptr); - fprintf(tee,"\n"); + if (log) { + fprintf(log, "Debug: %s:\t%s\n", who, (const char *)msg); + if (force_flush) fflush(log); + } + if (tee) { + fprintf(tee, "Debug: %s:\t%s\n", who, (const char *)msg); } - va_end(argptr); - #ifdef SYSLOG - va_start( argptr, format ); - if ( syslog ) { - // Replace with dynamic memory allocation - char buffer[4096]; - sprintf( buffer, "Debug: %s\t%s", who, format ); - vsyslog( LOG_DEBUG, buffer, argptr ); + if (syslog) { + ::syslog(LOG_DEBUG, "Debug: %s\t%s", who, (const char *)msg); } - va_end( argptr ); #endif - #ifdef __ANDROID__ - va_start(argptr, format); - cbuffer_t buffer; - buffer.printf("Debug: %s\t%s", who, format); - __android_log_vprint(ANDROID_LOG_DEBUG, LOG_TAG, buffer, argptr); - va_end( argptr ); + __android_log_print(ANDROID_LOG_DEBUG, LOG_TAG, "Debug: %s\t%s", who, (const char *)msg); #endif } } @@ -147,43 +114,24 @@ void log_t::message(const char *who, const char *format, ...) if(debuglevel >= log_t::LEVEL_MSG) { va_list argptr; va_start(argptr, format); - - if( log ) { /* only log when a log */ - fprintf(log ,"Message: %s:\t",who); /* is already open */ - vfprintf(log, format, argptr); - fprintf(log,"\n"); - - if( force_flush ) { - fflush(log); - } - } + cbuffer_t msg; + msg.vprintf(format, argptr); va_end(argptr); - va_start(argptr, format); - if( tee ) { /* only log when a log */ - fprintf(tee, "Message: %s:\t",who); /* is already open */ - vfprintf(tee, format, argptr); - fprintf(tee,"\n"); + if (log) { + fprintf(log, "Message: %s:\t%s\n", who, (const char *)msg); + if (force_flush) fflush(log); + } + if (tee) { + fprintf(tee, "Message: %s:\t%s\n", who, (const char *)msg); } - va_end(argptr); - #ifdef SYSLOG - va_start( argptr, format ); - if ( syslog ) { - // Replace with dynamic memory allocation - char buffer[4096]; - sprintf( buffer, "Message: %s\t%s", who, format ); - vsyslog( LOG_INFO, buffer, argptr ); + if (syslog) { + ::syslog(LOG_INFO, "Message: %s\t%s", who, (const char *)msg); } - va_end( argptr ); #endif - #ifdef __ANDROID__ - va_start(argptr, format); - cbuffer_t buffer; - buffer.printf("Message: %s\t%s", who, format); - __android_log_vprint(ANDROID_LOG_INFO, LOG_TAG, buffer, argptr); - va_end( argptr ); + __android_log_print(ANDROID_LOG_INFO, LOG_TAG, "Message: %s\t%s", who, (const char *)msg); #endif } } @@ -197,43 +145,24 @@ void log_t::warning(const char *who, const char *format, ...) if(debuglevel >= log_t::LEVEL_WARN) { va_list argptr; va_start(argptr, format); - - if( log ) { /* only log when a log */ - fprintf(log ,"Warning: %s:\t",who); /* is already open */ - vfprintf(log, format, argptr); - fprintf(log,"\n"); - - if( force_flush ) { - fflush(log); - } - } + cbuffer_t msg; + msg.vprintf(format, argptr); va_end(argptr); - va_start(argptr, format); - if( tee ) { /* only log when a log */ - fprintf(tee, "Warning: %s:\t",who); /* is already open */ - vfprintf(tee, format, argptr); - fprintf(tee,"\n"); + if (log) { + fprintf(log, "Warning: %s:\t%s\n", who, (const char *)msg); + if (force_flush) fflush(log); + } + if (tee) { + fprintf(tee, "Warning: %s:\t%s\n", who, (const char *)msg); } - va_end(argptr); - #ifdef SYSLOG - va_start( argptr, format ); - if ( syslog ) { - // Replace with dynamic memory allocation - char buffer[4096]; - sprintf( buffer, "Warning: %s\t%s", who, format ); - vsyslog( LOG_WARNING, buffer, argptr ); + if (syslog) { + ::syslog(LOG_WARNING, "Warning: %s\t%s", who, (const char *)msg); } - va_end( argptr ); #endif - #ifdef __ANDROID__ - va_start(argptr, format); - cbuffer_t buffer; - buffer.printf("Debug: %s\t%s", who, format); - __android_log_vprint(ANDROID_LOG_WARN, LOG_TAG, buffer, argptr); - va_end( argptr ); + __android_log_print(ANDROID_LOG_WARN, LOG_TAG, "Warning: %s\t%s", who, (const char *)msg); #endif } } @@ -247,50 +176,28 @@ void log_t::error(const char *who, const char *format, ...) if(debuglevel >= log_t::LEVEL_ERROR) { va_list argptr; va_start(argptr, format); - - if( log ) { /* only log when a log */ - fprintf(log ,"ERROR: %s:\t",who); /* is already open */ - vfprintf(log, format, argptr); - fprintf(log,"\n"); - - if( force_flush ) { - fflush(log); - } - - fprintf(log ,"For help with this error or to file a bug report please see the Simutrans forum:\n"); - fprintf(log ,"https://forum.simutrans.com\n"); - } + cbuffer_t msg; + msg.vprintf(format, argptr); va_end(argptr); - va_start(argptr, format); - if( tee ) { /* only log when a log */ - fprintf(tee, "ERROR: %s:\t",who); /* is already open */ - vfprintf(tee, format, argptr); - fprintf(tee,"\n"); + static const char forum_hint[] = + "For help with this error or to file a bug report please see the Simutrans forum:\n" + "https://forum.simutrans.com\n"; - fprintf(tee ,"For help with this error or to file a bug report please see the Simutrans forum:\n"); - fprintf(tee ,"https://forum.simutrans.com\n"); + if (log) { + fprintf(log, "ERROR: %s:\t%s\n%s", who, (const char *)msg, forum_hint); + if (force_flush) fflush(log); + } + if (tee) { + fprintf(tee, "ERROR: %s:\t%s\n%s", who, (const char *)msg, forum_hint); } - va_end(argptr); - #ifdef SYSLOG - va_start( argptr, format ); - if ( syslog ) { - - // Replace with dynamic memory allocation - char buffer[4096]; - sprintf( buffer, "ERROR: %s\t%s", who, format ); - vsyslog( LOG_ERR, buffer, argptr ); + if (syslog) { + ::syslog(LOG_ERR, "ERROR: %s\t%s", who, (const char *)msg); } - va_end( argptr ); #endif - #ifdef __ANDROID__ - va_start(argptr, format); - cbuffer_t buffer; - buffer.printf("ERROR: %s\t%s", who, format); - __android_log_vprint(ANDROID_LOG_ERROR, LOG_TAG, buffer, argptr); - va_end( argptr ); + __android_log_print(ANDROID_LOG_ERROR, LOG_TAG, "ERROR: %s\t%s", who, (const char *)msg); #endif } } @@ -303,19 +210,18 @@ void log_t::fatal(const char* who, const char* format, ...) { va_list argptr; va_start(argptr, format); + cbuffer_t msg; + msg.vprintf(format, argptr); + va_end(argptr); - static char formatbuffer[512]; - sprintf(formatbuffer, + char buffer[8192]; + snprintf(buffer, sizeof(buffer), "FATAL ERROR: %s - %s\n" "Aborting program execution ...\n" "\n" "For help with this error or to file a bug report please see the Simutrans forum at\n" "https://forum.simutrans.com\n", - who, format); - - static char buffer[8192]; - vsprintf(buffer, formatbuffer, argptr); - va_end(argptr); + who, (const char *)msg); custom_fatal(buffer); } @@ -337,7 +243,7 @@ void log_t::custom_fatal(char *buffer) #ifdef SYSLOG if ( syslog ) { - ::syslog( LOG_ERR, buffer ); + ::syslog( LOG_ERR, "%s", buffer ); } #endif @@ -397,24 +303,16 @@ void log_t::custom_fatal(char *buffer) void log_t::vmessage(const char *what, const char *who, const char *format, va_list args ) { if(debuglevel >= LEVEL_ERROR) { - va_list args2; - va_copy(args2, args); + cbuffer_t msg; + msg.vprintf(format, args); - if( log ) { /* only log when a log */ - fprintf(log ,"%s: %s:\t", what, who); /* is already open */ - vfprintf(log, format, args); - fprintf(log,"\n"); - - if( force_flush ) { - fflush(log); - } + if (log) { + fprintf(log, "%s: %s:\t%s\n", what, who, (const char *)msg); + if (force_flush) fflush(log); } - if( tee ) { /* only log when a log */ - fprintf(tee,"%s: %s:\t", what, who); /* is already open */ - vfprintf(tee, format, args2); - fprintf(tee,"\n"); + if (tee) { + fprintf(tee, "%s: %s:\t%s\n", what, who, (const char *)msg); } - va_end(args2); } } @@ -476,7 +374,7 @@ log_t::log_t( const char *logfilename, bool force_flush, bool log_debug, bool lo } #ifdef SYSLOG if ( syslog ) { - ::syslog( LOG_NOTICE, greeting ); + ::syslog( LOG_NOTICE, "%s", greeting ); } #else (void)syslogtag;