Weird `Unhandled exception (St12length_error): basic_string::_M_replace_aux ` error

[illwieckz]

While testing a branch attempting to fix #1611, I get this error:

Warn: Unhandled exception (St12length_error): basic_string::_M_replace_aux 

My branch only modifies GLSL so this my change doesn't cause this bug, this bug is hiding in our current code base.

Unfortunately this exception raises an annoying error popup instead of returning to debugger, so I don't know how to backtrace it.

[slipher]

Unfortunately this exception raises an annoying error popup instead of returning to debugger, so I don't know how to backtrace it.

Configure the debugger to break when length_error is thrown.

[illwieckz]

I commented out the catcher, and got this:

terminate called after throwing an instance of 'std::length_error'
  what():  basic_string::_M_replace_aux

Thread 1 "daemon" received signal SIGABRT, Aborted.

Thread 1 (Thread 0x7c6a465e5b00 (LWP 1863202) "daemon"):
#0  __pthread_kill_implementation (no_tid=0, signo=6, threadid=<optimized out>) at ./nptl/pthread_kill.c:44
#1  __pthread_kill_internal (signo=6, threadid=<optimized out>) at ./nptl/pthread_kill.c:78
#2  __GI___pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ./nptl/pthread_kill.c:89
#3  0x00007c6a5264527e in __GI_raise (sig=sig@entry=6) at ../sysdeps/posix/raise.c:26
#4  0x00007c6a526288ff in __GI_abort () at ./stdlib/abort.c:79
#5  0x00007c6a52aa5ff5 in __gnu_cxx::__verbose_terminate_handler () at ../../../../src/libstdc++-v3/libsupc++/vterminate.cc:95
#6  0x00007c6a52abb0da in __cxxabiv1::__terminate (handler=<optimized out>) at ../../../../src/libstdc++-v3/libsupc++/eh_terminate.cc:48
#7  0x00007c6a52aa5a55 in std::terminate () at ../../../../src/libstdc++-v3/libsupc++/eh_terminate.cc:58
#8  0x00007c6a52abb391 in __cxxabiv1::__cxa_throw (obj=<optimized out>, tinfo=0x7c6a52c6ee88 <typeinfo for std::length_error>, dest=0x7c6a52ad20b0 <std::length_error::~length_error()>) at ../../../../src/libstdc++-v3/libsupc++/eh_throw.cc:98
#9  0x00007c6a52aa92d2 in std::__throw_length_error (__s=__s@entry=0x7c6a52be5ecf "basic_string::_M_replace_aux") at ../../../../../src/libstdc++-v3/src/c++11/functexcept.cc:82
#10 0x00007c6a52b69536 in std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >::_M_check_length (this=<optimized out>, __n1=<optimized out>, __n2=18446744073709551615, __s=0x7c6a52be5ecf "basic_string::_M_replace_aux") at /build/gcc-14-ig5ci0/gcc-14-14.2.0/build/x86_64-linux-gnu/libstdc++-v3/include/bits/basic_string.h:405
#11 std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >::_M_replace_aux (this=<optimized out>, __pos1=<optimized out>, __n1=<optimized out>, __n2=18446744073709551615, __c=<optimized out>) at /build/gcc-14-ig5ci0/gcc-14-14.2.0/build/x86_64-linux-gnu/libstdc++-v3/include/bits/basic_string.tcc:454
#12 0x00005fd40e4bdd2f in GLShaderManager::PrintShaderSource (this=0x5fd40f14dac0 <gl_shaderManager>, programName=..., object=312, infoLog=std::vector of length 13, capacity 16 = {...}) at /src/engine/renderer/gl_shader.cpp:1765
#13 0x00005fd40e4b8b70 in GLShaderManager::BuildShader (this=0x5fd40f14dac0 <gl_shaderManager>, descriptor=0x5fd447e03890) at /src/engine/renderer/gl_shader.cpp:997
#14 0x00005fd40e4b9750 in GLShaderManager::FindShaderProgram (this=0x5fd40f14dac0 <gl_shaderManager>, shaders=std::vector of length 3, capacity 4 = {...}, mainShader="lighttile") at /src/engine/renderer/gl_shader.cpp:1111
#15 0x00005fd40e4b9d6f in GLShaderManager::BuildPermutation (this=0x5fd40f14dac0 <gl_shaderManager>, shader=0x5fd4482eee20, macroIndex=0, deformIndex=0) at /src/engine/renderer/gl_shader.cpp:1170
#16 0x00005fd40e4ba0bb in GLShaderManager::BuildAll (this=0x5fd40f14dac0 <gl_shaderManager>) at /src/engine/renderer/gl_shader.cpp:1201
#17 0x00005fd40e5e4caf in GLSL_FinishGPUShaders () at /src/engine/renderer/tr_shade.cpp:522
#18 0x00005fd40e5acd71 in RE_EndRegistration () at /src/engine/renderer/tr_init.cpp:1633
#19 0x00005fd40e3d5519 in CL_InitCGame () at /src/engine/client/cl_cgame.cpp:640
#20 0x00005fd40e42ccfd in CL_DownloadsComplete () at /src/engine/client/cl_download.cpp:109
#21 0x00005fd40e42d14e in CL_InitDownloads () at /src/engine/client/cl_download.cpp:237
#22 0x00005fd40e446ab8 in CL_ParseGamestate (msg=0x7ffe69a89d60) at /src/engine/client/cl_parse.cpp:460
#23 0x00005fd40e446e21 in CL_ParseServerMessage (msg=0x7ffe69a89d60) at /src/engine/client/cl_parse.cpp:570
#24 0x00005fd40e43a7a7 in CL_PacketEvent (from=..., msg=0x7ffe69a89d60) at /src/engine/client/cl_main.cpp:1945
#25 0x00005fd40e355ccd in Com_EventLoop () at /src/engine/qcommon/common.cpp:429
#26 0x00005fd40e356a94 in Com_Frame () at /src/engine/qcommon/common.cpp:948
#27 0x00005fd40e34e181 in Application::ClientApplication::Frame (this=0x5fd40e8ef920 <Application::GetApp()::app>) at /src/engine/client/ClientApplication.cpp:112
#28 0x00005fd40e6bb86d in Application::Frame () at /src/engine/framework/Application.cpp:87
#29 0x00005fd40e6fe36f in main (argc=52, argv=0x7ffe69a92058) at /src/engine/framework/System.cpp:1012

