exponentially long exception messages in multi-threaded setup (ref #37392)

[slava77]

I observed a problem similar to #37392
with

Exception Message:
basic_string::_M_construct null not valid

in 12_4_0_pre2.
While the issue goes away in a recent IB (e.g. in CMSSW_12_4_X_2022-04-14-1100),

I have a tangential question: the exception messages in 12_4_0_pre2 are issued for every thread with increasingly long stack. In a 32-thread test the last one comes out with

   [10210] While reading from source edm::HepMCProduct generatorSmeared '' SIM
   [10211] Reading branch edmHepMCProduct_generatorSmeared__SIM.
Exception Message:
basic_string::_M_construct null not valid
----- End Fatal Exception -------------------------------------------------

Is the framework really creating such deep stacks or is this just a feature of the printout?
I have a reference setup on cmsdev34:/build/slava77/reltest/CMSSW_12_4_0_pre2-orig/test/gensim-1210p5/11634.0_TTbar_14TeV+2021/sort
there with 8-threads the last exception message is 1703-deep

[cmsbuild]

A new Issue was created by @slava77 Slava Krutelyov.

@Dr15Jones, @perrotta, @dpiparo, @makortel, @smuzaffar, @qliphy can you please review it and eventually sign/assign? Thanks.

cms-bot commands are listed here

[makortel]

assign core

[cmsbuild]

New categories assigned: core

@Dr15Jones,@smuzaffar,@makortel you have been requested to review this Pull request/Issue and eventually sign? Thanks

[makortel]

Looking at cmsdev34:/build/slava77/reltest/CMSSW_12_4_0_pre2-orig/test/gensim-1210p5/11634.0_TTbar_14TeV+2021/sort/step2.mt8.log I see

• 1st trace has depth 4
• 2nd trace has depth 264
• 3rd trace has depth 282
• 4th trace has depth 119
• 5th trace has depth 638
• 6th trace has depth 994
• 7th trace has depth 1347
• 8th trace has depth 1703

The traces are full of Rethrowing an exception that happened on a different read request.

I guess what happens is something along

• the delayed read throws an exception, one of the streams reports that
• the same exception propagates to all other delayed read requests, and those add additional context
• the additional context gets duplicated as well

[makortel]

The delayed reader throws its exception on "different read request" here

cmssw/IOPool/Input/src/RootDelayedReader.cc

Lines 42 to 49 in 086e2e2

	std::shared_ptr<WrapperBase> RootDelayedReader::getProduct_(BranchID const& k, EDProductGetter const* ep) {
	if (lastException_) {
	try {
	std::rethrow_exception(lastException_);
	} catch (cms::Exception& e) {
	e.addContext("Rethrowing an exception that happened on a different read request.");
	throw;
	}

The message gets extended with While reading from in

cmssw/FWCore/Framework/src/ProductResolvers.cc

Lines 196 to 204 in 086e2e2

	try {
	//another thread could have beaten us here
	setProduct(reader->getProduct(branchDescription().branchID(), &principal, mcc));
	} catch (cms::Exception& e) {
	throw extendException(e, branchDescription(), mcc);
	} catch (std::exception const& e) {
	auto newExcept = edm::Exception(errors::StdException) << e.what();
	throw extendException(newExcept, branchDescription(), mcc);
	}

[slava77]

Do I understand this correctly that this is just a length of a message, not an actual depth of the calls?

[makortel]

Correct, it is how the exception messages are constructed (specifically how additional context information gets added), not the depth of the actual call stack.

[slava77]

Correct, it is how the exception messages are constructed (specifically how additional context information gets added), not the depth of the actual call stack.

OK, I guess I can close this issue as not an issue.
Thanks for checking/clarifying.

[Dr15Jones]

Should be fixed by #37591