[illwieckz]

So this is a side effect of me dealing with GLSL, but the bug is in the code printing the GLSL code after a GLSL build error.

[illwieckz]

I reproduce the bug running that illwieckz/unpack branch:

https://github.com/DaemonEngine/Daemon/tree/illwieckz/unpack

On Mesa with this environment:

export MESA_GL_VERSION_OVERRIDE='3.1'
export MESA_GLSL_VERSION_OVERRIDE='140'
export MESA_EXTENSION_OVERRIDE='-GL_ARB_gpu_shader5'

[illwieckz]

@VReaperV you may know what is happening, the crash happens in GLShaderManager::PrintShaderSource().

[illwieckz]

I also noticed that with earlier commits before the one I reproduce the crash with, I got incomplete shader souce printing.

[VReaperV]

@VReaperV you may know what is happening, the crash happens in GLShaderManager::PrintShaderSource().

I'm not sure why it fails on that line... it only does const size_t position = line.find_first_not_of( "\t" );, which returns either a valid position within the string, or std::string::npos.

[VReaperV]

I also noticed that with earlier commits before the one I reproduce the crash with, I got incomplete shader souce printing.

Which commit is that? This also sounds similar to #1491.

[illwieckz]

With my illwieckz/unpack branch, on the commit wip: rewrite unpackUnorm4x8 with explicit typing but without the wip: do explicit typing computeLight commit so it fails building on line 216 of computeLight_fp.glsl as imported by lightMapping_fp.glsl.

See how it says the error is on line 20216 but it eats the log in the middle of the line 20140 to jump straight to the 30020 one:

Warn: Source for shader program lightMapping:
…
20121: 
20122: 		float G = NdotL / (NdotL * ( 1.0 - k ) + k );
20123: 		G *= NdotV / ( NdotV * ( 1.0 - k ) + k );
20124: 
20125: 		vec3 diffuseBRDF = NdotL * diffuseColor.rgb * ( 1.0 - metalness );
20126: 		vec3 specularBRDF = vec3( ( D * F * G ) / max( 4.0 * NdotL * NdotV, 0.0001f ) );
20127: 		color.rgb += ( diffuseBRDF + specularBRDF ) * lightColor.rgb * NdotL;
20128: 		color.a = mix( diffuseColor.a, 1.0, FexpNV );
20129: 
20130: 	#else // !USE_PHYSICAL_MAPPING
20131: 		color.rgb += lightColor.rgb * NdotL * diffuseColor.rgb;
20132: 		#if defined(r_specularMapping)
20133: 			color.rgb += computeSpecularity(lightColor.rgb, materialColor, NdotH);
20134: 		#endif // r_specularMapping
20135: 	#endif // !USE_PHYSICAL_MAPPING
20136: }
20137: #endif // defined(USE_DELUXE_MAPPING) || defined(USE_GRID_DELUXE_MAPPING) || (defined(r_realtimeLighting) && r_realtimeLightingRenderer == 1)
20138: 
20139: #if !defined(USE_DELUXE_MAPPING) && !defined(USE_GRID_DELUXE_MAPPING)
20140: 	void computeLight( in vec3 lightColor, vec4 diffuseColor, inout vec4 color ) {30020: ===========================================================================
30021: */
30022: // reliefMapping_fp.glsl - Relief mapping helper functions
30023: 
30024: #define RELIEFMAPPING_GLSL
30025: 
30026: #if defined(r_normalMapping) || defined(USE_HEIGHTMAP_IN_NORMALMAP)
30027: uniform sampler2D	u_NormalMap;
30028: #endif // r_normalMapping || USE_HEIGHTMAP_IN_NORMALMAP
30029: 
30030: #if defined(r_normalMapping)
30031: uniform vec3        u_NormalScale;
30032: #endif // r_normalMapping
…
Warn: Compile log:
0:20216(16): error: could not implicitly convert operands to arithmetic operator
0:20216(38): error: could not implicitly convert operands to modulus (%) operator
0:20216(32): error: operands to arithmetic operators must be numeric
0:20216(11): error: RHS of operator >> must be an integer or integer vector
0:20216(9): error: LHS of `&' must be an integer
0:20216(2): error: `return' with wrong type error, in function `nextIdx' returning uint
0:20228(7): error: initializer of type int cannot be assigned to variable of type uint
0:20228(23): error: could not implicitly convert operands to relational operator
0:20228(23): error: loop condition must be scalar boolean
0:20229(2): error: initializer of type int cannot be assigned to variable of type uint
0:20232(7): error: initializer of type int cannot be assigned to variable of type uint
0:20232(19): error: could not implicitly convert operands to relational operator
0:20232(19): error: loop condition must be scalar boolean
0:20235(6): error: operands of `==' must have the same type
0:20241(10): error: could not implicitly convert operands to arithmetic operator
0:20241(8): error: operands to arithmetic operators must be numeric
0:20241(8): error: operands to arithmetic operators must be numeric
 
Warn: Unhandled exception (15ShaderException): Couldn't compile fragment shader: lightMapping 

On Mesa I reproduce this with this environment:

export LIBGL_ALWAYS_SOFTWARE=1
export MESA_GL_VERSION_OVERRIDE='3.1'
export MESA_GLSL_VERSION_OVERRIDE='140'
export MESA_EXTENSION_OVERRIDE='-GL_ARB_gpu_shader5'

The LIBGL_ALWAYS_SOFTWARE=1 option forces Mesa to use software rendering, this means I reproduce it with llvmpipe and then it can be reproduced on Windows with software rendering. The error is in the lighting code so better use an higher preset like ultra to make sure the feature triggering the bug is enabled.

[VReaperV]

I guess that code is simply eaten by the driver since we get it back through the api. With the recent changes to shader build system we can just store it in the shader program descriptor, we already assemble it when building the programs to get the checksum.

[illwieckz]

So, right now I got that:

terminate called after throwing an instance of 'std::length_error'
  what():  basic_string::_M_replace_aux

Thread 1 "daemon" received signal SIGABRT, Aborted.

Thread 1 (Thread 0x7693e42beb00 (LWP 2126188) "daemon"):
#0  __pthread_kill_implementation (no_tid=0, signo=6, threadid=<optimized out>) at ./nptl/pthread_kill.c:44
#1  __pthread_kill_internal (signo=6, threadid=<optimized out>) at ./nptl/pthread_kill.c:78
#2  __GI___pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ./nptl/pthread_kill.c:89
#3  0x00007693f024527e in __GI_raise (sig=sig@entry=6) at ../sysdeps/posix/raise.c:26
#4  0x00007693f02288ff in __GI_abort () at ./stdlib/abort.c:79
#5  0x00007693f06a5ff5 in __gnu_cxx::__verbose_terminate_handler () at ../../../../src/libstdc++-v3/libsupc++/vterminate.cc:95
#6  0x00007693f06bb0da in __cxxabiv1::__terminate (handler=<optimized out>) at ../../../../src/libstdc++-v3/libsupc++/eh_terminate.cc:48
#7  0x00007693f06a5a55 in std::terminate () at ../../../../src/libstdc++-v3/libsupc++/eh_terminate.cc:58
#8  0x00007693f06bb391 in __cxxabiv1::__cxa_throw (obj=<optimized out>, tinfo=0x7693f086ee88 <typeinfo for std::length_error>, dest=0x7693f06d20b0 <std::length_error::~length_error()>) at ../../../../src/libstdc++-v3/libsupc++/eh_throw.cc:98
#9  0x00007693f06a92d2 in std::__throw_length_error (__s=__s@entry=0x7693f07e5ecf "basic_string::_M_replace_aux") at ../../../../../src/libstdc++-v3/src/c++11/functexcept.cc:82
#10 0x00007693f0769536 in std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >::_M_check_length (this=<optimized out>, __n1=<optimized out>, __n2=18446744073709551615, __s=0x7693f07e5ecf "basic_string::_M_replace_aux") at /build/gcc-14-ig5ci0/gcc-14-14.2.0/build/x86_64-linux-gnu/libstdc++-v3/include/bits/basic_string.h:405
#11 std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >::_M_replace_aux (this=<optimized out>, __pos1=<optimized out>, __n1=<optimized out>, __n2=18446744073709551615, __c=<optimized out>) at /build/gcc-14-ig5ci0/gcc-14-14.2.0/build/x86_64-linux-gnu/libstdc++-v3/include/bits/basic_string.tcc:454
#12 0x000065065ec32d2f in GLShaderManager::PrintShaderSource (this=0x65065f8c2ac0 <gl_shaderManager>, programName=..., object=430, infoLog=std::vector of length 13, capacity 16 = {...}) at /src/engine/renderer/gl_shader.cpp:1765
#13 0x000065065ec2db70 in GLShaderManager::BuildShader (this=0x65065f8c2ac0 <gl_shaderManager>, descriptor=0x65069d8c9010) at /src/engine/renderer/gl_shader.cpp:997
#14 0x000065065ec2e750 in GLShaderManager::FindShaderProgram (this=0x65065f8c2ac0 <gl_shaderManager>, shaders=std::vector of length 3, capacity 4 = {...}, mainShader="lighttile") at /src/engine/renderer/gl_shader.cpp:1111
#15 0x000065065ec2ed6f in GLShaderManager::BuildPermutation (this=0x65065f8c2ac0 <gl_shaderManager>, shader=0x65069dddbb60, macroIndex=0, deformIndex=0) at /src/engine/renderer/gl_shader.cpp:1170
#16 0x000065065ec2f0bb in GLShaderManager::BuildAll (this=0x65065f8c2ac0 <gl_shaderManager>) at /src/engine/renderer/gl_shader.cpp:1201
#17 0x000065065ed59caf in GLSL_FinishGPUShaders () at /src/engine/renderer/tr_shade.cpp:522
#18 0x000065065ed21d71 in RE_EndRegistration () at /src/engine/renderer/tr_init.cpp:1633
#19 0x000065065eb4a519 in CL_InitCGame () at /src/engine/client/cl_cgame.cpp:640
#20 0x000065065eba1cfd in CL_DownloadsComplete () at /src/engine/client/cl_download.cpp:109
#21 0x000065065eba214e in CL_InitDownloads () at /src/engine/client/cl_download.cpp:237
#22 0x000065065ebbbab8 in CL_ParseGamestate (msg=0x7ffec6cb0110) at /src/engine/client/cl_parse.cpp:460
#23 0x000065065ebbbe21 in CL_ParseServerMessage (msg=0x7ffec6cb0110) at /src/engine/client/cl_parse.cpp:570
#24 0x000065065ebaf7a7 in CL_PacketEvent (from=..., msg=0x7ffec6cb0110) at /src/engine/client/cl_main.cpp:1945
#25 0x000065065eacaccd in Com_EventLoop () at /src/engine/qcommon/common.cpp:429
#26 0x000065065eacba94 in Com_Frame () at /src/engine/qcommon/common.cpp:948
#27 0x000065065eac3181 in Application::ClientApplication::Frame (this=0x65065f064920 <Application::GetApp()::app>) at /src/engine/client/ClientApplication.cpp:112
#28 0x000065065ee3086d in Application::Frame () at /src/engine/framework/Application.cpp:87
#29 0x000065065ee7336f in main (argc=52, argv=0x7ffec6cb8408) at /src/engine/framework/System.cpp:1012

So it crashed there:

		while ( infoLogID != -1 && infoLog[infoLogID].line == lineNumber ) {
			if ( ( int( line.length() ) > infoLog[infoLogID].character ) && ( infoLog[infoLogID].character != -1 ) ) {
				buffer.append( numberWidth + 2, '-' );
				const size_t position = line.find_first_not_of( "\t" );

				if ( position != std::string::npos ) {
					buffer.append( position, '\t' );
/*	HERE	--->	*/		buffer.append( infoLog[infoLogID].character - position, '-' );
				} else {
					buffer.append( infoLog[infoLogID].character, '-' );
				}
				buffer.append( "^" );
				buffer.append( line.length() - infoLog[infoLogID].character - 1, '-' );

[illwieckz]

LOL if I add some exception catcher this way:

--- a/src/engine/renderer/gl_shader.cpp
+++ b/src/engine/renderer/gl_shader.cpp
@@ -1727,6 +1727,7 @@ void GLShaderManager::PrintShaderSource( Str::StringRef programName, GLuint obje
 
 	ri.Hunk_FreeTempMemory( dump );
 
+	try {
 	int lineNumber = 0;
 	size_t pos = 0;
 
@@ -1809,6 +1810,11 @@ void GLShaderManager::PrintShaderSource( Str::StringRef programName, GLuint obje
 	}
 
 	Log::Warn("Source for shader program %s:\n%s", programName, buffer.c_str());
+	}
+	catch (...)
+	{
+	Log::Warn("Raw source for shader program %s:\n%s", programName, src.c_str());
+	}
 }
 
 std::vector<GLShaderManager::InfoLogEntry> GLShaderManager::ParseInfoLog( const std::string& infoLog ) const {

I get that:

Warn: Raw source for shader program lighttile:
			lightCount++;

			if( lightCount == lightsPerLayer ) {
				break;
			}
		}
	}

	exportIdxs( idxs );
}
 
Warn: Compile log:
0:159(7): error: could not implicitly convert operands to arithmetic operator
0:160(7): error: could not implicitly convert operands to arithmetic operator
0:206(2): error: initializer of type int cannot be assigned to variable of type uint
0:212(7): error: initializer of type int cannot be assigned to variable of type uint
0:212(30): error: could not implicitly convert operands to relational operator
0:212(30): error: loop condition must be scalar boolean
0:212(47): error: could not implicitly convert operands to arithmetic operator
0:212(47): error: could not implicitly convert error to uint
0:228(14): error: could not implicitly convert operands to arithmetic operator
0:228(12): error: operands to arithmetic operators must be numeric
0:228(2): error: no matching function for call to `pushIdxs(error, uint, uvec4)'; candidates are:
0:228(2): error:    void pushIdxs(uint, uint, uvec4)
0:231(6): error: operands of `==' must have the same type
 
]terminate called after throwing an instance of 'ShaderException'
  what():  Couldn't compile fragment shader: lighttile

Almost everything was eaten.

As a remind, src is gotten this way:

	glGetShaderSource( object, maxLength, &maxLength, dump );

	std::string buffer;
	std::string delim( "\n" );
	std::string src( dump );

	ri.Hunk_FreeTempMemory( dump );

And just in case std::string src( dump ); was not truly copying, I tried moving ri.Hunk_FreeTempMemory( dump ); after the processing and src is still truncated.

[illwieckz]

If I print the source before processing it, the string is complete, so something is eating the source in our code.

[illwieckz]

So I have a patch that rewrites the processing without the shady src.erase( 0, pos + delim.length() );.

Now the source is not eaten, but I still get the exception when processing it.

[illwieckz]

Well, so it means it was expected that src was eaten when processing it, so we better use my patch so we can print src in case something went wrong when processing it.