From f02419eb5c10810349309898f0f9255e35bd9d0e Mon Sep 17 00:00:00 2001 From: Aleksandr Ivanov Date: Thu, 28 Mar 2024 18:28:36 +0200 Subject: [PATCH 01/23] Fix macro redefinition warnings, add bmqstoragetool.td target Signed-off-by: Aleksandr Ivanov --- etc/cmake/BMQTest.cmake | 17 +++++++---------- .../bmqstoragetool/m_bmqstoragetool_testutils.h | 9 +++++++++ 2 files changed, 16 insertions(+), 10 deletions(-) diff --git a/etc/cmake/BMQTest.cmake b/etc/cmake/BMQTest.cmake index 248998572..6b5468bd7 100644 --- a/etc/cmake/BMQTest.cmake +++ b/etc/cmake/BMQTest.cmake @@ -194,6 +194,13 @@ function(bmq_add_application_test target) add_custom_target(${target}.t) endif() add_dependencies(${target}.t ${lib_target}.t) + + if(_COMPAT) + if (NOT TARGET ${target}.td) + add_custom_target(${target}.td) + endif() + add_dependencies(${target}.td ${lib_target}.t) + endif() endif() if (${lib_target}_TEST_TARGETS) @@ -203,16 +210,6 @@ function(bmq_add_application_test target) set(td_manifest) if(${lib_target}_TEST_TARGETS) - - if(NOT TARGET ${lib_target}.t) - add_custom_target(${lib_target}.t) - if(_COMPAT) - add_custom_target(${lib_target}.td) - endif() - endif() - - add_dependencies(${lib_target}.t ${${lib_target}_TEST_TARGETS}) - if(_COMPAT) foreach(test_target ${${lib_target}_TEST_TARGETS}) string(REPLACE ".t" "" component ${test_target}) diff --git a/src/applications/bmqstoragetool/m_bmqstoragetool_testutils.h b/src/applications/bmqstoragetool/m_bmqstoragetool_testutils.h index f8bf024d8..89e9ba162 100644 --- a/src/applications/bmqstoragetool/m_bmqstoragetool_testutils.h +++ b/src/applications/bmqstoragetool/m_bmqstoragetool_testutils.h @@ -51,6 +51,15 @@ // GMOCK #include +// Undefine macroses from gtest.h which are defined in mwctst_testhelper.h +#undef ASSERT_EQ +#undef ASSERT_NE +#undef ASSERT_LT +#undef ASSERT_LE +#undef ASSERT_GT +#undef ASSERT_GE +#undef TEST_F +#undef TEST // TEST DRIVER #include From 9117ac76a92f12e4cd39addd32649977b1415490 Mon Sep 17 00:00:00 2001 From: Aleksandr Ivanov Date: Thu, 6 Jun 2024 15:22:12 +0300 Subject: [PATCH 02/23] Fix order of objects creation in unit test Signed-off-by: Aleksandr Ivanov --- src/applications/bmqtool/m_bmqtool_inpututil.t.cpp | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/applications/bmqtool/m_bmqtool_inpututil.t.cpp b/src/applications/bmqtool/m_bmqtool_inpututil.t.cpp index 5c5b93621..60f1d81b6 100644 --- a/src/applications/bmqtool/m_bmqtool_inpututil.t.cpp +++ b/src/applications/bmqtool/m_bmqtool_inpututil.t.cpp @@ -290,9 +290,9 @@ static void test2_loadMessageFromFileTest() // Check payload ASSERT_EQ_D(test.d_line, payload.str(), test.d_expectedPayload); // Check properties (deserialize into properties instance) - bmqa::MessageProperties messageProperties(s_allocator_p); bdlbb::PooledBlobBufferFactory bufferFactory(128, s_allocator_p); bdlbb::Blob blob(&bufferFactory, s_allocator_p); + bmqa::MessageProperties messageProperties(s_allocator_p); bdlbb::BlobUtil::append(&blob, properties.str().c_str(), static_cast(properties.str().size())); From 3c6651fd67e0587e8e56f9ad753967039497b489 Mon Sep 17 00:00:00 2001 From: Aleksandr Ivanov Date: Wed, 11 Sep 2024 18:19:16 +0300 Subject: [PATCH 03/23] Enhance queue alarm log with subscriptions info Signed-off-by: Aleksandr Ivanov --- .../mqbblp/mqbblp_queueconsumptionmonitor.cpp | 276 +++++++++++------- .../mqbblp/mqbblp_queueconsumptionmonitor.h | 6 + .../mqb/mqbblp/mqbblp_queueengineutil.h | 7 + .../mqb/mqbblp/mqbblp_rootqueueengine.cpp | 185 +++++++++++- .../mqb/mqbblp/mqbblp_rootqueueengine.h | 7 + 5 files changed, 368 insertions(+), 113 deletions(-) diff --git a/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.cpp b/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.cpp index 04567bd41..d5ce68057 100644 --- a/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.cpp +++ b/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.cpp @@ -19,12 +19,13 @@ #include // MBQ #include -#include +#include +// #include #include #include #include -#include -#include +// #include +// #include // BMQ #include @@ -150,14 +151,17 @@ QueueConsumptionMonitor::SubStreamInfo::SubStreamInfo( // CREATORS QueueConsumptionMonitor::QueueConsumptionMonitor(QueueState* queueState, + const LoggingCb& loggingCb, bslma::Allocator* allocator) : d_queueState_p(queueState) , d_maxIdleTime(0) , d_currentTimer(0) , d_subStreamInfos(allocator) +, d_loggingCb(loggingCb) { // PRECONDITIONS BSLS_ASSERT_SAFE(d_queueState_p); + BALL_LOG_WARN << "QueueConsumptionMonitor::QueueConsumptionMonitor"; } // MANIPULATORS @@ -170,6 +174,8 @@ QueueConsumptionMonitor::setMaxIdleTime(bsls::Types::Int64 value) // PRECONDITIONS BSLS_ASSERT_SAFE(value >= 0); + BALL_LOG_WARN << "setMaxIdleTime " << value; + d_maxIdleTime = value; for (SubStreamInfoMapIter iter = d_subStreamInfos.begin(), @@ -196,6 +202,8 @@ void QueueConsumptionMonitor::registerSubStream(const mqbu::StorageKey& key, d_subStreamInfos.end()); BSLS_ASSERT_SAFE(d_subStreamInfos.find(key) == d_subStreamInfos.end()); + BALL_LOG_WARN << "registerSubStream"; + d_subStreamInfos.insert(bsl::make_pair(key, SubStreamInfo(headCb))); } @@ -217,6 +225,8 @@ void QueueConsumptionMonitor::reset() // Should always be called from the queue thread, but will be invoked from // the cluster thread once upon queue creation. + BALL_LOG_WARN << "reset"; + d_maxIdleTime = 0; d_currentTimer = 0; d_subStreamInfos.clear(); @@ -230,6 +240,8 @@ void QueueConsumptionMonitor::onTimer(bsls::Types::Int64 currentTimer) BSLS_ASSERT_SAFE(d_queueState_p->queue()->dispatcher()->inDispatcherThread( d_queueState_p->queue())); + BALL_LOG_WARN << "onTimer"; + if (BSLS_PERFORMANCEHINT_PREDICT_UNLIKELY(d_maxIdleTime == 0)) { // monitoring is disabled BSLS_PERFORMANCEHINT_UNLIKELY_HINT; @@ -254,7 +266,11 @@ void QueueConsumptionMonitor::onTimer(bsls::Types::Int64 currentTimer) ++iter) { SubStreamInfo& info = iter->second; BSLS_ASSERT_SAFE(info.d_headCb); + bslma::ManagedPtr head = info.d_headCb(); + + BALL_LOG_WARN << "Inside FOR head: " << (head ? "true" : "false"); + if (head) { if (head->atEnd()) { head.reset(); @@ -270,22 +286,40 @@ void QueueConsumptionMonitor::onTimer(bsls::Types::Int64 currentTimer) if (info.d_state == State::e_IDLE) { // object was in idle state + BALL_LOG_WARN << "object was in idle state"; onTransitionToAlive(&(iter->second), iter->first); continue; // CONTINUE } + BALL_LOG_WARN << "info.d_messageSent || !head, d_messageSent: " << info.d_messageSent; BSLS_ASSERT_SAFE(info.d_state == State::e_ALIVE); + + // !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!! + mqbi::QueueEngine* qEngine_p = d_queueState_p->queue()->queueEngine(); + // QueueEngineUtil_AppState& app = d_queueState_p->subQueues()[1]; //*subQueue(subQueueId); + const QueueState::SubQueues& sq = d_queueState_p->subQueues(); + for (auto& as : sq) { + // size_t size = as->d_putAsideList.size(); + // const mqbu::StorageKey appKey = as->d_appKey; + // const bsl::string appId = as->d_appId; + BALL_LOG_WARN << "d_putAsideList.size(): " << as->d_putAsideList.size() << "d_redeliveryList.size(): " << as->d_redeliveryList.size() << " d_appKey: " << as->d_appKey << " d_appId: " << as->d_appId; + } + // bsl::shared_ptr as = sq[0]; continue; // CONTINUE } if (info.d_state == State::e_IDLE) { // state was already idle, nothing more to do + BALL_LOG_WARN << "state was already idle, nothing more to do"; continue; // CONTINUE } + BALL_LOG_WARN << "info.d_state: " << info.d_state; + BSLS_ASSERT_SAFE(info.d_state == State::e_ALIVE); if (d_currentTimer - info.d_lastKnownGoodTimer > d_maxIdleTime) { + BALL_LOG_WARN << "No delivered messages in the last 'maxIdleTime'"; // No delivered messages in the last 'maxIdleTime'. onTransitionToIdle(&(iter->second), iter->first, head); continue; // CONTINUE @@ -332,117 +366,135 @@ void QueueConsumptionMonitor::onTransitionToIdle( BSLS_ASSERT_SAFE(d_queueState_p->queue()->dispatcher()->inDispatcherThread( d_queueState_p->queue())); - subStreamInfo->d_state = State::e_IDLE; - - bdlma::LocalSequentialAllocator<2048> localAllocator(0); - bsl::vector handles(&localAllocator); - d_queueState_p->handleCatalog().loadHandles(&handles); - - bmqt::UriBuilder uriBuilder(d_queueState_p->uri(), &localAllocator); - bsl::string appId; - - if (appKey.isNull()) { - appId = bmqp::ProtocolUtil::k_DEFAULT_APP_ID; - } - else if (d_queueState_p->storage()->hasVirtualStorage(appKey, &appId)) { - uriBuilder.setId(appId); - } - - bmqt::Uri uri(&localAllocator); - uriBuilder.uri(&uri); - - mwcu::MemOutStream ss(&localAllocator); - - int idx = 1; - int numConsumers = 0; - - const bool isFanoutValue = - d_queueState_p->queue()->hasMultipleSubStreams(); + d_loggingCb(appKey, head); - for (bsl::vector::const_iterator it = handles.begin(), - last = handles.end(); - it != last; - ++it) { - const mqbi::QueueHandle::SubStreams& subStreamInfos = - (*it)->subStreamInfos(); - - for (mqbi::QueueHandle::SubStreams::const_iterator infoCiter = - subStreamInfos.begin(); - infoCiter != subStreamInfos.end(); - ++infoCiter) { - const bsl::string& itemAppId = infoCiter->first; - - bool isReader = !isFanoutValue && - bmqt::QueueFlagsUtil::isReader( - (*it)->handleParameters().flags()); - // Non-fanout mode consumer in the default subStream ? - isReader |= isFanoutValue && !itemAppId.empty(); - - if (!isReader) { - continue; // CONTINUE - } - - if (itemAppId != appId) { - continue; // CONTINUE - } - - numConsumers += infoCiter->second.d_counts.d_readCount; - - const int level = 2, spacesPerLevel = 2; - - ss << "\n " << idx++ << ". " << (*it)->client()->description() - << mwcu::PrintUtil::newlineAndIndent(level, spacesPerLevel) - << "Handle Parameters .....: " << (*it)->handleParameters() - << mwcu::PrintUtil::newlineAndIndent(level, spacesPerLevel) - << "UnconfirmedMonitors ....:"; - - const bsl::vector monitors = - (*it)->unconfirmedMonitors(appId); - for (size_t i = 0; i < monitors.size(); ++i) { - ss << "\n " << monitors[i]; - } - } - } - - mwcu::MemOutStream out; - out << "Queue '" << uri << "' "; - d_queueState_p->storage()->capacityMeter()->printShortSummary(out); - out << ", max idle time " - << mwcu::PrintUtil::prettyTimeInterval(d_maxIdleTime) - << " appears to be stuck. It currently has " << numConsumers - << " consumers." << ss.str() << "\n"; - - // Print the 10 oldest messages in the queue - static const int k_NUM_MSGS = 10; - const int level = 0, spacesPerLevel = 2; - - out << mwcu::PrintUtil::newlineAndIndent(level, spacesPerLevel) - << k_NUM_MSGS << " oldest messages in the queue:\n"; - - mqbcmd::Result result; - mqbs::StoragePrintUtil::listMessages(&result.makeQueueContents(), - appId, - 0, - k_NUM_MSGS, - d_queueState_p->storage()); - mqbcmd::HumanPrinter::print(out, result); - - if (!head) { - return; // RETURN - } - - // Print the current head of the queue - mqbi::Storage* const storage = d_queueState_p->storage(); - out << mwcu::PrintUtil::newlineAndIndent(level, spacesPerLevel) - << "Current head of the queue:\n"; - - mqbs::StoragePrintUtil::listMessage(&result.makeMessage(), storage, *head); - - mqbcmd::HumanPrinter::print(out, result); - out << "\n"; + subStreamInfo->d_state = State::e_IDLE; - MWCTSK_ALARMLOG_ALARM("QUEUE_CONSUMER_MONITOR") - << out.str() << MWCTSK_ALARMLOG_END; + // bdlma::LocalSequentialAllocator<2048> localAllocator(0); + // bsl::vector handles(&localAllocator); + // d_queueState_p->handleCatalog().loadHandles(&handles); + + // bmqt::UriBuilder uriBuilder(d_queueState_p->uri(), &localAllocator); + // bsl::string appId; + + // if (appKey.isNull()) { + // appId = bmqp::ProtocolUtil::k_DEFAULT_APP_ID; + // } + // else if (d_queueState_p->storage()->hasVirtualStorage(appKey, &appId)) { + // uriBuilder.setId(appId); + // } + + // bmqt::Uri uri(&localAllocator); + // uriBuilder.uri(&uri); + + // mwcu::MemOutStream ss(&localAllocator); + + // int idx = 1; + // int numConsumers = 0; + + // const bool isFanoutValue = + // d_queueState_p->queue()->hasMultipleSubStreams(); + + // for (bsl::vector::const_iterator it = handles.begin(), + // last = handles.end(); + // it != last; + // ++it) { + // const mqbi::QueueHandle::SubStreams& subStreamInfos = + // (*it)->subStreamInfos(); + + // for (mqbi::QueueHandle::SubStreams::const_iterator infoCiter = + // subStreamInfos.begin(); + // infoCiter != subStreamInfos.end(); + // ++infoCiter) { + // const bsl::string& itemAppId = infoCiter->first; + + // bool isReader = !isFanoutValue && + // bmqt::QueueFlagsUtil::isReader( + // (*it)->handleParameters().flags()); + // // Non-fanout mode consumer in the default subStream ? + // isReader |= isFanoutValue && !itemAppId.empty(); + + + // // !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!! + // mqbi::QueueEngine* qEngine_p = d_queueState_p->queue()->queueEngine(); + // // QueueEngineUtil_AppState& app = d_queueState_p->subQueues()[1]; //*subQueue(subQueueId); + // const QueueState::SubQueues& sq = d_queueState_p->subQueues(); + + // BALL_LOG_WARN << "SubQueues size" << sq.size(); + // for (auto& as : sq) { + // // size_t size = as->d_putAsideList.size(); + // // const mqbu::StorageKey appKey = as->d_appKey; + // // const bsl::string appId = as->d_appId; + // BALL_LOG_WARN << "d_putAsideList.size(): " << as->d_putAsideList.size() << "d_redeliveryList.size(): " << as->d_redeliveryList.size() << " d_appKey: " << as->d_appKey << " d_appId: " << as->d_appId; + // } + // // QueueEngineUtil_AppState& appState = bsl::find_if(sq.begin(), sq.end(), [&](auto as){ as->d_appId == appId }); + + + // if (!isReader) { + // continue; // CONTINUE + // } + + // if (itemAppId != appId) { + // continue; // CONTINUE + // } + + // numConsumers += infoCiter->second.d_counts.d_readCount; + + // const int level = 2, spacesPerLevel = 2; + + // ss << "\n " << idx++ << ". " << (*it)->client()->description() + // << mwcu::PrintUtil::newlineAndIndent(level, spacesPerLevel) + // << "Handle Parameters .....: " << (*it)->handleParameters() + // << mwcu::PrintUtil::newlineAndIndent(level, spacesPerLevel) + // << "UnconfirmedMonitors ....:"; + + // const bsl::vector monitors = + // (*it)->unconfirmedMonitors(appId); + // for (size_t i = 0; i < monitors.size(); ++i) { + // ss << "\n " << monitors[i]; + // } + // } + // } + + // mwcu::MemOutStream out; + // out << "Queue '" << uri << "' "; + // d_queueState_p->storage()->capacityMeter()->printShortSummary(out); + // out << ", max idle time " + // << mwcu::PrintUtil::prettyTimeInterval(d_maxIdleTime) + // << " appears to be stuck. It currently has " << numConsumers + // << " consumers." << ss.str() << "\n"; + + // // Print the 10 oldest messages in the queue + // static const int k_NUM_MSGS = 10; + // const int level = 0, spacesPerLevel = 2; + + // out << mwcu::PrintUtil::newlineAndIndent(level, spacesPerLevel) + // << k_NUM_MSGS << " oldest messages in the queue:\n"; + + // mqbcmd::Result result; + // mqbs::StoragePrintUtil::listMessages(&result.makeQueueContents(), + // appId, + // 0, + // k_NUM_MSGS, + // d_queueState_p->storage()); + // mqbcmd::HumanPrinter::print(out, result); + + // if (!head) { + // return; // RETURN + // } + + // // Print the current head of the queue + // mqbi::Storage* const storage = d_queueState_p->storage(); + // out << mwcu::PrintUtil::newlineAndIndent(level, spacesPerLevel) + // << "Current head of the queue:\n"; + + // mqbs::StoragePrintUtil::listMessage(&result.makeMessage(), storage, *head); + + // mqbcmd::HumanPrinter::print(out, result); + // out << "\n"; + + // MWCTSK_ALARMLOG_ALARM("QUEUE_CONSUMER_MONITOR") + // << out.str() << MWCTSK_ALARMLOG_END; } } // close package namespace diff --git a/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.h b/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.h index 0779ea601..9619e430f 100644 --- a/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.h +++ b/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.h @@ -213,6 +213,9 @@ class QueueConsumptionMonitor { typedef bsl::function(void)> HeadCb; + typedef bsl::function& head)> + LoggingCb; + private: // PRIVATE TYPES @@ -265,6 +268,8 @@ class QueueConsumptionMonitor { SubStreamInfoMap d_subStreamInfos; + LoggingCb d_loggingCb; + // NOT IMPLEMENTED QueueConsumptionMonitor(const QueueConsumptionMonitor&) BSLS_CPP11_DELETED; QueueConsumptionMonitor& @@ -306,6 +311,7 @@ class QueueConsumptionMonitor { /// `basicAllocator` to supply memory. If `basicAllocator` is 0, the /// currently installed default allocator is used. QueueConsumptionMonitor(QueueState* queueState, + const LoggingCb& loggingCb, bslma::Allocator* allocator); // MANIPULATORS diff --git a/src/groups/mqb/mqbblp/mqbblp_queueengineutil.h b/src/groups/mqb/mqbblp/mqbblp_queueengineutil.h index eb810de86..8ad3147e5 100644 --- a/src/groups/mqb/mqbblp/mqbblp_queueengineutil.h +++ b/src/groups/mqb/mqbblp/mqbblp_queueengineutil.h @@ -514,6 +514,8 @@ struct QueueEngineUtil_AppState { // ACCESSORS size_t redeliveryListSize() const; + size_t putAsideListSize() const; + Routers::Consumer* findQueueHandleContext(mqbi::QueueHandle* handle); unsigned int upstreamSubQueueId() const; @@ -695,6 +697,11 @@ inline size_t QueueEngineUtil_AppState::redeliveryListSize() const return d_redeliveryList.size(); } +inline size_t QueueEngineUtil_AppState::putAsideListSize() const +{ + return d_putAsideList.size(); +} + inline Routers::Consumer* QueueEngineUtil_AppState::findQueueHandleContext(mqbi::QueueHandle* handle) { diff --git a/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.cpp b/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.cpp index 2e5b853a7..2de454b78 100644 --- a/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.cpp +++ b/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.cpp @@ -23,6 +23,7 @@ #include #include #include +#include #include #include #include @@ -30,6 +31,7 @@ #include #include #include +#include // BMQ #include @@ -243,7 +245,12 @@ RootQueueEngine::RootQueueEngine(QueueState* queueState, const mqbconfm::Domain& domainConfig, bslma::Allocator* allocator) : d_queueState_p(queueState) -, d_consumptionMonitor(queueState, allocator) +, d_consumptionMonitor(queueState, + bdlf::BindUtil::bind(&RootQueueEngine::logAlarmCb, + this, + bdlf::PlaceHolders::_1, // appKey + bdlf::PlaceHolders::_2), // host + allocator) , d_apps(allocator) , d_nullKeyCount(0) , d_hasAutoSubscriptions(false) @@ -289,6 +296,8 @@ int RootQueueEngine::configure(bsl::ostream& errorDescription) rc_AUTO_SUBSCRIPTIONS_ERROR = -3 // Wrong number of auto subscriptions }; + BALL_LOG_WARN << "RootQueueEngine::configure"; + // Populate map of appId to appKey for statically registered consumers size_t numApps = 0; @@ -379,6 +388,9 @@ int RootQueueEngine::configure(bsl::ostream& errorDescription) } if (!QueueEngineUtil::isBroadcastMode(d_queueState_p->queue())) { + BALL_LOG_WARN + << "setMaxIdleTime: " + << d_queueState_p->queue()->domain()->config().maxIdleTime(); d_consumptionMonitor.setMaxIdleTime( d_queueState_p->queue()->domain()->config().maxIdleTime() * bdlt::TimeUnitRatio::k_NANOSECONDS_PER_SECOND); @@ -1554,6 +1566,177 @@ void RootQueueEngine::onTimer(bsls::Types::Int64 currentTimer) d_consumptionMonitor.onTimer(currentTimer); } +void RootQueueEngine::logAlarmCb( + const mqbu::StorageKey& appKey, + const bslma::ManagedPtr& head) const +{ + // executed by the *QUEUE DISPATCHER* thread + + bdlma::LocalSequentialAllocator<2048> localAllocator(0); + bsl::vector handles(&localAllocator); + d_queueState_p->handleCatalog().loadHandles(&handles); + + bmqt::UriBuilder uriBuilder(d_queueState_p->uri(), &localAllocator); + bsl::string appId; + + if (appKey.isNull()) { + appId = bmqp::ProtocolUtil::k_DEFAULT_APP_ID; + } + else if (d_queueState_p->storage()->hasVirtualStorage(appKey, &appId)) { + uriBuilder.setId(appId); + } + + bmqt::Uri uri(&localAllocator); + uriBuilder.uri(&uri); + + mwcu::MemOutStream ss(&localAllocator); + + int idx = 1; + int numConsumers = 0; + + for (bsl::vector::const_iterator it = handles.begin(), + last = handles.end(); + it != last; + ++it) { + const mqbi::QueueHandle::SubStreams& subStreamInfos = + (*it)->subStreamInfos(); + + for (mqbi::QueueHandle::SubStreams::const_iterator infoCiter = + subStreamInfos.begin(); + infoCiter != subStreamInfos.end(); + ++infoCiter) { + const bsl::string& itemAppId = infoCiter->first; + + bool isReader = !d_isFanout && + bmqt::QueueFlagsUtil::isReader( + (*it)->handleParameters().flags()); + // Non-fanout mode consumer in the default subStream ? + isReader |= d_isFanout && !itemAppId.empty(); + + if (!isReader) { + continue; // CONTINUE + } + + if (itemAppId != appId) { + continue; // CONTINUE + } + + numConsumers += infoCiter->second.d_counts.d_readCount; + + const int level = 2, spacesPerLevel = 2; + + ss << "\n " << idx++ << ". " << (*it)->client()->description() + << mwcu::PrintUtil::newlineAndIndent(level, spacesPerLevel) + << "Handle Parameters .....: " << (*it)->handleParameters() + << mwcu::PrintUtil::newlineAndIndent(level, spacesPerLevel) + << "Unconfirmed messages count: " << (*it)->countUnconfirmed() + << mwcu::PrintUtil::newlineAndIndent(level, spacesPerLevel) + << "UnconfirmedMonitors ....:"; + + const bsl::vector monitors = + (*it)->unconfirmedMonitors(appId); + for (size_t i = 0; i < monitors.size(); ++i) { + ss << "\n " << monitors[i]; + } + } + } + + mwcu::MemOutStream out; + out << "Queue '" << uri << "' "; + d_queueState_p->storage()->capacityMeter()->printShortSummary(out); + out << ", max idle time " + << mwcu::PrintUtil::prettyTimeInterval( + d_queueState_p->queue()->domain()->config().maxIdleTime() * + bdlt::TimeUnitRatio::k_NANOSECONDS_PER_SECOND) + << " appears to be stuck. It currently has " << numConsumers + << " consumers." << ss.str() << "\n"; + + // TODO: move to some helper class + Apps::const_iterator cItApp = d_apps.findByKey1(appId); + if (cItApp != d_apps.end()) { + const AppStateSp& app = cItApp->value(); + out << "\nPut aside list size: " << app->putAsideListSize() << '\n'; + out << "Redelivery list size: " << app->redeliveryListSize() << '\n'; + out << "Not delivered number of messages: " + << d_queueState_p->storage()->numMessages(app->d_appKey) << '\n'; + + // Log consumer subscriptions + mqbblp::Routers::QueueRoutingContext& routingContext = + app->d_routing_sp->d_queue; + mqbcmd::Routing routing; + routingContext.loadInternals(&routing); + const bsl::vector& subscriptionGroups = + routing.subscriptionGroups(); + // Limit to log only 100 expressions + static const size_t k_EXPR_NUM_LIMIT = 100; + const size_t exprCountLimit = bsl::min(subscriptionGroups.size(), + k_EXPR_NUM_LIMIT); + if (subscriptionGroups.size() > exprCountLimit) { + out << exprCountLimit << " of " << subscriptionGroups.size() + << " consumer subscriptions: " << '\n'; + } + else { + out << "Consumer subscriptions: " << '\n'; + } + // TODO: use LimitedPrinter + for (bsl::vector::const_iterator cIt = + subscriptionGroups.begin(); + bsl::distance(subscriptionGroups.begin(), cIt) < + static_cast(exprCountLimit); + ++cIt) { + out << cIt->expression() << '\n'; + } + + out << "Put aside list GUIDS: " << '\n'; + for (RedeliveryList::iterator it = app->d_putAsideList.begin(); !app->d_putAsideList.isEnd(it); app->d_putAsideList.next(&it)) + { + out << *it << '\n'; + } + out << "First GUID in Put aside list: " << app->d_putAsideList.first() << '\n'; + out << "Has message: " << d_queueState_p->storage()->hasMessage(app->d_putAsideList.first()) << '\n'; + mqbi::StorageMessageAttributes attributes; + mqbi::StorageResult::Enum rc = d_queueState_p->storage()->get(&attributes, app->d_putAsideList.first()); + if (rc == mqbi::StorageResult::Enum::e_SUCCESS) + { + out << "Attributes: " << attributes << '\n'; + } else { + out << "Get Attributes failed: rc= " << rc << '\n'; + } + } + + // Print the 10 oldest messages in the queue + static const int k_NUM_MSGS = 10; + const int level = 0, spacesPerLevel = 2; + + out << mwcu::PrintUtil::newlineAndIndent(level, spacesPerLevel) + << k_NUM_MSGS << " oldest messages in the queue:\n"; + + mqbcmd::Result result; + mqbs::StoragePrintUtil::listMessages(&result.makeQueueContents(), + appId, + 0, + k_NUM_MSGS, + d_queueState_p->storage()); + mqbcmd::HumanPrinter::print(out, result); + + if (!head) { + return; // RETURN + } + + // Print the current head of the queue + mqbi::Storage* const storage = d_queueState_p->storage(); + out << mwcu::PrintUtil::newlineAndIndent(level, spacesPerLevel) + << "Current head of the queue:\n"; + + mqbs::StoragePrintUtil::listMessage(&result.makeMessage(), storage, *head); + + mqbcmd::HumanPrinter::print(out, result); + out << "\n"; + + MWCTSK_ALARMLOG_ALARM("ROOT_QUEUE_ENGINE") + << out.str() << MWCTSK_ALARMLOG_END; +} + void RootQueueEngine::afterAppIdRegistered( const mqbi::Storage::AppIdKeyPair& appIdKeyPair) { diff --git a/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.h b/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.h index 8e7598247..652326431 100644 --- a/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.h +++ b/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.h @@ -34,6 +34,7 @@ #include #include #include +#include #include #include @@ -203,6 +204,12 @@ class RootQueueEngine BSLS_KEYWORD_FINAL : public mqbi::QueueEngine { const AppStateSp& subQueue(unsigned int upstreamSubQueueId) const; + /// Callback called by `d_consumptionMonitor` when alarm is detected. + /// It logs queue data for the specified `appKey` and `head`. + void + logAlarmCb(const mqbu::StorageKey& appKey, + const bslma::ManagedPtr& head) const; + public: // TRAITS BSLMF_NESTED_TRAIT_DECLARATION(RootQueueEngine, bslma::UsesBslmaAllocator) From 69da6c10edfc810f534d4abd32ea34c2c1619562 Mon Sep 17 00:00:00 2001 From: Aleksandr Ivanov Date: Thu, 12 Sep 2024 15:16:13 +0300 Subject: [PATCH 04/23] Debug message properties Signed-off-by: Aleksandr Ivanov --- .../mqb/mqbblp/mqbblp_rootqueueengine.cpp | 59 +++++++++++++++++++ .../mqb/mqbblp/mqbblp_rootqueueengine.h | 2 +- 2 files changed, 60 insertions(+), 1 deletion(-) diff --git a/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.cpp b/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.cpp index 2de454b78..3eea975c4 100644 --- a/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.cpp +++ b/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.cpp @@ -1702,6 +1702,65 @@ void RootQueueEngine::logAlarmCb( } else { out << "Get Attributes failed: rc= " << rc << '\n'; } + + const bmqp::MessagePropertiesInfo& logic = attributes.messagePropertiesInfo(); + bslma::ManagedPtr storageIterator; + rc = d_queueState_p->storage()->getIterator(&storageIterator, appKey, app->d_putAsideList.first()); + if (rc != mqbi::StorageResult::Enum::e_SUCCESS) + { + out << "getIterator failed: rc= " << rc << '\n'; + } + + { + const bsl::shared_ptr& appData = storageIterator->appData(); + + bmqp::MessageProperties properties; + const bdlbb::Blob& blob = *appData.get(); + int rc = properties.streamIn(blob, logic.isExtended()); + if (rc) { + out << "streamIn failed: rc= " << rc << '\n'; + } + out << "Message Properties: " << properties << '\n'; + + + // bmqp::MessagePropertiesIterator iter(&properties); + // while (iter.hasNext()) { + // out << " Name [" << iter.name() << "], Type [" << iter.type() + // << "], Value [" << iter << "]\n"; + // } + + // const char* appData = 0; + // unsigned int appDataLen = 0; + // unsigned int propertiesAreaLen = 0; + // it->loadApplicationData(&appData, &appDataLen); + // int rc = mqbs::FileStoreProtocolPrinter::printMessageProperties( + // &propertiesAreaLen, + // propsOsstr, + // appData, + // bmqp::MessagePropertiesInfo(dh)); + + } + + + + //StorageIterator + // /// Return a reference offering non-modifiable access to the application + // /// data associated with the item currently pointed at by this iterator. + // /// The behavior is undefined unless `atEnd` returns `false`. + // virtual const bsl::shared_ptr& appData() const = 0; + + // /// Return a reference offering non-modifiable access to the options + // /// associated with the item currently pointed at by this iterator. The + // /// behavior is undefined unless `atEnd` returns `false`. + // virtual const bsl::shared_ptr& options() const = 0; + + // /// Return a reference offering non-modifiable access to the attributes + // /// associated with the message currently pointed at by this iterator. + // /// The behavior is undefined unless `atEnd` returns `false`. + // virtual const StorageMessageAttributes& attributes() const = 0; + + + } // Print the 10 oldest messages in the queue diff --git a/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.h b/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.h index 652326431..48c1de451 100644 --- a/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.h +++ b/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.h @@ -98,7 +98,7 @@ class RootQueueEngine BSLS_KEYWORD_FINAL : public mqbi::QueueEngine { /// (appId, appKeyCount) -> AppStateSp typedef mwcc::TwoKeyHashMap Apps; - typedef bslma::ManagedPtr StorageIteratorMp; + // typedef bslma::ManagedPtr StorageIteratorMp; private: // DATA From 493b459d4c2cf442e4455323919495af4df94261 Mon Sep 17 00:00:00 2001 From: Aleksandr Ivanov Date: Thu, 12 Sep 2024 18:23:39 +0300 Subject: [PATCH 05/23] Add logging of oldest message in put aside queue and its properties Signed-off-by: Aleksandr Ivanov --- .github/workflows/build.yaml | 1 + .../mqbblp/mqbblp_queueconsumptionmonitor.cpp | 168 +----------------- .../mqbblp/mqbblp_queueconsumptionmonitor.h | 7 +- .../mqb/mqbblp/mqbblp_rootqueueengine.cpp | 158 ++++++---------- .../mqb/mqbblp/mqbblp_rootqueueengine.h | 3 +- 5 files changed, 73 insertions(+), 264 deletions(-) diff --git a/.github/workflows/build.yaml b/.github/workflows/build.yaml index dc9dc65b3..8233734e5 100644 --- a/.github/workflows/build.yaml +++ b/.github/workflows/build.yaml @@ -4,6 +4,7 @@ on: push: branches: - main + - enhance-alarm-log pull_request: branches: - main diff --git a/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.cpp b/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.cpp index d5ce68057..55ba6df51 100644 --- a/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.cpp +++ b/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.cpp @@ -20,12 +20,9 @@ // MBQ #include #include -// #include #include #include #include -// #include -// #include // BMQ #include @@ -151,7 +148,7 @@ QueueConsumptionMonitor::SubStreamInfo::SubStreamInfo( // CREATORS QueueConsumptionMonitor::QueueConsumptionMonitor(QueueState* queueState, - const LoggingCb& loggingCb, + const LoggingCb& loggingCb, bslma::Allocator* allocator) : d_queueState_p(queueState) , d_maxIdleTime(0) @@ -161,7 +158,7 @@ QueueConsumptionMonitor::QueueConsumptionMonitor(QueueState* queueState, { // PRECONDITIONS BSLS_ASSERT_SAFE(d_queueState_p); - BALL_LOG_WARN << "QueueConsumptionMonitor::QueueConsumptionMonitor"; + BSLS_ASSERT_SAFE(d_loggingCb); } // MANIPULATORS @@ -174,8 +171,6 @@ QueueConsumptionMonitor::setMaxIdleTime(bsls::Types::Int64 value) // PRECONDITIONS BSLS_ASSERT_SAFE(value >= 0); - BALL_LOG_WARN << "setMaxIdleTime " << value; - d_maxIdleTime = value; for (SubStreamInfoMapIter iter = d_subStreamInfos.begin(), @@ -202,8 +197,6 @@ void QueueConsumptionMonitor::registerSubStream(const mqbu::StorageKey& key, d_subStreamInfos.end()); BSLS_ASSERT_SAFE(d_subStreamInfos.find(key) == d_subStreamInfos.end()); - BALL_LOG_WARN << "registerSubStream"; - d_subStreamInfos.insert(bsl::make_pair(key, SubStreamInfo(headCb))); } @@ -225,8 +218,6 @@ void QueueConsumptionMonitor::reset() // Should always be called from the queue thread, but will be invoked from // the cluster thread once upon queue creation. - BALL_LOG_WARN << "reset"; - d_maxIdleTime = 0; d_currentTimer = 0; d_subStreamInfos.clear(); @@ -240,8 +231,6 @@ void QueueConsumptionMonitor::onTimer(bsls::Types::Int64 currentTimer) BSLS_ASSERT_SAFE(d_queueState_p->queue()->dispatcher()->inDispatcherThread( d_queueState_p->queue())); - BALL_LOG_WARN << "onTimer"; - if (BSLS_PERFORMANCEHINT_PREDICT_UNLIKELY(d_maxIdleTime == 0)) { // monitoring is disabled BSLS_PERFORMANCEHINT_UNLIKELY_HINT; @@ -266,10 +255,7 @@ void QueueConsumptionMonitor::onTimer(bsls::Types::Int64 currentTimer) ++iter) { SubStreamInfo& info = iter->second; BSLS_ASSERT_SAFE(info.d_headCb); - bslma::ManagedPtr head = info.d_headCb(); - - BALL_LOG_WARN << "Inside FOR head: " << (head ? "true" : "false"); if (head) { if (head->atEnd()) { @@ -286,40 +272,24 @@ void QueueConsumptionMonitor::onTimer(bsls::Types::Int64 currentTimer) if (info.d_state == State::e_IDLE) { // object was in idle state - BALL_LOG_WARN << "object was in idle state"; onTransitionToAlive(&(iter->second), iter->first); continue; // CONTINUE } - BALL_LOG_WARN << "info.d_messageSent || !head, d_messageSent: " << info.d_messageSent; + BALL_LOG_WARN << "info.d_messageSent || !head, d_messageSent: " + << info.d_messageSent; BSLS_ASSERT_SAFE(info.d_state == State::e_ALIVE); - - // !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!! - mqbi::QueueEngine* qEngine_p = d_queueState_p->queue()->queueEngine(); - // QueueEngineUtil_AppState& app = d_queueState_p->subQueues()[1]; //*subQueue(subQueueId); - const QueueState::SubQueues& sq = d_queueState_p->subQueues(); - for (auto& as : sq) { - // size_t size = as->d_putAsideList.size(); - // const mqbu::StorageKey appKey = as->d_appKey; - // const bsl::string appId = as->d_appId; - BALL_LOG_WARN << "d_putAsideList.size(): " << as->d_putAsideList.size() << "d_redeliveryList.size(): " << as->d_redeliveryList.size() << " d_appKey: " << as->d_appKey << " d_appId: " << as->d_appId; - } - // bsl::shared_ptr as = sq[0]; continue; // CONTINUE } if (info.d_state == State::e_IDLE) { // state was already idle, nothing more to do - BALL_LOG_WARN << "state was already idle, nothing more to do"; continue; // CONTINUE } - BALL_LOG_WARN << "info.d_state: " << info.d_state; - BSLS_ASSERT_SAFE(info.d_state == State::e_ALIVE); if (d_currentTimer - info.d_lastKnownGoodTimer > d_maxIdleTime) { - BALL_LOG_WARN << "No delivered messages in the last 'maxIdleTime'"; // No delivered messages in the last 'maxIdleTime'. onTransitionToIdle(&(iter->second), iter->first, head); continue; // CONTINUE @@ -365,136 +335,12 @@ void QueueConsumptionMonitor::onTransitionToIdle( // PRECONDITIONS BSLS_ASSERT_SAFE(d_queueState_p->queue()->dispatcher()->inDispatcherThread( d_queueState_p->queue())); - - d_loggingCb(appKey, head); + BSLS_ASSERT_SAFE(d_loggingCb); subStreamInfo->d_state = State::e_IDLE; - // bdlma::LocalSequentialAllocator<2048> localAllocator(0); - // bsl::vector handles(&localAllocator); - // d_queueState_p->handleCatalog().loadHandles(&handles); - - // bmqt::UriBuilder uriBuilder(d_queueState_p->uri(), &localAllocator); - // bsl::string appId; - - // if (appKey.isNull()) { - // appId = bmqp::ProtocolUtil::k_DEFAULT_APP_ID; - // } - // else if (d_queueState_p->storage()->hasVirtualStorage(appKey, &appId)) { - // uriBuilder.setId(appId); - // } - - // bmqt::Uri uri(&localAllocator); - // uriBuilder.uri(&uri); - - // mwcu::MemOutStream ss(&localAllocator); - - // int idx = 1; - // int numConsumers = 0; - - // const bool isFanoutValue = - // d_queueState_p->queue()->hasMultipleSubStreams(); - - // for (bsl::vector::const_iterator it = handles.begin(), - // last = handles.end(); - // it != last; - // ++it) { - // const mqbi::QueueHandle::SubStreams& subStreamInfos = - // (*it)->subStreamInfos(); - - // for (mqbi::QueueHandle::SubStreams::const_iterator infoCiter = - // subStreamInfos.begin(); - // infoCiter != subStreamInfos.end(); - // ++infoCiter) { - // const bsl::string& itemAppId = infoCiter->first; - - // bool isReader = !isFanoutValue && - // bmqt::QueueFlagsUtil::isReader( - // (*it)->handleParameters().flags()); - // // Non-fanout mode consumer in the default subStream ? - // isReader |= isFanoutValue && !itemAppId.empty(); - - - // // !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!! - // mqbi::QueueEngine* qEngine_p = d_queueState_p->queue()->queueEngine(); - // // QueueEngineUtil_AppState& app = d_queueState_p->subQueues()[1]; //*subQueue(subQueueId); - // const QueueState::SubQueues& sq = d_queueState_p->subQueues(); - - // BALL_LOG_WARN << "SubQueues size" << sq.size(); - // for (auto& as : sq) { - // // size_t size = as->d_putAsideList.size(); - // // const mqbu::StorageKey appKey = as->d_appKey; - // // const bsl::string appId = as->d_appId; - // BALL_LOG_WARN << "d_putAsideList.size(): " << as->d_putAsideList.size() << "d_redeliveryList.size(): " << as->d_redeliveryList.size() << " d_appKey: " << as->d_appKey << " d_appId: " << as->d_appId; - // } - // // QueueEngineUtil_AppState& appState = bsl::find_if(sq.begin(), sq.end(), [&](auto as){ as->d_appId == appId }); - - - // if (!isReader) { - // continue; // CONTINUE - // } - - // if (itemAppId != appId) { - // continue; // CONTINUE - // } - - // numConsumers += infoCiter->second.d_counts.d_readCount; - - // const int level = 2, spacesPerLevel = 2; - - // ss << "\n " << idx++ << ". " << (*it)->client()->description() - // << mwcu::PrintUtil::newlineAndIndent(level, spacesPerLevel) - // << "Handle Parameters .....: " << (*it)->handleParameters() - // << mwcu::PrintUtil::newlineAndIndent(level, spacesPerLevel) - // << "UnconfirmedMonitors ....:"; - - // const bsl::vector monitors = - // (*it)->unconfirmedMonitors(appId); - // for (size_t i = 0; i < monitors.size(); ++i) { - // ss << "\n " << monitors[i]; - // } - // } - // } - - // mwcu::MemOutStream out; - // out << "Queue '" << uri << "' "; - // d_queueState_p->storage()->capacityMeter()->printShortSummary(out); - // out << ", max idle time " - // << mwcu::PrintUtil::prettyTimeInterval(d_maxIdleTime) - // << " appears to be stuck. It currently has " << numConsumers - // << " consumers." << ss.str() << "\n"; - - // // Print the 10 oldest messages in the queue - // static const int k_NUM_MSGS = 10; - // const int level = 0, spacesPerLevel = 2; - - // out << mwcu::PrintUtil::newlineAndIndent(level, spacesPerLevel) - // << k_NUM_MSGS << " oldest messages in the queue:\n"; - - // mqbcmd::Result result; - // mqbs::StoragePrintUtil::listMessages(&result.makeQueueContents(), - // appId, - // 0, - // k_NUM_MSGS, - // d_queueState_p->storage()); - // mqbcmd::HumanPrinter::print(out, result); - - // if (!head) { - // return; // RETURN - // } - - // // Print the current head of the queue - // mqbi::Storage* const storage = d_queueState_p->storage(); - // out << mwcu::PrintUtil::newlineAndIndent(level, spacesPerLevel) - // << "Current head of the queue:\n"; - - // mqbs::StoragePrintUtil::listMessage(&result.makeMessage(), storage, *head); - - // mqbcmd::HumanPrinter::print(out, result); - // out << "\n"; - - // MWCTSK_ALARMLOG_ALARM("QUEUE_CONSUMER_MONITOR") - // << out.str() << MWCTSK_ALARMLOG_END; + // Call logging callback to log alarm info. + d_loggingCb(appKey, head); } } // close package namespace diff --git a/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.h b/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.h index 9619e430f..63323fad6 100644 --- a/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.h +++ b/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.h @@ -213,7 +213,9 @@ class QueueConsumptionMonitor { typedef bsl::function(void)> HeadCb; - typedef bsl::function& head)> + typedef bsl::function& head)> LoggingCb; private: @@ -269,6 +271,7 @@ class QueueConsumptionMonitor { SubStreamInfoMap d_subStreamInfos; LoggingCb d_loggingCb; + // Callback to log alarm info. // NOT IMPLEMENTED QueueConsumptionMonitor(const QueueConsumptionMonitor&) BSLS_CPP11_DELETED; @@ -311,7 +314,7 @@ class QueueConsumptionMonitor { /// `basicAllocator` to supply memory. If `basicAllocator` is 0, the /// currently installed default allocator is used. QueueConsumptionMonitor(QueueState* queueState, - const LoggingCb& loggingCb, + const LoggingCb& loggingCb, bslma::Allocator* allocator); // MANIPULATORS diff --git a/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.cpp b/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.cpp index 3eea975c4..33b1ae273 100644 --- a/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.cpp +++ b/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.cpp @@ -30,6 +30,7 @@ #include #include #include +#include #include #include @@ -249,7 +250,7 @@ RootQueueEngine::RootQueueEngine(QueueState* queueState, bdlf::BindUtil::bind(&RootQueueEngine::logAlarmCb, this, bdlf::PlaceHolders::_1, // appKey - bdlf::PlaceHolders::_2), // host + bdlf::PlaceHolders::_2), // head allocator) , d_apps(allocator) , d_nullKeyCount(0) @@ -296,8 +297,6 @@ int RootQueueEngine::configure(bsl::ostream& errorDescription) rc_AUTO_SUBSCRIPTIONS_ERROR = -3 // Wrong number of auto subscriptions }; - BALL_LOG_WARN << "RootQueueEngine::configure"; - // Populate map of appId to appKey for statically registered consumers size_t numApps = 0; @@ -388,9 +387,6 @@ int RootQueueEngine::configure(bsl::ostream& errorDescription) } if (!QueueEngineUtil::isBroadcastMode(d_queueState_p->queue())) { - BALL_LOG_WARN - << "setMaxIdleTime: " - << d_queueState_p->queue()->domain()->config().maxIdleTime(); d_consumptionMonitor.setMaxIdleTime( d_queueState_p->queue()->domain()->config().maxIdleTime() * bdlt::TimeUnitRatio::k_NANOSECONDS_PER_SECOND); @@ -1572,6 +1568,10 @@ void RootQueueEngine::logAlarmCb( { // executed by the *QUEUE DISPATCHER* thread + // PRECONDITIONS + BSLS_ASSERT_SAFE(d_queueState_p->queue()->dispatcher()->inDispatcherThread( + d_queueState_p->queue())); + bdlma::LocalSequentialAllocator<2048> localAllocator(0); bsl::vector handles(&localAllocator); d_queueState_p->handleCatalog().loadHandles(&handles); @@ -1649,118 +1649,79 @@ void RootQueueEngine::logAlarmCb( d_queueState_p->queue()->domain()->config().maxIdleTime() * bdlt::TimeUnitRatio::k_NANOSECONDS_PER_SECOND) << " appears to be stuck. It currently has " << numConsumers - << " consumers." << ss.str() << "\n"; + << " consumers." << ss.str() << '\n'; + + mqbi::Storage* const storage = d_queueState_p->storage(); - // TODO: move to some helper class Apps::const_iterator cItApp = d_apps.findByKey1(appId); if (cItApp != d_apps.end()) { const AppStateSp& app = cItApp->value(); out << "\nPut aside list size: " << app->putAsideListSize() << '\n'; - out << "Redelivery list size: " << app->redeliveryListSize() << '\n'; - out << "Not delivered number of messages: " - << d_queueState_p->storage()->numMessages(app->d_appKey) << '\n'; + out << "Redelivery list size: " << app->redeliveryListSize() << "\n\n"; // Log consumer subscriptions mqbblp::Routers::QueueRoutingContext& routingContext = app->d_routing_sp->d_queue; mqbcmd::Routing routing; routingContext.loadInternals(&routing); - const bsl::vector& subscriptionGroups = + const bsl::vector& subscrGroups = routing.subscriptionGroups(); - // Limit to log only 100 expressions - static const size_t k_EXPR_NUM_LIMIT = 100; - const size_t exprCountLimit = bsl::min(subscriptionGroups.size(), - k_EXPR_NUM_LIMIT); - if (subscriptionGroups.size() > exprCountLimit) { - out << exprCountLimit << " of " << subscriptionGroups.size() - << " consumer subscriptions: " << '\n'; + + static const size_t k_EXPR_NUM_LIMIT = 50; + if (subscrGroups.size() > k_EXPR_NUM_LIMIT) { + out << k_EXPR_NUM_LIMIT << " of " << subscrGroups.size() + << " consumer subscription expressions: " << '\n'; } else { - out << "Consumer subscriptions: " << '\n'; + out << "Consumer subscription expressions: " << '\n'; } - // TODO: use LimitedPrinter + // Limit to log only k_EXPR_NUM_LIMIT expressions + size_t currNum = 0; for (bsl::vector::const_iterator cIt = - subscriptionGroups.begin(); - bsl::distance(subscriptionGroups.begin(), cIt) < - static_cast(exprCountLimit); - ++cIt) { + subscrGroups.begin(); + cIt != subscrGroups.end() && currNum < k_EXPR_NUM_LIMIT; + ++cIt, ++currNum) { out << cIt->expression() << '\n'; } - - out << "Put aside list GUIDS: " << '\n'; - for (RedeliveryList::iterator it = app->d_putAsideList.begin(); !app->d_putAsideList.isEnd(it); app->d_putAsideList.next(&it)) - { - out << *it << '\n'; - } - out << "First GUID in Put aside list: " << app->d_putAsideList.first() << '\n'; - out << "Has message: " << d_queueState_p->storage()->hasMessage(app->d_putAsideList.first()) << '\n'; - mqbi::StorageMessageAttributes attributes; - mqbi::StorageResult::Enum rc = d_queueState_p->storage()->get(&attributes, app->d_putAsideList.first()); - if (rc == mqbi::StorageResult::Enum::e_SUCCESS) - { - out << "Attributes: " << attributes << '\n'; - } else { - out << "Get Attributes failed: rc= " << rc << '\n'; - } - - const bmqp::MessagePropertiesInfo& logic = attributes.messagePropertiesInfo(); - bslma::ManagedPtr storageIterator; - rc = d_queueState_p->storage()->getIterator(&storageIterator, appKey, app->d_putAsideList.first()); - if (rc != mqbi::StorageResult::Enum::e_SUCCESS) - { - out << "getIterator failed: rc= " << rc << '\n'; - } - - { - const bsl::shared_ptr& appData = storageIterator->appData(); - + out << '\n'; + + // Log the first (oldest) message in Put aside list and its properties + bslma::ManagedPtr storageIt_mp; + mqbi::StorageResult::Enum rc = storage->getIterator( + &storageIt_mp, + appKey, + app->d_putAsideList.first()); + if (rc == mqbi::StorageResult::Enum::e_SUCCESS) { + // Log timestamp + out << "Oldest message in a 'Put aside' list:\n"; + mqbcmd::Result result; + mqbs::StoragePrintUtil::listMessage(&result.makeMessage(), + storage, + *storageIt_mp); + mqbcmd::HumanPrinter::print(out, result); + out << '\n'; + // Log message properties + const bsl::shared_ptr& appData = + storageIt_mp->appData(); + const bmqp::MessagePropertiesInfo& logic = + storageIt_mp->attributes().messagePropertiesInfo(); bmqp::MessageProperties properties; - const bdlbb::Blob& blob = *appData.get(); - int rc = properties.streamIn(blob, logic.isExtended()); - if (rc) { - out << "streamIn failed: rc= " << rc << '\n'; + int ret = properties.streamIn(*appData, logic.isExtended()); + if (!ret) { + out << "Message Properties: " << properties << '\n'; + } + else { + BALL_LOG_WARN << "Failed to streamIn MessageProperties, rc = " + << rc; } - out << "Message Properties: " << properties << '\n'; - - - // bmqp::MessagePropertiesIterator iter(&properties); - // while (iter.hasNext()) { - // out << " Name [" << iter.name() << "], Type [" << iter.type() - // << "], Value [" << iter << "]\n"; - // } - - // const char* appData = 0; - // unsigned int appDataLen = 0; - // unsigned int propertiesAreaLen = 0; - // it->loadApplicationData(&appData, &appDataLen); - // int rc = mqbs::FileStoreProtocolPrinter::printMessageProperties( - // &propertiesAreaLen, - // propsOsstr, - // appData, - // bmqp::MessagePropertiesInfo(dh)); - } - - - - //StorageIterator - // /// Return a reference offering non-modifiable access to the application - // /// data associated with the item currently pointed at by this iterator. - // /// The behavior is undefined unless `atEnd` returns `false`. - // virtual const bsl::shared_ptr& appData() const = 0; - - // /// Return a reference offering non-modifiable access to the options - // /// associated with the item currently pointed at by this iterator. The - // /// behavior is undefined unless `atEnd` returns `false`. - // virtual const bsl::shared_ptr& options() const = 0; - - // /// Return a reference offering non-modifiable access to the attributes - // /// associated with the message currently pointed at by this iterator. - // /// The behavior is undefined unless `atEnd` returns `false`. - // virtual const StorageMessageAttributes& attributes() const = 0; - - - + else { + BALL_LOG_WARN << "Failed to get storage iterator for GUID: " + << app->d_putAsideList.first() << ", rc = " << rc; + } + } + else { + BALL_LOG_WARN << "No App found for appId: " << appId; } // Print the 10 oldest messages in the queue @@ -1775,7 +1736,7 @@ void RootQueueEngine::logAlarmCb( appId, 0, k_NUM_MSGS, - d_queueState_p->storage()); + storage); mqbcmd::HumanPrinter::print(out, result); if (!head) { @@ -1783,7 +1744,6 @@ void RootQueueEngine::logAlarmCb( } // Print the current head of the queue - mqbi::Storage* const storage = d_queueState_p->storage(); out << mwcu::PrintUtil::newlineAndIndent(level, spacesPerLevel) << "Current head of the queue:\n"; diff --git a/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.h b/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.h index 48c1de451..babe6a8c1 100644 --- a/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.h +++ b/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.h @@ -34,7 +34,6 @@ #include #include #include -#include #include #include @@ -208,7 +207,7 @@ class RootQueueEngine BSLS_KEYWORD_FINAL : public mqbi::QueueEngine { /// It logs queue data for the specified `appKey` and `head`. void logAlarmCb(const mqbu::StorageKey& appKey, - const bslma::ManagedPtr& head) const; + const bslma::ManagedPtr& head) const; public: // TRAITS From b972874dc8f8d00cc948610dce52856b60d4dd43 Mon Sep 17 00:00:00 2001 From: Aleksandr Ivanov Date: Fri, 13 Sep 2024 13:04:23 +0300 Subject: [PATCH 06/23] Fix mqbblp_queueconsumptionmonitor.t Signed-off-by: Aleksandr Ivanov --- .../mqbblp/mqbblp_queueconsumptionmonitor.cpp | 3 - .../mqbblp_queueconsumptionmonitor.t.cpp | 56 +++-------- .../mqb/mqbblp/mqbblp_rootqueueengine.cpp | 99 ++++++++++--------- 3 files changed, 68 insertions(+), 90 deletions(-) diff --git a/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.cpp b/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.cpp index 55ba6df51..7dc3a924d 100644 --- a/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.cpp +++ b/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.cpp @@ -30,7 +30,6 @@ #include // MWC -#include #include #include @@ -276,8 +275,6 @@ void QueueConsumptionMonitor::onTimer(bsls::Types::Int64 currentTimer) continue; // CONTINUE } - BALL_LOG_WARN << "info.d_messageSent || !head, d_messageSent: " - << info.d_messageSent; BSLS_ASSERT_SAFE(info.d_state == State::e_ALIVE); continue; // CONTINUE } diff --git a/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.t.cpp b/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.t.cpp index c9061a16f..e3a77e840 100644 --- a/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.t.cpp +++ b/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.t.cpp @@ -39,6 +39,7 @@ #include // MWC +#include #include #include #include @@ -93,6 +94,18 @@ ClientContext::~ClientContext() // NOTHING } +static void loggingCb(BSLS_ANNOTATION_UNUSED const mqbu::StorageKey& appKey, + BSLS_ANNOTATION_UNUSED const + bslma::ManagedPtr& head) +{ + BALL_LOG_SET_CATEGORY("MQBBLP.QUEUECONSUMPTIONMONITORTEST"); + + mwcu::MemOutStream out(s_allocator_p); + out << "Test Alarm"; + MWCTSK_ALARMLOG_ALARM("QUEUE_CONSUMER_MONITOR") + << out.str() << MWCTSK_ALARMLOG_END; +} + struct Test : mwctst::Test { typedef bsl::vector< bsl::pair > @@ -152,7 +165,7 @@ Test::Test() d_partitionId, &d_domain, s_allocator_p) -, d_monitor(&d_queueState, s_allocator_p) +, d_monitor(&d_queueState, &loggingCb, s_allocator_p) , d_storage(d_queue.uri(), mqbu::StorageKey::k_NULL_KEY, mqbs::DataStore::k_INVALID_PARTITION_ID, @@ -388,10 +401,6 @@ TEST_F(Test, logFormat) logObserver.records().back(), "ALARM \\[QUEUE_CONSUMER_MONITOR\\]", s_allocator_p)); - ASSERT(mwctst::ScopedLogObserverUtil::recordMessageMatch( - logObserver.records().back(), - "Queue '.*'", - s_allocator_p)); } TEST_F(Test, putAliveIdleSendAlive) @@ -442,10 +451,6 @@ TEST_F(Test, putAliveIdleSendAlive) logObserver.records().back(), "ALARM \\[QUEUE_CONSUMER_MONITOR\\]", s_allocator_p)); - ASSERT(mwctst::ScopedLogObserverUtil::recordMessageMatch( - logObserver.records().back(), - "0 consumers", - s_allocator_p)); d_monitor.onTimer(2 * k_MAX_IDLE_TIME + 2); ASSERT_EQ(d_monitor.state(mqbu::StorageKey::k_NULL_KEY), @@ -503,19 +508,7 @@ TEST_F(Test, putAliveIdleWithConsumer) ASSERT_EQ(logObserver.records().size(), ++expectedLogRecords); ASSERT(mwctst::ScopedLogObserverUtil::recordMessageMatch( logObserver.records().back(), - "ALARM \\[QUEUE_CONSUMER_MONITOR\\].*It currently has 2 consumers", - s_allocator_p)); - ASSERT(mwctst::ScopedLogObserverUtil::recordMessageMatch( - logObserver.records().back(), - "test consumer 1", - s_allocator_p)); - ASSERT(mwctst::ScopedLogObserverUtil::recordMessageMatch( - logObserver.records().back(), - "test consumer 2", - s_allocator_p)); - ASSERT(!mwctst::ScopedLogObserverUtil::recordMessageMatch( - logObserver.records().back(), - "test producer", + "ALARM \\[QUEUE_CONSUMER_MONITOR\\]", s_allocator_p)); } @@ -691,10 +684,6 @@ TEST_F(Test, putAliveIdleSendAliveTwoSubstreams) logObserver.records().rbegin()[i], "ALARM \\[QUEUE_CONSUMER_MONITOR\\]", s_allocator_p)); - ASSERT(mwctst::ScopedLogObserverUtil::recordMessageMatch( - logObserver.records().rbegin()[i], - "0 consumers", - s_allocator_p)); } d_monitor.onTimer(2 * k_MAX_IDLE_TIME + 2); @@ -797,21 +786,8 @@ TEST_F(Test, putAliveIdleSendAliveTwoSubstreamsTwoConsumers) ++iter) { ASSERT(mwctst::ScopedLogObserverUtil::recordMessageMatch( *iter, - "ALARM \\[QUEUE_CONSUMER_MONITOR\\] Queue " - "'bmq://bmq.test.local/test_queue\\?id=app\\d'", - s_allocator_p)); - ASSERT( - mwctst::ScopedLogObserverUtil::recordMessageMatch(*iter, - "1 consumers", - s_allocator_p)); - ASSERT(mwctst::ScopedLogObserverUtil::recordMessageMatch( - *iter, - "test consumer \\d", + "ALARM \\[QUEUE_CONSUMER_MONITOR\\]", s_allocator_p)); - ASSERT( - !mwctst::ScopedLogObserverUtil::recordMessageMatch(*iter, - "test producer", - s_allocator_p)); } d_monitor.onTimer(2 * k_MAX_IDLE_TIME + 2); diff --git a/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.cpp b/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.cpp index 33b1ae273..f961454c4 100644 --- a/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.cpp +++ b/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.cpp @@ -1572,7 +1572,7 @@ void RootQueueEngine::logAlarmCb( BSLS_ASSERT_SAFE(d_queueState_p->queue()->dispatcher()->inDispatcherThread( d_queueState_p->queue())); - bdlma::LocalSequentialAllocator<2048> localAllocator(0); + bdlma::LocalSequentialAllocator<4096> localAllocator(d_allocator_p); bsl::vector handles(&localAllocator); d_queueState_p->handleCatalog().loadHandles(&handles); @@ -1641,7 +1641,7 @@ void RootQueueEngine::logAlarmCb( } } - mwcu::MemOutStream out; + mwcu::MemOutStream out(&localAllocator); out << "Queue '" << uri << "' "; d_queueState_p->storage()->capacityMeter()->printShortSummary(out); out << ", max idle time " @@ -1667,58 +1667,63 @@ void RootQueueEngine::logAlarmCb( const bsl::vector& subscrGroups = routing.subscriptionGroups(); - static const size_t k_EXPR_NUM_LIMIT = 50; - if (subscrGroups.size() > k_EXPR_NUM_LIMIT) { - out << k_EXPR_NUM_LIMIT << " of " << subscrGroups.size() - << " consumer subscription expressions: " << '\n'; - } - else { - out << "Consumer subscription expressions: " << '\n'; - } - // Limit to log only k_EXPR_NUM_LIMIT expressions - size_t currNum = 0; - for (bsl::vector::const_iterator cIt = - subscrGroups.begin(); - cIt != subscrGroups.end() && currNum < k_EXPR_NUM_LIMIT; - ++cIt, ++currNum) { - out << cIt->expression() << '\n'; + if (!subscrGroups.empty()) { + static const size_t k_EXPR_NUM_LIMIT = 50; + if (subscrGroups.size() > k_EXPR_NUM_LIMIT) { + out << k_EXPR_NUM_LIMIT << " of " << subscrGroups.size() + << " consumer subscription expressions: " << '\n'; + } + else { + out << "Consumer subscription expressions: " << '\n'; + } + // Limit to log only k_EXPR_NUM_LIMIT expressions + size_t currNum = 0; + for (bsl::vector::const_iterator cIt = + subscrGroups.begin(); + cIt != subscrGroups.end() && currNum < k_EXPR_NUM_LIMIT; + ++cIt, ++currNum) { + out << cIt->expression() << '\n'; + } + out << '\n'; } - out << '\n'; // Log the first (oldest) message in Put aside list and its properties - bslma::ManagedPtr storageIt_mp; - mqbi::StorageResult::Enum rc = storage->getIterator( - &storageIt_mp, - appKey, - app->d_putAsideList.first()); - if (rc == mqbi::StorageResult::Enum::e_SUCCESS) { - // Log timestamp - out << "Oldest message in a 'Put aside' list:\n"; - mqbcmd::Result result; - mqbs::StoragePrintUtil::listMessage(&result.makeMessage(), - storage, - *storageIt_mp); - mqbcmd::HumanPrinter::print(out, result); - out << '\n'; - // Log message properties - const bsl::shared_ptr& appData = - storageIt_mp->appData(); - const bmqp::MessagePropertiesInfo& logic = - storageIt_mp->attributes().messagePropertiesInfo(); - bmqp::MessageProperties properties; - int ret = properties.streamIn(*appData, logic.isExtended()); - if (!ret) { - out << "Message Properties: " << properties << '\n'; + if (!app->d_putAsideList.empty()) { + bslma::ManagedPtr storageIt_mp; + mqbi::StorageResult::Enum rc = storage->getIterator( + &storageIt_mp, + appKey, + app->d_putAsideList.first()); + if (rc == mqbi::StorageResult::Enum::e_SUCCESS) { + // Log timestamp + out << "Oldest message in a 'Put aside' list:\n"; + mqbcmd::Result result; + mqbs::StoragePrintUtil::listMessage(&result.makeMessage(), + storage, + *storageIt_mp); + mqbcmd::HumanPrinter::print(out, result); + out << '\n'; + // Log message properties + const bsl::shared_ptr& appData = + storageIt_mp->appData(); + const bmqp::MessagePropertiesInfo& logic = + storageIt_mp->attributes().messagePropertiesInfo(); + bmqp::MessageProperties properties; + int ret = properties.streamIn(*appData, logic.isExtended()); + if (!ret) { + out << "Message Properties: " << properties << '\n'; + } + else { + BALL_LOG_WARN + << "Failed to streamIn MessageProperties, rc = " << rc; + } } else { - BALL_LOG_WARN << "Failed to streamIn MessageProperties, rc = " - << rc; + BALL_LOG_WARN << "Failed to get storage iterator for GUID: " + << app->d_putAsideList.first() + << ", rc = " << rc; } } - else { - BALL_LOG_WARN << "Failed to get storage iterator for GUID: " - << app->d_putAsideList.first() << ", rc = " << rc; - } } else { BALL_LOG_WARN << "No App found for appId: " << appId; From 763563fbd87f9a5867479b06fd62ea5523403202 Mon Sep 17 00:00:00 2001 From: Aleksandr Ivanov Date: Fri, 13 Sep 2024 13:59:00 +0300 Subject: [PATCH 07/23] Rename alarm label Signed-off-by: Aleksandr Ivanov --- .../mqb/mqbblp/mqbblp_rootqueueengine.cpp | 23 +++++++++---------- src/integration-tests/test_alarms.py | 4 ++-- .../test_reconfigure_domains.py | 4 ++-- 3 files changed, 15 insertions(+), 16 deletions(-) diff --git a/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.cpp b/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.cpp index f961454c4..564951337 100644 --- a/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.cpp +++ b/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.cpp @@ -1744,21 +1744,20 @@ void RootQueueEngine::logAlarmCb( storage); mqbcmd::HumanPrinter::print(out, result); - if (!head) { - return; // RETURN - } - - // Print the current head of the queue - out << mwcu::PrintUtil::newlineAndIndent(level, spacesPerLevel) - << "Current head of the queue:\n"; + if (head) { + // Print the current head of the queue + out << mwcu::PrintUtil::newlineAndIndent(level, spacesPerLevel) + << "Current head of the queue:\n"; - mqbs::StoragePrintUtil::listMessage(&result.makeMessage(), storage, *head); + mqbs::StoragePrintUtil::listMessage(&result.makeMessage(), + storage, + *head); - mqbcmd::HumanPrinter::print(out, result); - out << "\n"; + mqbcmd::HumanPrinter::print(out, result); + out << "\n"; + } - MWCTSK_ALARMLOG_ALARM("ROOT_QUEUE_ENGINE") - << out.str() << MWCTSK_ALARMLOG_END; + MWCTSK_ALARMLOG_ALARM("QUEUE_STUCK") << out.str() << MWCTSK_ALARMLOG_END; } void RootQueueEngine::afterAppIdRegistered( diff --git a/src/integration-tests/test_alarms.py b/src/integration-tests/test_alarms.py index 7728f99a9..0fe9d08bd 100644 --- a/src/integration-tests/test_alarms.py +++ b/src/integration-tests/test_alarms.py @@ -56,7 +56,7 @@ def test_no_alarms_for_a_slow_queue(cluster: Cluster): time.sleep(4) # First, test the alarm - assert leader.alarms("QUEUE_CONSUMER_MONITOR", 1) + assert leader.alarms("QUEUE_STUCK", 1) leader.drain() # Then test no alarm while consumer1 slowly confirms @@ -74,4 +74,4 @@ def test_no_alarms_for_a_slow_queue(cluster: Cluster): ) time.sleep(1) - assert not leader.alarms("QUEUE_CONSUMER_MONITOR", 1) + assert not leader.alarms("QUEUE_STUCK", 1) diff --git a/src/integration-tests/test_reconfigure_domains.py b/src/integration-tests/test_reconfigure_domains.py index 89aca318a..3f325cba8 100644 --- a/src/integration-tests/test_reconfigure_domains.py +++ b/src/integration-tests/test_reconfigure_domains.py @@ -254,7 +254,7 @@ def test_reconfigure_max_idle_time(self, multi_node: Cluster): # Sleep for long enough to trigger an alarm. time.sleep(1.5) - assert leader.alarms("QUEUE_CONSUMER_MONITOR", 1) + assert leader.alarms("QUEUE_STUCK", 1) # Confirm all messages in the queue. self.reader.confirm(URI_PRIORITY_1, "+2", succeed=True) @@ -277,7 +277,7 @@ def test_reconfigure_max_idle_time(self, multi_node: Cluster): self.reader.confirm(URI_PRIORITY_1, "+2", succeed=True) # Ensure that no alarm was issued. - assert not leader.alarms("QUEUE_CONSUMER_MONITOR", 1) + assert not leader.alarms("QUEUE_STUCK", 1) @tweak.domain.message_ttl(1) def test_reconfigure_message_ttl(self, multi_node: Cluster): From d092e76683ef8389031f7ede5661f22888e9a183 Mon Sep 17 00:00:00 2001 From: Aleksandr Ivanov Date: Fri, 13 Sep 2024 15:29:07 +0300 Subject: [PATCH 08/23] Remove CI debug Signed-off-by: Aleksandr Ivanov --- .github/workflows/build.yaml | 1 - 1 file changed, 1 deletion(-) diff --git a/.github/workflows/build.yaml b/.github/workflows/build.yaml index 8233734e5..dc9dc65b3 100644 --- a/.github/workflows/build.yaml +++ b/.github/workflows/build.yaml @@ -4,7 +4,6 @@ on: push: branches: - main - - enhance-alarm-log pull_request: branches: - main From d2a5164b456464de6f318b81eeba9478aad2e8ee Mon Sep 17 00:00:00 2001 From: Aleksandr Ivanov Date: Fri, 13 Sep 2024 15:44:58 +0300 Subject: [PATCH 09/23] Cleanup Signed-off-by: Aleksandr Ivanov --- .../mqb/mqbblp/mqbblp_queueconsumptionmonitor.cpp | 2 -- .../mqb/mqbblp/mqbblp_queueconsumptionmonitor.t.cpp | 13 ++++++------- src/groups/mqb/mqbblp/mqbblp_rootqueueengine.h | 1 - 3 files changed, 6 insertions(+), 10 deletions(-) diff --git a/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.cpp b/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.cpp index 7dc3a924d..c7daee29e 100644 --- a/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.cpp +++ b/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.cpp @@ -19,7 +19,6 @@ #include // MBQ #include -#include #include #include #include @@ -255,7 +254,6 @@ void QueueConsumptionMonitor::onTimer(bsls::Types::Int64 currentTimer) SubStreamInfo& info = iter->second; BSLS_ASSERT_SAFE(info.d_headCb); bslma::ManagedPtr head = info.d_headCb(); - if (head) { if (head->atEnd()) { head.reset(); diff --git a/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.t.cpp b/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.t.cpp index e3a77e840..5fd675f17 100644 --- a/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.t.cpp +++ b/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.t.cpp @@ -102,8 +102,7 @@ static void loggingCb(BSLS_ANNOTATION_UNUSED const mqbu::StorageKey& appKey, mwcu::MemOutStream out(s_allocator_p); out << "Test Alarm"; - MWCTSK_ALARMLOG_ALARM("QUEUE_CONSUMER_MONITOR") - << out.str() << MWCTSK_ALARMLOG_END; + MWCTSK_ALARMLOG_ALARM("QUEUE_STUCK") << out.str() << MWCTSK_ALARMLOG_END; } struct Test : mwctst::Test { @@ -399,7 +398,7 @@ TEST_F(Test, logFormat) ASSERT_EQ(logObserver.records().size(), 1u); ASSERT(mwctst::ScopedLogObserverUtil::recordMessageMatch( logObserver.records().back(), - "ALARM \\[QUEUE_CONSUMER_MONITOR\\]", + "ALARM \\[QUEUE_STUCK\\]", s_allocator_p)); } @@ -449,7 +448,7 @@ TEST_F(Test, putAliveIdleSendAlive) ASSERT_EQ(logObserver.records().size(), ++expectedLogRecords); ASSERT(mwctst::ScopedLogObserverUtil::recordMessageMatch( logObserver.records().back(), - "ALARM \\[QUEUE_CONSUMER_MONITOR\\]", + "ALARM \\[QUEUE_STUCK\\]", s_allocator_p)); d_monitor.onTimer(2 * k_MAX_IDLE_TIME + 2); @@ -508,7 +507,7 @@ TEST_F(Test, putAliveIdleWithConsumer) ASSERT_EQ(logObserver.records().size(), ++expectedLogRecords); ASSERT(mwctst::ScopedLogObserverUtil::recordMessageMatch( logObserver.records().back(), - "ALARM \\[QUEUE_CONSUMER_MONITOR\\]", + "ALARM \\[QUEUE_STUCK\\]", s_allocator_p)); } @@ -682,7 +681,7 @@ TEST_F(Test, putAliveIdleSendAliveTwoSubstreams) for (int i = 0; i < 2; ++i) { ASSERT(mwctst::ScopedLogObserverUtil::recordMessageMatch( logObserver.records().rbegin()[i], - "ALARM \\[QUEUE_CONSUMER_MONITOR\\]", + "ALARM \\[QUEUE_STUCK\\]", s_allocator_p)); } @@ -786,7 +785,7 @@ TEST_F(Test, putAliveIdleSendAliveTwoSubstreamsTwoConsumers) ++iter) { ASSERT(mwctst::ScopedLogObserverUtil::recordMessageMatch( *iter, - "ALARM \\[QUEUE_CONSUMER_MONITOR\\]", + "ALARM \\[QUEUE_STUCK\\]", s_allocator_p)); } diff --git a/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.h b/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.h index babe6a8c1..bcb95e6d9 100644 --- a/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.h +++ b/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.h @@ -97,7 +97,6 @@ class RootQueueEngine BSLS_KEYWORD_FINAL : public mqbi::QueueEngine { /// (appId, appKeyCount) -> AppStateSp typedef mwcc::TwoKeyHashMap Apps; - // typedef bslma::ManagedPtr StorageIteratorMp; private: // DATA From e54b1b8efef7cecd6084f75dabb7fd0372bd2d57 Mon Sep 17 00:00:00 2001 From: Aleksandr Ivanov Date: Tue, 17 Sep 2024 12:24:30 -0400 Subject: [PATCH 10/23] Fix subscription expressions printing Signed-off-by: Aleksandr Ivanov --- .../mqb/mqbblp/mqbblp_rootqueueengine.cpp | 34 +++++++++++-------- 1 file changed, 19 insertions(+), 15 deletions(-) diff --git a/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.cpp b/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.cpp index 564951337..faa6ee4a5 100644 --- a/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.cpp +++ b/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.cpp @@ -1667,24 +1667,28 @@ void RootQueueEngine::logAlarmCb( const bsl::vector& subscrGroups = routing.subscriptionGroups(); - if (!subscrGroups.empty()) { - static const size_t k_EXPR_NUM_LIMIT = 50; - if (subscrGroups.size() > k_EXPR_NUM_LIMIT) { - out << k_EXPR_NUM_LIMIT << " of " << subscrGroups.size() - << " consumer subscription expressions: " << '\n'; + // Limit to log only k_EXPR_NUM_LIMIT expressions + static const size_t k_EXPR_NUM_LIMIT = 50; + ss.reset(); + size_t exprNum = 0; + for (bsl::vector::const_iterator cIt = + subscrGroups.begin(); + cIt != subscrGroups.end() && exprNum < k_EXPR_NUM_LIMIT; + ++cIt) { + if (!cIt->expression().empty()) { + ss << cIt->expression() << '\n'; + ++exprNum; } - else { - out << "Consumer subscription expressions: " << '\n'; + } + if (exprNum) { + if (exprNum == k_EXPR_NUM_LIMIT) { + out << k_EXPR_NUM_LIMIT << " of " + << " consumer subscription expressions: "; } - // Limit to log only k_EXPR_NUM_LIMIT expressions - size_t currNum = 0; - for (bsl::vector::const_iterator cIt = - subscrGroups.begin(); - cIt != subscrGroups.end() && currNum < k_EXPR_NUM_LIMIT; - ++cIt, ++currNum) { - out << cIt->expression() << '\n'; + else { + out << "Consumer subscription expressions: "; } - out << '\n'; + out << '\n' << ss.str() << '\n'; } // Log the first (oldest) message in Put aside list and its properties From 070baeca15daf93fb30c34947e495c0e5416dfd8 Mon Sep 17 00:00:00 2001 From: Aleksandr Ivanov Date: Wed, 18 Sep 2024 11:38:43 -0400 Subject: [PATCH 11/23] Add printing of numMessages/numBytes per appId Signed-off-by: Aleksandr Ivanov --- src/groups/mqb/mqbblp/mqbblp_rootqueueengine.cpp | 10 ++++++++-- 1 file changed, 8 insertions(+), 2 deletions(-) diff --git a/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.cpp b/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.cpp index faa6ee4a5..0e3203ac1 100644 --- a/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.cpp +++ b/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.cpp @@ -1656,8 +1656,14 @@ void RootQueueEngine::logAlarmCb( Apps::const_iterator cItApp = d_apps.findByKey1(appId); if (cItApp != d_apps.end()) { const AppStateSp& app = cItApp->value(); - out << "\nPut aside list size: " << app->putAsideListSize() << '\n'; - out << "Redelivery list size: " << app->redeliveryListSize() << "\n\n"; + + out << "\nFor appId: " << appId << '\n'; + out << "Put aside list size: " << app->putAsideListSize() << '\n'; + out << "Redelivery list size: " << app->redeliveryListSize() << '\n'; + out << "Number of messages: " + << d_queueState_p->storage()->numMessages(app->d_appKey) << '\n'; + out << "Number of bytes: " + << d_queueState_p->storage()->numBytes(app->d_appKey) << "\n\n"; // Log consumer subscriptions mqbblp::Routers::QueueRoutingContext& routingContext = From d4cf81d51dd09968077b9ab9b1ff39af5121570d Mon Sep 17 00:00:00 2001 From: Aleksandr Ivanov Date: Mon, 23 Sep 2024 06:21:18 -0400 Subject: [PATCH 12/23] Get rid of headCb Signed-off-by: Aleksandr Ivanov --- .../mqbblp/mqbblp_queueconsumptionmonitor.cpp | 121 ++++---- .../mqbblp/mqbblp_queueconsumptionmonitor.h | 32 +-- .../mqb/mqbblp/mqbblp_rootqueueengine.cpp | 270 +++++++++--------- .../mqb/mqbblp/mqbblp_rootqueueengine.h | 9 +- 4 files changed, 216 insertions(+), 216 deletions(-) diff --git a/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.cpp b/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.cpp index c7daee29e..d76904d25 100644 --- a/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.cpp +++ b/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.cpp @@ -121,24 +121,21 @@ const char* QueueConsumptionMonitor::Transition::toAscii( // struct QueueConsumptionMonitor::SubStreamInfo // --------------------------------------------- -QueueConsumptionMonitor::SubStreamInfo::SubStreamInfo(const HeadCb& headCb) +QueueConsumptionMonitor::SubStreamInfo::SubStreamInfo() : d_lastKnownGoodTimer(0) , d_messageSent(true) , d_state(State::e_ALIVE) -, d_headCb(headCb) { - BSLS_ASSERT_SAFE(d_headCb); + // NOTHING } -QueueConsumptionMonitor::SubStreamInfo::SubStreamInfo( - const SubStreamInfo& other) -: d_lastKnownGoodTimer(other.d_lastKnownGoodTimer) -, d_messageSent(other.d_messageSent) -, d_state(other.d_state) -, d_headCb(other.d_headCb) -{ - BSLS_ASSERT_SAFE(d_headCb); -} +// QueueConsumptionMonitor::SubStreamInfo::SubStreamInfo( +// const SubStreamInfo& other) +// : d_lastKnownGoodTimer(other.d_lastKnownGoodTimer) +// , d_messageSent(other.d_messageSent) +// , d_state(other.d_state) +// { +// } // ----------------------------- // class QueueConsumptionMonitor @@ -175,14 +172,13 @@ QueueConsumptionMonitor::setMaxIdleTime(bsls::Types::Int64 value) last = d_subStreamInfos.end(); iter != last; ++iter) { - iter->second = SubStreamInfo(iter->second.d_headCb); + iter->second = SubStreamInfo(); } return *this; } -void QueueConsumptionMonitor::registerSubStream(const mqbu::StorageKey& key, - const HeadCb& headCb) +void QueueConsumptionMonitor::registerSubStream(const mqbu::StorageKey& key) { // Should always be called from the queue thread, but will be invoked from // the cluster thread once upon queue creation. @@ -190,12 +186,11 @@ void QueueConsumptionMonitor::registerSubStream(const mqbu::StorageKey& key, // PRECONDITIONS BSLS_ASSERT_SAFE(key != mqbu::StorageKey::k_NULL_KEY || d_subStreamInfos.empty()); - BSLS_ASSERT_SAFE(headCb); BSLS_ASSERT_SAFE(d_subStreamInfos.find(mqbu::StorageKey::k_NULL_KEY) == d_subStreamInfos.end()); BSLS_ASSERT_SAFE(d_subStreamInfos.find(key) == d_subStreamInfos.end()); - d_subStreamInfos.insert(bsl::make_pair(key, SubStreamInfo(headCb))); + d_subStreamInfos.insert(bsl::make_pair(key, SubStreamInfo())); } void QueueConsumptionMonitor::unregisterSubStream(const mqbu::StorageKey& key) @@ -228,6 +223,7 @@ void QueueConsumptionMonitor::onTimer(bsls::Types::Int64 currentTimer) // PRECONDITIONS BSLS_ASSERT_SAFE(d_queueState_p->queue()->dispatcher()->inDispatcherThread( d_queueState_p->queue())); + BSLS_ASSERT_SAFE(d_loggingCb); if (BSLS_PERFORMANCEHINT_PREDICT_UNLIKELY(d_maxIdleTime == 0)) { // monitoring is disabled @@ -238,38 +234,24 @@ void QueueConsumptionMonitor::onTimer(bsls::Types::Int64 currentTimer) BSLS_ASSERT_SAFE(currentTimer >= d_currentTimer); d_currentTimer = currentTimer; - - // TBD: 'queue empty' is not the best condition to test. The queue may - // contain messages that have been sent but not yet confirmed. A better - // test would be to check whether the message iterator in the engine points - // to the end of storage, but we don't have access to these. A solution - // would be to have QueueEngine::beforeMessageRemoved notify this monitor, - // via a new method on this component. Not implemented yet because Engines - // are about to undergo overhaul. + // BALL_LOG_WARN << "currentTimer: " << currentTimer; for (SubStreamInfoMapIter iter = d_subStreamInfos.begin(), last = d_subStreamInfos.end(); iter != last; ++iter) { - SubStreamInfo& info = iter->second; - BSLS_ASSERT_SAFE(info.d_headCb); - bslma::ManagedPtr head = info.d_headCb(); - if (head) { - if (head->atEnd()) { - head.reset(); - } - } - if (info.d_messageSent || !head) { - // Queue is 'alive' either because at least one message was sent - // since the last 'timer', or the queue is at its head (no more - // messages to deliver to this substream). + SubStreamInfo& info = iter->second; + const mqbu::StorageKey& appKey = iter->first; + if (info.d_messageSent) { + // Queue is 'alive' because at least one message was sent + // since the last 'timer'. info.d_messageSent = false; info.d_lastKnownGoodTimer = d_currentTimer; if (info.d_state == State::e_IDLE) { // object was in idle state - onTransitionToAlive(&(iter->second), iter->first); + onTransitionToAlive(&info, appKey); continue; // CONTINUE } @@ -277,17 +259,39 @@ void QueueConsumptionMonitor::onTimer(bsls::Types::Int64 currentTimer) continue; // CONTINUE } - if (info.d_state == State::e_IDLE) { - // state was already idle, nothing more to do - continue; // CONTINUE - } + // if (info.d_state == State::e_IDLE) { + // // state was already idle, nothing more to do + // continue; // CONTINUE + // } - BSLS_ASSERT_SAFE(info.d_state == State::e_ALIVE); + // BSLS_ASSERT_SAFE(info.d_state == State::e_ALIVE); if (d_currentTimer - info.d_lastKnownGoodTimer > d_maxIdleTime) { + // BALL_LOG_WARN << "Inside info.d_lastKnownGoodTimer: " << + // info.d_lastKnownGoodTimer << " State: " << info.d_state; + // No delivered messages in the last 'maxIdleTime'. - onTransitionToIdle(&(iter->second), iter->first, head); - continue; // CONTINUE + // If alive, log alarm and transition to idle + const bool queueAtHead = d_loggingCb(appKey, + info.d_state == + State::e_ALIVE); + + if (queueAtHead) { + // The queue is at its head (no more + // messages to deliver to this substream), + // so transition to alive. + if (info.d_state == State::e_IDLE) { + info.d_lastKnownGoodTimer = d_currentTimer; + onTransitionToAlive(&info, appKey); + } + } + else { + // onTransitionToIdle(&(iter->second), iter->first, head); + // There are undelivede messages, transition to idle. + if (info.d_state == State::e_ALIVE) { + info.d_state = State::e_IDLE; + } + } } } } @@ -320,23 +324,20 @@ void QueueConsumptionMonitor::onTransitionToAlive( BALL_LOG_INFO << "Queue '" << uri << "' no longer appears to be stuck."; } -void QueueConsumptionMonitor::onTransitionToIdle( - SubStreamInfo* subStreamInfo, - const mqbu::StorageKey& appKey, - const bslma::ManagedPtr& head) -{ - // executed by the *QUEUE DISPATCHER* thread - - // PRECONDITIONS - BSLS_ASSERT_SAFE(d_queueState_p->queue()->dispatcher()->inDispatcherThread( - d_queueState_p->queue())); - BSLS_ASSERT_SAFE(d_loggingCb); +// void QueueConsumptionMonitor::onTransitionToIdle( +// SubStreamInfo* subStreamInfo, +// const mqbu::StorageKey& appKey, +// const bslma::ManagedPtr& head) +// { +// // executed by the *QUEUE DISPATCHER* thread - subStreamInfo->d_state = State::e_IDLE; +// // PRECONDITIONS +// BSLS_ASSERT_SAFE(d_queueState_p->queue()->dispatcher()->inDispatcherThread( +// d_queueState_p->queue())); +// BSLS_ASSERT_SAFE(d_loggingCb); - // Call logging callback to log alarm info. - d_loggingCb(appKey, head); -} +// subStreamInfo->d_state = State::e_IDLE; +// } } // close package namespace } // close enterprise namespace diff --git a/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.h b/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.h index 63323fad6..54908be03 100644 --- a/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.h +++ b/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.h @@ -210,13 +210,10 @@ class QueueConsumptionMonitor { static const char* toAscii(Transition::Enum value); }; - typedef bsl::function(void)> - HeadCb; + // typedef bsl::function(void)> + // HeadCb; - typedef bsl::function& head)> - LoggingCb; + typedef bsl::function LoggingCb; private: // PRIVATE TYPES @@ -225,8 +222,8 @@ class QueueConsumptionMonitor { struct SubStreamInfo { // CREATORS - SubStreamInfo(const HeadCb& headCb); - SubStreamInfo(const SubStreamInfo& other); + SubStreamInfo(); + // SubStreamInfo(const SubStreamInfo& other); // PUBLIC DATA bsls::Types::Int64 d_lastKnownGoodTimer; @@ -240,7 +237,7 @@ class QueueConsumptionMonitor { State::Enum d_state; // The current state. - HeadCb d_headCb; + // HeadCb d_headCb; // Returns storage iterator to the 1st // un-delivered message including // 'put-aside' messages (those without @@ -297,10 +294,11 @@ class QueueConsumptionMonitor { /// Update the specified `subStreamInfo`, associated to the specified /// `appKey`, and write log, upon transition to idle state. - void - onTransitionToIdle(SubStreamInfo* subStreamInfo, - const mqbu::StorageKey& appKey, - const bslma::ManagedPtr& head); + // void + // onTransitionToIdle(SubStreamInfo* subStreamInfo, + // const mqbu::StorageKey& appKey, + // const bslma::ManagedPtr& + // head); public: // TRAITS @@ -330,12 +328,12 @@ class QueueConsumptionMonitor { /// this object. QueueConsumptionMonitor& setMaxIdleTime(bsls::Types::Int64 value); - /// Register the substream identified by the specified `key` and - /// consuming from the specified `storageIter` for monitoring. `key` - /// may be `StorageKey::k_NULL_KEY`, in which case no other key may be + /// Register the substream identified by the specified `key`. + /// `key` may be `StorageKey::k_NULL_KEY`, in which case no other key may + /// be /// registered via this function. It is illegal to register the same /// substream more than once. - void registerSubStream(const mqbu::StorageKey& key, const HeadCb& headCb); + void registerSubStream(const mqbu::StorageKey& key); /// Stop monitoring the substream identified by the specified `key`. /// `key` must have been previously registered via `registerSubStream`. diff --git a/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.cpp b/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.cpp index 0e3203ac1..07d79dbb4 100644 --- a/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.cpp +++ b/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.cpp @@ -147,9 +147,7 @@ RootQueueEngine::makeSubStream(const bsl::string& appId, d_allocator_p); if (hasStorage) { - d_consumptionMonitor.registerSubStream( - appKey.first, - bdlf::BindUtil::bind(&AppState::head, app.get())); + d_consumptionMonitor.registerSubStream(appKey.first); } bsl::pair rc = d_apps.insert(appId, @@ -246,12 +244,13 @@ RootQueueEngine::RootQueueEngine(QueueState* queueState, const mqbconfm::Domain& domainConfig, bslma::Allocator* allocator) : d_queueState_p(queueState) -, d_consumptionMonitor(queueState, - bdlf::BindUtil::bind(&RootQueueEngine::logAlarmCb, - this, - bdlf::PlaceHolders::_1, // appKey - bdlf::PlaceHolders::_2), // head - allocator) +, d_consumptionMonitor( + queueState, + bdlf::BindUtil::bind(&RootQueueEngine::logAlarmCb, + this, + bdlf::PlaceHolders::_1, // appKey + bdlf::PlaceHolders::_2), // isAlarm + allocator) , d_apps(allocator) , d_nullKeyCount(0) , d_hasAutoSubscriptions(false) @@ -1185,7 +1184,7 @@ void RootQueueEngine::releaseHandle( // the set of consumers for the given appId BSLS_ASSERT_SAFE(!hasHandle(subStreamInfo.appId(), handle)); } // else there are app consumers on this handle - } // else producer + } // else producer // Register/unregister both consumers and producers handle->unregisterSubStream( @@ -1562,9 +1561,8 @@ void RootQueueEngine::onTimer(bsls::Types::Int64 currentTimer) d_consumptionMonitor.onTimer(currentTimer); } -void RootQueueEngine::logAlarmCb( - const mqbu::StorageKey& appKey, - const bslma::ManagedPtr& head) const +bool RootQueueEngine::logAlarmCb(const mqbu::StorageKey& appKey, + const bool isAlarm) const { // executed by the *QUEUE DISPATCHER* thread @@ -1572,12 +1570,12 @@ void RootQueueEngine::logAlarmCb( BSLS_ASSERT_SAFE(d_queueState_p->queue()->dispatcher()->inDispatcherThread( d_queueState_p->queue())); - bdlma::LocalSequentialAllocator<4096> localAllocator(d_allocator_p); - bsl::vector handles(&localAllocator); - d_queueState_p->handleCatalog().loadHandles(&handles); + // By default assume queue is at head. + bool queueAtHead = true; - bmqt::UriBuilder uriBuilder(d_queueState_p->uri(), &localAllocator); - bsl::string appId; + // Construct AppId from appKey + bmqt::UriBuilder uriBuilder(d_queueState_p->uri(), d_allocator_p); + bsl::string appId(d_allocator_p); if (appKey.isNull()) { appId = bmqp::ProtocolUtil::k_DEFAULT_APP_ID; @@ -1586,57 +1584,71 @@ void RootQueueEngine::logAlarmCb( uriBuilder.setId(appId); } + // Get AppState by appId. + Apps::const_iterator cItApp = d_apps.findByKey1(appId); + if (cItApp == d_apps.end()) { + BALL_LOG_WARN << "No app found for appId: " << appId; + return queueAtHead; // RETURN + } + const AppStateSp& app = cItApp->value(); + + bslma::ManagedPtr head = app->head(); + // Return if there are no un-delivered messages + if (!head) { + return queueAtHead; // RETURN + } + + queueAtHead = false; + + // If queue state is not alive, don't log alarm + if (!isAlarm) { + return queueAtHead; // RETURN + } + + bdlma::LocalSequentialAllocator<4096> localAllocator(d_allocator_p); + bmqt::Uri uri(&localAllocator); uriBuilder.uri(&uri); mwcu::MemOutStream ss(&localAllocator); + // Print app consumers queue handles info int idx = 1; int numConsumers = 0; - for (bsl::vector::const_iterator it = handles.begin(), - last = handles.end(); - it != last; - ++it) { + QueueEngineUtil_AppState::Consumers& consumers = app->consumers(); + for (QueueEngineUtil_AppState::Consumers::const_iterator itConsumer = + consumers.begin(); + itConsumer != consumers.end(); + ++itConsumer) { + mqbi::QueueHandle* queueHandle_p = itConsumer->first; + const mqbi::QueueHandle::SubStreams& subStreamInfos = - (*it)->subStreamInfos(); + queueHandle_p->subStreamInfos(); for (mqbi::QueueHandle::SubStreams::const_iterator infoCiter = subStreamInfos.begin(); infoCiter != subStreamInfos.end(); ++infoCiter) { - const bsl::string& itemAppId = infoCiter->first; - - bool isReader = !d_isFanout && - bmqt::QueueFlagsUtil::isReader( - (*it)->handleParameters().flags()); - // Non-fanout mode consumer in the default subStream ? - isReader |= d_isFanout && !itemAppId.empty(); - - if (!isReader) { - continue; // CONTINUE - } - - if (itemAppId != appId) { - continue; // CONTINUE - } - numConsumers += infoCiter->second.d_counts.d_readCount; const int level = 2, spacesPerLevel = 2; - ss << "\n " << idx++ << ". " << (*it)->client()->description() + ss << "\n " << idx++ << ". " + << queueHandle_p->client()->description() << mwcu::PrintUtil::newlineAndIndent(level, spacesPerLevel) - << "Handle Parameters .....: " << (*it)->handleParameters() + << "Handle Parameters .....: " + << queueHandle_p->handleParameters() << mwcu::PrintUtil::newlineAndIndent(level, spacesPerLevel) - << "Unconfirmed messages count: " << (*it)->countUnconfirmed() + << "Unconfirmed messages count: " + << queueHandle_p->countUnconfirmed() << mwcu::PrintUtil::newlineAndIndent(level, spacesPerLevel) << "UnconfirmedMonitors ....:"; const bsl::vector monitors = - (*it)->unconfirmedMonitors(appId); + queueHandle_p->unconfirmedMonitors(appId); for (size_t i = 0; i < monitors.size(); ++i) { - ss << "\n " << monitors[i]; + ss << "\n " << *monitors[i]; } } } @@ -1653,90 +1665,84 @@ void RootQueueEngine::logAlarmCb( mqbi::Storage* const storage = d_queueState_p->storage(); - Apps::const_iterator cItApp = d_apps.findByKey1(appId); - if (cItApp != d_apps.end()) { - const AppStateSp& app = cItApp->value(); - - out << "\nFor appId: " << appId << '\n'; - out << "Put aside list size: " << app->putAsideListSize() << '\n'; - out << "Redelivery list size: " << app->redeliveryListSize() << '\n'; - out << "Number of messages: " - << d_queueState_p->storage()->numMessages(app->d_appKey) << '\n'; - out << "Number of bytes: " - << d_queueState_p->storage()->numBytes(app->d_appKey) << "\n\n"; - - // Log consumer subscriptions - mqbblp::Routers::QueueRoutingContext& routingContext = - app->d_routing_sp->d_queue; - mqbcmd::Routing routing; - routingContext.loadInternals(&routing); - const bsl::vector& subscrGroups = - routing.subscriptionGroups(); - - // Limit to log only k_EXPR_NUM_LIMIT expressions - static const size_t k_EXPR_NUM_LIMIT = 50; - ss.reset(); - size_t exprNum = 0; - for (bsl::vector::const_iterator cIt = - subscrGroups.begin(); - cIt != subscrGroups.end() && exprNum < k_EXPR_NUM_LIMIT; - ++cIt) { - if (!cIt->expression().empty()) { - ss << cIt->expression() << '\n'; - ++exprNum; - } + // Apps::const_iterator cItApp = d_apps.findByKey1(appId); + // const AppStateSp& app = cItApp->value(); + + out << "\nFor appId: " << appId << '\n'; + out << "Put aside list size: " << app->putAsideListSize() << '\n'; + out << "Redelivery list size: " << app->redeliveryListSize() << '\n'; + out << "Number of messages: " + << d_queueState_p->storage()->numMessages(app->d_appKey) << '\n'; + out << "Number of bytes: " + << d_queueState_p->storage()->numBytes(app->d_appKey) << "\n\n"; + + // Log consumer subscriptions + mqbblp::Routers::QueueRoutingContext& routingContext = + app->d_routing_sp->d_queue; + mqbcmd::Routing routing; + routingContext.loadInternals(&routing); + const bsl::vector& subscrGroups = + routing.subscriptionGroups(); + + // Limit to log only k_EXPR_NUM_LIMIT expressions + static const size_t k_EXPR_NUM_LIMIT = 50; + ss.reset(); + size_t exprNum = 0; + for (bsl::vector::const_iterator cIt = + subscrGroups.begin(); + cIt != subscrGroups.end() && exprNum < k_EXPR_NUM_LIMIT; + ++cIt) { + if (!cIt->expression().empty()) { + ss << cIt->expression() << '\n'; + ++exprNum; } - if (exprNum) { - if (exprNum == k_EXPR_NUM_LIMIT) { - out << k_EXPR_NUM_LIMIT << " of " - << " consumer subscription expressions: "; - } - else { - out << "Consumer subscription expressions: "; - } - out << '\n' << ss.str() << '\n'; + } + if (exprNum) { + if (exprNum == k_EXPR_NUM_LIMIT) { + out << k_EXPR_NUM_LIMIT << " of " + << " consumer subscription expressions: "; } + else { + out << "Consumer subscription expressions: "; + } + out << '\n' << ss.str() << '\n'; + } - // Log the first (oldest) message in Put aside list and its properties - if (!app->d_putAsideList.empty()) { - bslma::ManagedPtr storageIt_mp; - mqbi::StorageResult::Enum rc = storage->getIterator( - &storageIt_mp, - appKey, - app->d_putAsideList.first()); - if (rc == mqbi::StorageResult::Enum::e_SUCCESS) { - // Log timestamp - out << "Oldest message in a 'Put aside' list:\n"; - mqbcmd::Result result; - mqbs::StoragePrintUtil::listMessage(&result.makeMessage(), - storage, - *storageIt_mp); - mqbcmd::HumanPrinter::print(out, result); - out << '\n'; - // Log message properties - const bsl::shared_ptr& appData = - storageIt_mp->appData(); - const bmqp::MessagePropertiesInfo& logic = - storageIt_mp->attributes().messagePropertiesInfo(); - bmqp::MessageProperties properties; - int ret = properties.streamIn(*appData, logic.isExtended()); - if (!ret) { - out << "Message Properties: " << properties << '\n'; - } - else { - BALL_LOG_WARN - << "Failed to streamIn MessageProperties, rc = " << rc; - } + // Log the first (oldest) message in Put aside list and its properties + if (!app->d_putAsideList.empty()) { + bslma::ManagedPtr storageIt_mp; + mqbi::StorageResult::Enum rc = storage->getIterator( + &storageIt_mp, + appKey, + app->d_putAsideList.first()); + if (rc == mqbi::StorageResult::Enum::e_SUCCESS) { + // Log timestamp + out << "Oldest message in a 'Put aside' list:\n"; + mqbcmd::Result result; + mqbs::StoragePrintUtil::listMessage(&result.makeMessage(), + storage, + *storageIt_mp); + mqbcmd::HumanPrinter::print(out, result); + out << '\n'; + // Log message properties + const bsl::shared_ptr& appData = + storageIt_mp->appData(); + const bmqp::MessagePropertiesInfo& logic = + storageIt_mp->attributes().messagePropertiesInfo(); + bmqp::MessageProperties properties; + int ret = properties.streamIn(*appData, logic.isExtended()); + if (!ret) { + out << "Message Properties: " << properties << '\n'; } else { - BALL_LOG_WARN << "Failed to get storage iterator for GUID: " - << app->d_putAsideList.first() - << ", rc = " << rc; + BALL_LOG_WARN << "Failed to streamIn MessageProperties, rc = " + << rc; } } - } - else { - BALL_LOG_WARN << "No App found for appId: " << appId; + else { + BALL_LOG_WARN << "Failed to get storage iterator for GUID: " + << app->d_putAsideList.first() << ", rc = " << rc; + } } // Print the 10 oldest messages in the queue @@ -1754,20 +1760,18 @@ void RootQueueEngine::logAlarmCb( storage); mqbcmd::HumanPrinter::print(out, result); - if (head) { - // Print the current head of the queue - out << mwcu::PrintUtil::newlineAndIndent(level, spacesPerLevel) - << "Current head of the queue:\n"; + // Print the current head of the queue + out << mwcu::PrintUtil::newlineAndIndent(level, spacesPerLevel) + << "Current head of the queue:\n"; - mqbs::StoragePrintUtil::listMessage(&result.makeMessage(), - storage, - *head); + mqbs::StoragePrintUtil::listMessage(&result.makeMessage(), storage, *head); - mqbcmd::HumanPrinter::print(out, result); - out << "\n"; - } + mqbcmd::HumanPrinter::print(out, result); + out << "\n"; MWCTSK_ALARMLOG_ALARM("QUEUE_STUCK") << out.str() << MWCTSK_ALARMLOG_END; + + return queueAtHead; } void RootQueueEngine::afterAppIdRegistered( @@ -1880,9 +1884,7 @@ void RootQueueEngine::afterAppIdRegistered( bslma::ManagedPtr storageIterMp; storageIterMp = d_queueState_p->storage()->getIterator(iter->key2().first); - d_consumptionMonitor.registerSubStream( - key, - bdlf::BindUtil::bind(&AppState::head, iter->value())); + d_consumptionMonitor.registerSubStream(key); iter->value()->d_storageIter_mp = storageIterMp; } diff --git a/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.h b/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.h index bcb95e6d9..f2a876ed2 100644 --- a/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.h +++ b/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.h @@ -202,11 +202,10 @@ class RootQueueEngine BSLS_KEYWORD_FINAL : public mqbi::QueueEngine { const AppStateSp& subQueue(unsigned int upstreamSubQueueId) const; - /// Callback called by `d_consumptionMonitor` when alarm is detected. - /// It logs queue data for the specified `appKey` and `head`. - void - logAlarmCb(const mqbu::StorageKey& appKey, - const bslma::ManagedPtr& head) const; + /// Callback called by `d_consumptionMonitor` when alarm condition is met. + /// If the queue is at its head for the specified `appKey` it logs queue + /// alarm data. Returns `true` if alarm was logged and `false` otherwise. + bool logAlarmCb(const mqbu::StorageKey& appKey, const bool isAlarm) const; public: // TRAITS From 1982cc20e1513acd432025101fc69c6b427e0e5c Mon Sep 17 00:00:00 2001 From: Aleksandr Ivanov Date: Mon, 23 Sep 2024 06:55:09 -0400 Subject: [PATCH 13/23] Fix UT Signed-off-by: Aleksandr Ivanov --- .../mqbblp_queueconsumptionmonitor.t.cpp | 92 +++++++++---------- 1 file changed, 41 insertions(+), 51 deletions(-) diff --git a/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.t.cpp b/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.t.cpp index 5fd675f17..2c5bad073 100644 --- a/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.t.cpp +++ b/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.t.cpp @@ -94,17 +94,6 @@ ClientContext::~ClientContext() // NOTHING } -static void loggingCb(BSLS_ANNOTATION_UNUSED const mqbu::StorageKey& appKey, - BSLS_ANNOTATION_UNUSED const - bslma::ManagedPtr& head) -{ - BALL_LOG_SET_CATEGORY("MQBBLP.QUEUECONSUMPTIONMONITORTEST"); - - mwcu::MemOutStream out(s_allocator_p); - out << "Test Alarm"; - MWCTSK_ALARMLOG_ALARM("QUEUE_STUCK") << out.str() << MWCTSK_ALARMLOG_END; -} - struct Test : mwctst::Test { typedef bsl::vector< bsl::pair > @@ -143,8 +132,10 @@ struct Test : mwctst::Test { const bsl::string& appId = bmqp::ProtocolUtil::k_DEFAULT_APP_ID, unsigned int subQueueId = bmqp::QueueId::k_DEFAULT_SUBQUEUE_ID); - bslma::ManagedPtr head(const mqbu::StorageKey& key); + // bslma::ManagedPtr head(const mqbu::StorageKey& key); void advance(const mqbu::StorageKey& key); + bool loggingCb(const mqbu::StorageKey& appKey, const bool isAlarm); + }; Test::Test() @@ -164,7 +155,13 @@ Test::Test() d_partitionId, &d_domain, s_allocator_p) -, d_monitor(&d_queueState, &loggingCb, s_allocator_p) +, d_monitor(&d_queueState, + bdlf::BindUtil::bind(&Test::loggingCb, + this, + bdlf::PlaceHolders::_1, // appKey + bdlf::PlaceHolders::_2), // isAlarm + + s_allocator_p) , d_storage(d_queue.uri(), mqbu::StorageKey::k_NULL_KEY, mqbs::DataStore::k_INVALID_PARTITION_ID, @@ -287,24 +284,30 @@ mqbi::QueueHandle* Test::createClient(const ClientContext& clientContext, return queueHandle; } -bslma::ManagedPtr -Test::head(const mqbu::StorageKey& key) +void Test::advance(const mqbu::StorageKey& key) { - bslma::ManagedPtr out; - out = d_storage.getIterator(key); - for (int i = 0; i < d_advance[key]; ++i) { - if (!out->atEnd()) { - out->advance(); - } - } - return out; + ++d_advance[key]; } -void Test::advance(const mqbu::StorageKey& key) +bool Test::loggingCb(BSLS_ANNOTATION_UNUSED const mqbu::StorageKey& appKey, BSLS_ANNOTATION_UNUSED const bool isAlarm) { - ++d_advance[key]; + BALL_LOG_SET_CATEGORY("MQBBLP.QUEUECONSUMPTIONMONITORTEST"); + + bslma::ManagedPtr out; + out = d_storage.getIterator(appKey); + + bool queueAtHead = out->atEnd(); + + if (isAlarm && !queueAtHead) { + mwcu::MemOutStream out(s_allocator_p); + out << "Test Alarm"; + MWCTSK_ALARMLOG_ALARM("QUEUE_STUCK") << out.str() << MWCTSK_ALARMLOG_END; + } + + return queueAtHead; } + // ============================================================================ // TESTS // ---------------------------------------------------------------------------- @@ -323,8 +326,7 @@ TEST_F(Test, doNotMonitor) mwctst::ScopedLogObserver observer(ball::Severity::INFO, s_allocator_p); d_monitor.registerSubStream( - mqbu::StorageKey::k_NULL_KEY, - bdlf::BindUtil::bind(&Test::head, this, mqbu::StorageKey::k_NULL_KEY)); + mqbu::StorageKey::k_NULL_KEY); ASSERT_EQ(d_monitor.state(mqbu::StorageKey::k_NULL_KEY), QueueConsumptionMonitor::State::e_ALIVE); @@ -355,8 +357,7 @@ TEST_F(Test, emptyQueue) d_monitor.setMaxIdleTime(k_MAX_IDLE_TIME); d_monitor.registerSubStream( - mqbu::StorageKey::k_NULL_KEY, - bdlf::BindUtil::bind(&Test::head, this, mqbu::StorageKey::k_NULL_KEY)); + mqbu::StorageKey::k_NULL_KEY); d_monitor.onTimer(k_MAX_IDLE_TIME); ASSERT_EQ(d_monitor.state(mqbu::StorageKey::k_NULL_KEY), @@ -388,8 +389,7 @@ TEST_F(Test, logFormat) d_monitor.setMaxIdleTime(k_MAX_IDLE_TIME); d_monitor.registerSubStream( - mqbu::StorageKey::k_NULL_KEY, - bdlf::BindUtil::bind(&Test::head, this, mqbu::StorageKey::k_NULL_KEY)); + mqbu::StorageKey::k_NULL_KEY); putMessage(); @@ -422,8 +422,7 @@ TEST_F(Test, putAliveIdleSendAlive) d_monitor.setMaxIdleTime(k_MAX_IDLE_TIME); d_monitor.registerSubStream( - mqbu::StorageKey::k_NULL_KEY, - bdlf::BindUtil::bind(&Test::head, this, mqbu::StorageKey::k_NULL_KEY)); + mqbu::StorageKey::k_NULL_KEY); putMessage(); @@ -487,8 +486,7 @@ TEST_F(Test, putAliveIdleWithConsumer) d_monitor.setMaxIdleTime(k_MAX_IDLE_TIME); d_monitor.registerSubStream( - mqbu::StorageKey::k_NULL_KEY, - bdlf::BindUtil::bind(&Test::head, this, mqbu::StorageKey::k_NULL_KEY)); + mqbu::StorageKey::k_NULL_KEY); createClient(d_consumer1, bmqt::QueueFlags::e_READ); createClient(d_consumer2, bmqt::QueueFlags::e_READ); @@ -525,8 +523,7 @@ TEST_F(Test, putAliveIdleEmptyAlive) d_monitor.setMaxIdleTime(k_MAX_IDLE_TIME); d_monitor.registerSubStream( - mqbu::StorageKey::k_NULL_KEY, - bdlf::BindUtil::bind(&Test::head, this, mqbu::StorageKey::k_NULL_KEY)); + mqbu::StorageKey::k_NULL_KEY); putMessage(); d_monitor.onTimer(k_MAX_IDLE_TIME); @@ -559,8 +556,7 @@ TEST_F(Test, changeMaxIdleTime) d_monitor.setMaxIdleTime(k_MAX_IDLE_TIME); d_monitor.registerSubStream( - mqbu::StorageKey::k_NULL_KEY, - bdlf::BindUtil::bind(&Test::head, this, mqbu::StorageKey::k_NULL_KEY)); + mqbu::StorageKey::k_NULL_KEY); putMessage(); @@ -606,8 +602,7 @@ TEST_F(Test, reset) d_monitor.setMaxIdleTime(k_MAX_IDLE_TIME); d_monitor.registerSubStream( - mqbu::StorageKey::k_NULL_KEY, - bdlf::BindUtil::bind(&Test::head, this, mqbu::StorageKey::k_NULL_KEY)); + mqbu::StorageKey::k_NULL_KEY); putMessage(); @@ -649,11 +644,9 @@ TEST_F(Test, putAliveIdleSendAliveTwoSubstreams) d_storage.addVirtualStorage(errorDescription, "app1", key1); d_storage.addVirtualStorage(errorDescription, "app2", key2); - d_monitor.registerSubStream(key1, - bdlf::BindUtil::bind(&Test::head, this, key1)); + d_monitor.registerSubStream(key1); - d_monitor.registerSubStream(key2, - bdlf::BindUtil::bind(&Test::head, this, key2)); + d_monitor.registerSubStream(key2); putMessage(); @@ -746,11 +739,9 @@ TEST_F(Test, putAliveIdleSendAliveTwoSubstreamsTwoConsumers) d_storage.addVirtualStorage(errorDescription, "app1", key1); d_storage.addVirtualStorage(errorDescription, "app2", key2); - d_monitor.registerSubStream(key1, - bdlf::BindUtil::bind(&Test::head, this, key1)); + d_monitor.registerSubStream(key1); - d_monitor.registerSubStream(key2, - bdlf::BindUtil::bind(&Test::head, this, key2)); + d_monitor.registerSubStream(key2); createClient(d_consumer1, bmqt::QueueFlags::e_READ, "app1"); createClient(d_consumer2, bmqt::QueueFlags::e_READ, "app2"); @@ -837,8 +828,7 @@ TEST_F(Test, usage) monitor.setMaxIdleTime(20); d_monitor.registerSubStream( - mqbu::StorageKey::k_NULL_KEY, - bdlf::BindUtil::bind(&Test::head, this, mqbu::StorageKey::k_NULL_KEY)); + mqbu::StorageKey::k_NULL_KEY); putMessage(); putMessage(); From 76744dfdaa170f7b40ca5656267d9ec8e4214863 Mon Sep 17 00:00:00 2001 From: Aleksandr Ivanov Date: Tue, 24 Sep 2024 12:26:07 +0300 Subject: [PATCH 14/23] Cleanup Signed-off-by: Aleksandr Ivanov --- .../mqbblp/mqbblp_queueconsumptionmonitor.cpp | 58 ++++--------------- .../mqbblp/mqbblp_queueconsumptionmonitor.h | 27 ++------- .../mqbblp_queueconsumptionmonitor.t.cpp | 51 +++++++--------- .../mqb/mqbblp/mqbblp_rootqueueengine.cpp | 55 ++++++++---------- .../mqb/mqbblp/mqbblp_rootqueueengine.h | 8 ++- 5 files changed, 66 insertions(+), 133 deletions(-) diff --git a/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.cpp b/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.cpp index d76904d25..a10f4359f 100644 --- a/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.cpp +++ b/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.cpp @@ -129,14 +129,6 @@ QueueConsumptionMonitor::SubStreamInfo::SubStreamInfo() // NOTHING } -// QueueConsumptionMonitor::SubStreamInfo::SubStreamInfo( -// const SubStreamInfo& other) -// : d_lastKnownGoodTimer(other.d_lastKnownGoodTimer) -// , d_messageSent(other.d_messageSent) -// , d_state(other.d_state) -// { -// } - // ----------------------------- // class QueueConsumptionMonitor // ----------------------------- @@ -234,7 +226,6 @@ void QueueConsumptionMonitor::onTimer(bsls::Types::Int64 currentTimer) BSLS_ASSERT_SAFE(currentTimer >= d_currentTimer); d_currentTimer = currentTimer; - // BALL_LOG_WARN << "currentTimer: " << currentTimer; for (SubStreamInfoMapIter iter = d_subStreamInfos.begin(), last = d_subStreamInfos.end(); @@ -259,24 +250,21 @@ void QueueConsumptionMonitor::onTimer(bsls::Types::Int64 currentTimer) continue; // CONTINUE } - // if (info.d_state == State::e_IDLE) { - // // state was already idle, nothing more to do - // continue; // CONTINUE - // } - - // BSLS_ASSERT_SAFE(info.d_state == State::e_ALIVE); - if (d_currentTimer - info.d_lastKnownGoodTimer > d_maxIdleTime) { - // BALL_LOG_WARN << "Inside info.d_lastKnownGoodTimer: " << - // info.d_lastKnownGoodTimer << " State: " << info.d_state; - // No delivered messages in the last 'maxIdleTime'. - // If alive, log alarm and transition to idle - const bool queueAtHead = d_loggingCb(appKey, - info.d_state == - State::e_ALIVE); - if (queueAtHead) { + // Call callback to log alarm if there are undelivered messages. + const bool haveUndelivered = d_loggingCb(appKey, + info.d_state == + State::e_ALIVE); + + if (haveUndelivered) { + // There are undelivered messages, transition to idle. + if (info.d_state == State::e_ALIVE) { + info.d_state = State::e_IDLE; + } + } + else { // The queue is at its head (no more // messages to deliver to this substream), // so transition to alive. @@ -285,13 +273,6 @@ void QueueConsumptionMonitor::onTimer(bsls::Types::Int64 currentTimer) onTransitionToAlive(&info, appKey); } } - else { - // onTransitionToIdle(&(iter->second), iter->first, head); - // There are undelivede messages, transition to idle. - if (info.d_state == State::e_ALIVE) { - info.d_state = State::e_IDLE; - } - } } } } @@ -324,20 +305,5 @@ void QueueConsumptionMonitor::onTransitionToAlive( BALL_LOG_INFO << "Queue '" << uri << "' no longer appears to be stuck."; } -// void QueueConsumptionMonitor::onTransitionToIdle( -// SubStreamInfo* subStreamInfo, -// const mqbu::StorageKey& appKey, -// const bslma::ManagedPtr& head) -// { -// // executed by the *QUEUE DISPATCHER* thread - -// // PRECONDITIONS -// BSLS_ASSERT_SAFE(d_queueState_p->queue()->dispatcher()->inDispatcherThread( -// d_queueState_p->queue())); -// BSLS_ASSERT_SAFE(d_loggingCb); - -// subStreamInfo->d_state = State::e_IDLE; -// } - } // close package namespace } // close enterprise namespace diff --git a/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.h b/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.h index 54908be03..561672dab 100644 --- a/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.h +++ b/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.h @@ -210,9 +210,6 @@ class QueueConsumptionMonitor { static const char* toAscii(Transition::Enum value); }; - // typedef bsl::function(void)> - // HeadCb; - typedef bsl::function LoggingCb; private: @@ -223,7 +220,6 @@ class QueueConsumptionMonitor { // CREATORS SubStreamInfo(); - // SubStreamInfo(const SubStreamInfo& other); // PUBLIC DATA bsls::Types::Int64 d_lastKnownGoodTimer; @@ -236,12 +232,6 @@ class QueueConsumptionMonitor { // the last time slice State::Enum d_state; // The current state. - - // HeadCb d_headCb; - // Returns storage iterator to the 1st - // un-delivered message including - // 'put-aside' messages (those without - // matching Subscriptions). }; typedef bsl::unordered_map& - // head); - public: // TRAITS BSLMF_NESTED_TRAIT_DECLARATION(QueueConsumptionMonitor, diff --git a/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.t.cpp b/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.t.cpp index 2c5bad073..2c1dd80d4 100644 --- a/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.t.cpp +++ b/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.t.cpp @@ -132,10 +132,8 @@ struct Test : mwctst::Test { const bsl::string& appId = bmqp::ProtocolUtil::k_DEFAULT_APP_ID, unsigned int subQueueId = bmqp::QueueId::k_DEFAULT_SUBQUEUE_ID); - // bslma::ManagedPtr head(const mqbu::StorageKey& key); void advance(const mqbu::StorageKey& key); bool loggingCb(const mqbu::StorageKey& appKey, const bool isAlarm); - }; Test::Test() @@ -156,12 +154,12 @@ Test::Test() &d_domain, s_allocator_p) , d_monitor(&d_queueState, - bdlf::BindUtil::bind(&Test::loggingCb, - this, - bdlf::PlaceHolders::_1, // appKey - bdlf::PlaceHolders::_2), // isAlarm + bdlf::BindUtil::bind(&Test::loggingCb, + this, + bdlf::PlaceHolders::_1, // appKey + bdlf::PlaceHolders::_2), // isAlarm - s_allocator_p) + s_allocator_p) , d_storage(d_queue.uri(), mqbu::StorageKey::k_NULL_KEY, mqbs::DataStore::k_INVALID_PARTITION_ID, @@ -289,25 +287,25 @@ void Test::advance(const mqbu::StorageKey& key) ++d_advance[key]; } -bool Test::loggingCb(BSLS_ANNOTATION_UNUSED const mqbu::StorageKey& appKey, BSLS_ANNOTATION_UNUSED const bool isAlarm) +bool Test::loggingCb(const mqbu::StorageKey& appKey, const bool enableLog) { BALL_LOG_SET_CATEGORY("MQBBLP.QUEUECONSUMPTIONMONITORTEST"); bslma::ManagedPtr out; out = d_storage.getIterator(appKey); - bool queueAtHead = out->atEnd(); + bool haveUndelivered = !out->atEnd(); - if (isAlarm && !queueAtHead) { + if (enableLog && haveUndelivered) { mwcu::MemOutStream out(s_allocator_p); out << "Test Alarm"; - MWCTSK_ALARMLOG_ALARM("QUEUE_STUCK") << out.str() << MWCTSK_ALARMLOG_END; + MWCTSK_ALARMLOG_ALARM("QUEUE_STUCK") + << out.str() << MWCTSK_ALARMLOG_END; } - return queueAtHead; + return haveUndelivered; } - // ============================================================================ // TESTS // ---------------------------------------------------------------------------- @@ -325,8 +323,7 @@ TEST_F(Test, doNotMonitor) mwctst::ScopedLogObserver observer(ball::Severity::INFO, s_allocator_p); - d_monitor.registerSubStream( - mqbu::StorageKey::k_NULL_KEY); + d_monitor.registerSubStream(mqbu::StorageKey::k_NULL_KEY); ASSERT_EQ(d_monitor.state(mqbu::StorageKey::k_NULL_KEY), QueueConsumptionMonitor::State::e_ALIVE); @@ -356,8 +353,7 @@ TEST_F(Test, emptyQueue) d_monitor.setMaxIdleTime(k_MAX_IDLE_TIME); - d_monitor.registerSubStream( - mqbu::StorageKey::k_NULL_KEY); + d_monitor.registerSubStream(mqbu::StorageKey::k_NULL_KEY); d_monitor.onTimer(k_MAX_IDLE_TIME); ASSERT_EQ(d_monitor.state(mqbu::StorageKey::k_NULL_KEY), @@ -388,8 +384,7 @@ TEST_F(Test, logFormat) d_monitor.setMaxIdleTime(k_MAX_IDLE_TIME); - d_monitor.registerSubStream( - mqbu::StorageKey::k_NULL_KEY); + d_monitor.registerSubStream(mqbu::StorageKey::k_NULL_KEY); putMessage(); @@ -421,8 +416,7 @@ TEST_F(Test, putAliveIdleSendAlive) d_monitor.setMaxIdleTime(k_MAX_IDLE_TIME); - d_monitor.registerSubStream( - mqbu::StorageKey::k_NULL_KEY); + d_monitor.registerSubStream(mqbu::StorageKey::k_NULL_KEY); putMessage(); @@ -485,8 +479,7 @@ TEST_F(Test, putAliveIdleWithConsumer) const bsls::Types::Int64 k_MAX_IDLE_TIME = 10; d_monitor.setMaxIdleTime(k_MAX_IDLE_TIME); - d_monitor.registerSubStream( - mqbu::StorageKey::k_NULL_KEY); + d_monitor.registerSubStream(mqbu::StorageKey::k_NULL_KEY); createClient(d_consumer1, bmqt::QueueFlags::e_READ); createClient(d_consumer2, bmqt::QueueFlags::e_READ); @@ -522,8 +515,7 @@ TEST_F(Test, putAliveIdleEmptyAlive) d_monitor.setMaxIdleTime(k_MAX_IDLE_TIME); - d_monitor.registerSubStream( - mqbu::StorageKey::k_NULL_KEY); + d_monitor.registerSubStream(mqbu::StorageKey::k_NULL_KEY); putMessage(); d_monitor.onTimer(k_MAX_IDLE_TIME); @@ -555,8 +547,7 @@ TEST_F(Test, changeMaxIdleTime) d_monitor.setMaxIdleTime(k_MAX_IDLE_TIME); - d_monitor.registerSubStream( - mqbu::StorageKey::k_NULL_KEY); + d_monitor.registerSubStream(mqbu::StorageKey::k_NULL_KEY); putMessage(); @@ -601,8 +592,7 @@ TEST_F(Test, reset) d_monitor.setMaxIdleTime(k_MAX_IDLE_TIME); - d_monitor.registerSubStream( - mqbu::StorageKey::k_NULL_KEY); + d_monitor.registerSubStream(mqbu::StorageKey::k_NULL_KEY); putMessage(); @@ -827,8 +817,7 @@ TEST_F(Test, usage) monitor.setMaxIdleTime(20); - d_monitor.registerSubStream( - mqbu::StorageKey::k_NULL_KEY); + d_monitor.registerSubStream(mqbu::StorageKey::k_NULL_KEY); putMessage(); putMessage(); diff --git a/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.cpp b/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.cpp index 07d79dbb4..02b67a968 100644 --- a/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.cpp +++ b/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.cpp @@ -249,7 +249,7 @@ RootQueueEngine::RootQueueEngine(QueueState* queueState, bdlf::BindUtil::bind(&RootQueueEngine::logAlarmCb, this, bdlf::PlaceHolders::_1, // appKey - bdlf::PlaceHolders::_2), // isAlarm + bdlf::PlaceHolders::_2), // enableLog allocator) , d_apps(allocator) , d_nullKeyCount(0) @@ -1184,7 +1184,7 @@ void RootQueueEngine::releaseHandle( // the set of consumers for the given appId BSLS_ASSERT_SAFE(!hasHandle(subStreamInfo.appId(), handle)); } // else there are app consumers on this handle - } // else producer + } // else producer // Register/unregister both consumers and producers handle->unregisterSubStream( @@ -1562,7 +1562,7 @@ void RootQueueEngine::onTimer(bsls::Types::Int64 currentTimer) } bool RootQueueEngine::logAlarmCb(const mqbu::StorageKey& appKey, - const bool isAlarm) const + const bool enableLog) const { // executed by the *QUEUE DISPATCHER* thread @@ -1570,9 +1570,6 @@ bool RootQueueEngine::logAlarmCb(const mqbu::StorageKey& appKey, BSLS_ASSERT_SAFE(d_queueState_p->queue()->dispatcher()->inDispatcherThread( d_queueState_p->queue())); - // By default assume queue is at head. - bool queueAtHead = true; - // Construct AppId from appKey bmqt::UriBuilder uriBuilder(d_queueState_p->uri(), d_allocator_p); bsl::string appId(d_allocator_p); @@ -1588,23 +1585,22 @@ bool RootQueueEngine::logAlarmCb(const mqbu::StorageKey& appKey, Apps::const_iterator cItApp = d_apps.findByKey1(appId); if (cItApp == d_apps.end()) { BALL_LOG_WARN << "No app found for appId: " << appId; - return queueAtHead; // RETURN + return false; // RETURN } const AppStateSp& app = cItApp->value(); + // Check if there are un-delivered messages bslma::ManagedPtr head = app->head(); - // Return if there are no un-delivered messages if (!head) { - return queueAtHead; // RETURN + // No un-delivered messages, do nothing. + return false; // RETURN } - - queueAtHead = false; - - // If queue state is not alive, don't log alarm - if (!isAlarm) { - return queueAtHead; // RETURN + else if (!enableLog) { + // There are un-delivered messages, but log is disabled. + return true; // RETURN } + // Logging alarm info bdlma::LocalSequentialAllocator<4096> localAllocator(d_allocator_p); bmqt::Uri uri(&localAllocator); @@ -1612,25 +1608,25 @@ bool RootQueueEngine::logAlarmCb(const mqbu::StorageKey& appKey, mwcu::MemOutStream ss(&localAllocator); - // Print app consumers queue handles info + // Log app consumers queue handles info int idx = 1; int numConsumers = 0; QueueEngineUtil_AppState::Consumers& consumers = app->consumers(); - for (QueueEngineUtil_AppState::Consumers::const_iterator itConsumer = + for (QueueEngineUtil_AppState::Consumers::const_iterator citConsumer = consumers.begin(); - itConsumer != consumers.end(); - ++itConsumer) { - mqbi::QueueHandle* queueHandle_p = itConsumer->first; + citConsumer != consumers.end(); + ++citConsumer) { + mqbi::QueueHandle* const queueHandle_p = citConsumer->first; const mqbi::QueueHandle::SubStreams& subStreamInfos = queueHandle_p->subStreamInfos(); - for (mqbi::QueueHandle::SubStreams::const_iterator infoCiter = + for (mqbi::QueueHandle::SubStreams::const_iterator citSubStreams = subStreamInfos.begin(); - infoCiter != subStreamInfos.end(); - ++infoCiter) { - numConsumers += infoCiter->second.d_counts.d_readCount; + citSubStreams != subStreamInfos.end(); + ++citSubStreams) { + numConsumers += citSubStreams->second.d_counts.d_readCount; const int level = 2, spacesPerLevel = 2; @@ -1640,7 +1636,7 @@ bool RootQueueEngine::logAlarmCb(const mqbu::StorageKey& appKey, << "Handle Parameters .....: " << queueHandle_p->handleParameters() << mwcu::PrintUtil::newlineAndIndent(level, spacesPerLevel) - << "Unconfirmed messages count: " + << "Number of unconfirmed messages .....: " << queueHandle_p->countUnconfirmed() << mwcu::PrintUtil::newlineAndIndent(level, spacesPerLevel) << "UnconfirmedMonitors ....:"; @@ -1663,11 +1659,8 @@ bool RootQueueEngine::logAlarmCb(const mqbu::StorageKey& appKey, << " appears to be stuck. It currently has " << numConsumers << " consumers." << ss.str() << '\n'; + // Log un-delivered messages info mqbi::Storage* const storage = d_queueState_p->storage(); - - // Apps::const_iterator cItApp = d_apps.findByKey1(appId); - // const AppStateSp& app = cItApp->value(); - out << "\nFor appId: " << appId << '\n'; out << "Put aside list size: " << app->putAsideListSize() << '\n'; out << "Redelivery list size: " << app->redeliveryListSize() << '\n'; @@ -1708,7 +1701,7 @@ bool RootQueueEngine::logAlarmCb(const mqbu::StorageKey& appKey, out << '\n' << ss.str() << '\n'; } - // Log the first (oldest) message in Put aside list and its properties + // Log the first (oldest) message in a put aside list and its properties if (!app->d_putAsideList.empty()) { bslma::ManagedPtr storageIt_mp; mqbi::StorageResult::Enum rc = storage->getIterator( @@ -1771,7 +1764,7 @@ bool RootQueueEngine::logAlarmCb(const mqbu::StorageKey& appKey, MWCTSK_ALARMLOG_ALARM("QUEUE_STUCK") << out.str() << MWCTSK_ALARMLOG_END; - return queueAtHead; + return true; } void RootQueueEngine::afterAppIdRegistered( diff --git a/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.h b/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.h index f2a876ed2..91987f4fb 100644 --- a/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.h +++ b/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.h @@ -203,9 +203,11 @@ class RootQueueEngine BSLS_KEYWORD_FINAL : public mqbi::QueueEngine { const AppStateSp& subQueue(unsigned int upstreamSubQueueId) const; /// Callback called by `d_consumptionMonitor` when alarm condition is met. - /// If the queue is at its head for the specified `appKey` it logs queue - /// alarm data. Returns `true` if alarm was logged and `false` otherwise. - bool logAlarmCb(const mqbu::StorageKey& appKey, const bool isAlarm) const; + /// If there are un-delivered messages for the specified `appKey` and + /// `enableLog` is `true` it logs alarm data. Return `true` if there are + /// un-delivered messages and `false` otherwise. + bool logAlarmCb(const mqbu::StorageKey& appKey, + const bool enableLog) const; public: // TRAITS From a95ed92affe8efd8b6edef46768b5fefe8194a6c Mon Sep 17 00:00:00 2001 From: Aleksandr Ivanov Date: Tue, 24 Sep 2024 13:10:07 +0300 Subject: [PATCH 15/23] Fix Solaris build Signed-off-by: Aleksandr Ivanov --- src/groups/mqb/mqbblp/mqbblp_rootqueueengine.cpp | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.cpp b/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.cpp index 02b67a968..085111e00 100644 --- a/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.cpp +++ b/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.cpp @@ -1708,7 +1708,7 @@ bool RootQueueEngine::logAlarmCb(const mqbu::StorageKey& appKey, &storageIt_mp, appKey, app->d_putAsideList.first()); - if (rc == mqbi::StorageResult::Enum::e_SUCCESS) { + if (rc == mqbi::StorageResult::e_SUCCESS) { // Log timestamp out << "Oldest message in a 'Put aside' list:\n"; mqbcmd::Result result; From b29a25caa8f995fd7062b6d8dbd3f8b313165712 Mon Sep 17 00:00:00 2001 From: Aleksandr Ivanov Date: Tue, 24 Sep 2024 17:19:02 +0300 Subject: [PATCH 16/23] Add test_alarms_subscription_mismatch Signed-off-by: Aleksandr Ivanov --- src/integration-tests/test_alarms.py | 40 ++++++++++++++++++++++++++++ 1 file changed, 40 insertions(+) diff --git a/src/integration-tests/test_alarms.py b/src/integration-tests/test_alarms.py index 0fe9d08bd..ae1c561ab 100644 --- a/src/integration-tests/test_alarms.py +++ b/src/integration-tests/test_alarms.py @@ -75,3 +75,43 @@ def test_no_alarms_for_a_slow_queue(cluster: Cluster): time.sleep(1) assert not leader.alarms("QUEUE_STUCK", 1) + + +@tweak.cluster.queue_operations.consumption_monitor_period_ms(500) +@tweak.domain.max_idle_time(1) +def test_alarms_subscription_mismatch(cluster: Cluster): + """ + Test broker ALARM log content for producer/consumer subscription expression mismatch (put aside list is not empty). + """ + + leader = cluster.last_known_leader + proxy = next(cluster.proxy_cycle()) + + producer = proxy.create_client("producer") + producer.open(tc.URI_PRIORITY, flags=["write,ack"], succeed=True) + + consumer = proxy.create_client("consumer") + consumer.open( + tc.URI_PRIORITY, + flags=["read"], + succeed=True, + subscriptions=[{"expression": "x == 1"}], + ) + + producer.post( + tc.URI_PRIORITY, + ["msg"], + succeed=True, + wait_ack=True, + messageProperties=[{"name": "x", "value": "0", "type": "E_INT"}], + ) + + time.sleep(2) + + assert leader.alarms("QUEUE_STUCK", 1) + assert leader.capture(r"Put aside list size: 1") + assert leader.capture(r"Redelivery list size: 0") + assert leader.capture(r"Consumer subscription expressions:") + assert leader.capture(r"x == 1") + assert leader.capture(r"Oldest message in a 'Put aside' list:") + assert leader.capture(r"Message Properties: \[ x \(INT32\) = 0 \]") From 4e11d2d3c6d06c15739de06fd6c8f38396835d09 Mon Sep 17 00:00:00 2001 From: Aleksandr Ivanov Date: Tue, 24 Sep 2024 17:42:23 +0300 Subject: [PATCH 17/23] Cleanup Signed-off-by: Aleksandr Ivanov --- src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.h | 5 ++--- src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.t.cpp | 4 ++-- 2 files changed, 4 insertions(+), 5 deletions(-) diff --git a/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.h b/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.h index 561672dab..2038a2b85 100644 --- a/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.h +++ b/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.h @@ -312,9 +312,8 @@ class QueueConsumptionMonitor { QueueConsumptionMonitor& setMaxIdleTime(bsls::Types::Int64 value); /// Register the substream identified by the specified `key`. - /// `key` may be `StorageKey::k_NULL_KEY`, in which case no other key may - /// be - /// registered via this function. It is illegal to register the same + /// `key` may be `StorageKey::k_NULL_KEY`, in which case no other key may + /// be registered via this function. It is illegal to register the same /// substream more than once. void registerSubStream(const mqbu::StorageKey& key); diff --git a/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.t.cpp b/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.t.cpp index 2c1dd80d4..aa2f0c897 100644 --- a/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.t.cpp +++ b/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.t.cpp @@ -133,7 +133,7 @@ struct Test : mwctst::Test { unsigned int subQueueId = bmqp::QueueId::k_DEFAULT_SUBQUEUE_ID); void advance(const mqbu::StorageKey& key); - bool loggingCb(const mqbu::StorageKey& appKey, const bool isAlarm); + bool loggingCb(const mqbu::StorageKey& appKey, const bool enableLog); }; Test::Test() @@ -157,7 +157,7 @@ Test::Test() bdlf::BindUtil::bind(&Test::loggingCb, this, bdlf::PlaceHolders::_1, // appKey - bdlf::PlaceHolders::_2), // isAlarm + bdlf::PlaceHolders::_2), // enableLog s_allocator_p) , d_storage(d_queue.uri(), From 1616eb0f08eada8830788a6e8d92824c32a2bfb9 Mon Sep 17 00:00:00 2001 From: Aleksandr Ivanov Date: Mon, 30 Sep 2024 17:45:23 +0300 Subject: [PATCH 18/23] Fix review comments Signed-off-by: Aleksandr Ivanov --- .../mqb/mqbblp/mqbblp_rootqueueengine.cpp | 42 +++++++------------ 1 file changed, 14 insertions(+), 28 deletions(-) diff --git a/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.cpp b/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.cpp index 6922bcfb3..a8d25ce03 100644 --- a/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.cpp +++ b/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.cpp @@ -1578,21 +1578,10 @@ bool RootQueueEngine::logAlarmCb(const mqbu::StorageKey& appKey, BSLS_ASSERT_SAFE(d_queueState_p->queue()->dispatcher()->inDispatcherThread( d_queueState_p->queue())); - // Construct AppId from appKey - bmqt::UriBuilder uriBuilder(d_queueState_p->uri(), d_allocator_p); - bsl::string appId(d_allocator_p); - - if (appKey.isNull()) { - appId = bmqp::ProtocolUtil::k_DEFAULT_APP_ID; - } - else if (d_queueState_p->storage()->hasVirtualStorage(appKey, &appId)) { - uriBuilder.setId(appId); - } - - // Get AppState by appId. - Apps::const_iterator cItApp = d_apps.findByKey1(appId); + // Get AppState by appKey. + Apps::const_iterator cItApp = d_apps.findByKey2(AppKeyCount(appKey, 0)); if (cItApp == d_apps.end()) { - BALL_LOG_WARN << "No app found for appId: " << appId; + BALL_LOG_WARN << "No app found for appKey: " << appKey; return false; // RETURN } const AppStateSp& app = cItApp->value(); @@ -1611,9 +1600,6 @@ bool RootQueueEngine::logAlarmCb(const mqbu::StorageKey& appKey, // Logging alarm info bdlma::LocalSequentialAllocator<4096> localAllocator(d_allocator_p); - bmqt::Uri uri(&localAllocator); - uriBuilder.uri(&uri); - mwcu::MemOutStream ss(&localAllocator); // Log app consumers queue handles info @@ -1650,16 +1636,18 @@ bool RootQueueEngine::logAlarmCb(const mqbu::StorageKey& appKey, << "UnconfirmedMonitors ....:"; const bsl::vector monitors = - queueHandle_p->unconfirmedMonitors(appId); + queueHandle_p->unconfirmedMonitors(app->d_appId); for (size_t i = 0; i < monitors.size(); ++i) { ss << "\n " << *monitors[i]; } } } - mwcu::MemOutStream out(&localAllocator); - out << "Queue '" << uri << "' "; - d_queueState_p->storage()->capacityMeter()->printShortSummary(out); + mwcu::MemOutStream out(&localAllocator); + mqbi::Storage* const storage = d_queueState_p->storage(); + + out << "Queue '" << d_queueState_p->uri() << "' "; + storage->capacityMeter()->printShortSummary(out); out << ", max idle time " << mwcu::PrintUtil::prettyTimeInterval( d_queueState_p->queue()->domain()->config().maxIdleTime() * @@ -1668,14 +1656,12 @@ bool RootQueueEngine::logAlarmCb(const mqbu::StorageKey& appKey, << " consumers." << ss.str() << '\n'; // Log un-delivered messages info - mqbi::Storage* const storage = d_queueState_p->storage(); - out << "\nFor appId: " << appId << '\n'; + out << "\nFor appId: " << app->d_appId << '\n'; out << "Put aside list size: " << app->putAsideListSize() << '\n'; out << "Redelivery list size: " << app->redeliveryListSize() << '\n'; - out << "Number of messages: " - << d_queueState_p->storage()->numMessages(app->d_appKey) << '\n'; - out << "Number of bytes: " - << d_queueState_p->storage()->numBytes(app->d_appKey) << "\n\n"; + out << "Number of messages: " << storage->numMessages(app->d_appKey) + << '\n'; + out << "Number of bytes: " << storage->numBytes(app->d_appKey) << "\n\n"; // Log consumer subscriptions mqbblp::Routers::QueueRoutingContext& routingContext = @@ -1755,7 +1741,7 @@ bool RootQueueEngine::logAlarmCb(const mqbu::StorageKey& appKey, mqbcmd::Result result; mqbs::StoragePrintUtil::listMessages(&result.makeQueueContents(), - appId, + app->d_appId, 0, k_NUM_MSGS, storage); From 85a3eef7b65e2074a14262e8cefff551c9b55db8 Mon Sep 17 00:00:00 2001 From: Aleksandr Ivanov Date: Fri, 11 Oct 2024 16:32:08 +0300 Subject: [PATCH 19/23] Refactor mqbblp_queueconsumptionmonitor.t Signed-off-by: Aleksandr Ivanov --- .../mqbblp_queueconsumptionmonitor.t.cpp | 421 +++--------------- 1 file changed, 57 insertions(+), 364 deletions(-) diff --git a/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.t.cpp b/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.t.cpp index aa2f0c897..d4b7963a5 100644 --- a/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.t.cpp +++ b/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.t.cpp @@ -17,27 +17,17 @@ #include // MBQ -#include #include #include -#include -#include #include -#include #include #include #include #include #include #include -#include #include -// BMQ -#include -#include -#include - // MWC #include #include @@ -52,6 +42,7 @@ #include #include #include +#include using namespace BloombergLP; using namespace bsl; @@ -69,88 +60,40 @@ static mqbconfm::Domain getDomainConfig() return domainCfg; } -struct ClientContext { - // PUBLIC DATA - mqbmock::DispatcherClient d_dispatcherClient; - const bsl::shared_ptr - d_requesterContext_sp; - - // CREATORS - ClientContext(); - virtual ~ClientContext(); -}; - -ClientContext::ClientContext() -: d_dispatcherClient(s_allocator_p) -, d_requesterContext_sp(new (*s_allocator_p) - mqbi::QueueHandleRequesterContext(s_allocator_p), - s_allocator_p) -{ - d_requesterContext_sp->setClient(&d_dispatcherClient); -} - -ClientContext::~ClientContext() -{ - // NOTHING -} - struct Test : mwctst::Test { - typedef bsl::vector< - bsl::pair > - TestQueueHandleSeq; - // PUBLIC DATA - bmqt::Uri d_uri; - unsigned int d_id; - mqbu::StorageKey d_storageKey; - int d_partitionId; - mqbmock::Dispatcher d_dispatcher; - bdlbb::PooledBlobBufferFactory d_bufferFactory; - mqbmock::Cluster d_cluster; - mqbmock::Domain d_domain; - mqbmock::Queue d_queue; - QueueState d_queueState; - QueueConsumptionMonitor d_monitor; - mqbs::InMemoryStorage d_storage; - bdlbb::Blob d_dataBlob, d_optionBlob; - bsl::unordered_map d_advance; - unsigned int d_clientId; - ClientContext d_consumer1; - ClientContext d_consumer2; - ClientContext d_producer; - TestQueueHandleSeq d_testQueueHandles; + mqbu::StorageKey d_storageKey; + mqbmock::Dispatcher d_dispatcher; + bdlbb::PooledBlobBufferFactory d_bufferFactory; + mqbmock::Cluster d_cluster; + mqbmock::Domain d_domain; + mqbmock::Queue d_queue; + QueueState d_queueState; + QueueConsumptionMonitor d_monitor; + mqbs::InMemoryStorage d_storage; + bsl::set d_haveUndelivered; // CREATORS Test(); ~Test() BSLS_KEYWORD_OVERRIDE; // MANIPULATORS - void putMessage(); - mqbi::QueueHandle* createClient( - const ClientContext& clientContext, - bmqt::QueueFlags::Enum role, - const bsl::string& appId = bmqp::ProtocolUtil::k_DEFAULT_APP_ID, - unsigned int subQueueId = bmqp::QueueId::k_DEFAULT_SUBQUEUE_ID); - - void advance(const mqbu::StorageKey& key); + void putMessage(mqbu::StorageKey key = mqbu::StorageKey::k_NULL_KEY); bool loggingCb(const mqbu::StorageKey& appKey, const bool enableLog); }; Test::Test() -: d_uri("bmq://bmq.test.local/test_queue") -, d_id(802701) -, d_storageKey(mqbu::StorageKey::k_NULL_KEY) -, d_partitionId(1) +: d_storageKey(mqbu::StorageKey::k_NULL_KEY) , d_dispatcher(s_allocator_p) , d_bufferFactory(1024, s_allocator_p) , d_cluster(&d_bufferFactory, s_allocator_p) , d_domain(&d_cluster, s_allocator_p) , d_queue(&d_domain, s_allocator_p) , d_queueState(&d_queue, - d_uri, - d_id, + bmqt::Uri("bmq://bmq.test.local/test_queue"), + 802701, d_storageKey, - d_partitionId, + 1, &d_domain, s_allocator_p) , d_monitor(&d_queueState, @@ -161,18 +104,13 @@ Test::Test() s_allocator_p) , d_storage(d_queue.uri(), - mqbu::StorageKey::k_NULL_KEY, + d_storageKey, mqbs::DataStore::k_INVALID_PARTITION_ID, getDomainConfig(), d_domain.capacityMeter(), bmqp::RdaInfo(), s_allocator_p) -, d_advance(s_allocator_p) -, d_clientId(0) -, d_consumer1() -, d_consumer2() -, d_producer() -, d_testQueueHandles(s_allocator_p) +, d_haveUndelivered(s_allocator_p) { d_dispatcher._setInDispatcherThread(true); d_queue._setDispatcher(&d_dispatcher); @@ -205,96 +143,24 @@ Test::Test() d_queueState.setStorage(storageMp); d_domain.queueStatContext()->snapshot(); - - d_consumer1.d_dispatcherClient._setDescription("test consumer 1"); - d_consumer2.d_dispatcherClient._setDescription("test consumer 2"); - d_producer.d_dispatcherClient._setDescription("test producer"); } Test::~Test() { - for (TestQueueHandleSeq::reverse_iterator - iter = d_testQueueHandles.rbegin(), - last = d_testQueueHandles.rend(); - iter != last; - ++iter) { - bsl::shared_ptr handleSp; - bsls::Types::Uint64 lostFlags; - d_queueState.handleCatalog().releaseHandleHelper(&handleSp, - &lostFlags, - iter->first, - iter->second, - true); - } - d_domain.unregisterQueue(&d_queue); } -void Test::putMessage() +void Test::putMessage(mqbu::StorageKey key) { - bmqt::MessageGUID messageGUID; - mqbu::MessageGUIDUtil::generateGUID(&messageGUID); - - mqbi::StorageMessageAttributes messageAttributes; - bslma::ManagedPtr appData(&d_dataBlob, - 0, - bslma::ManagedPtrUtil::noOpDeleter); - bslma::ManagedPtr options(&d_dataBlob, - 0, - bslma::ManagedPtrUtil::noOpDeleter); - - ASSERT_EQ(d_storage.put(&messageAttributes, - messageGUID, - appData, - options, - mqbi::Storage::StorageKeys()), - mqbi::StorageResult::e_SUCCESS); -} - -mqbi::QueueHandle* Test::createClient(const ClientContext& clientContext, - bmqt::QueueFlags::Enum role, - const bsl::string& appId, - unsigned int subQueueId) -{ - bmqp_ctrlmsg::QueueHandleParameters handleParams(s_allocator_p); - handleParams.uri() = d_uri.asString(); - handleParams.qId() = ++d_clientId; - handleParams.readCount() = role == bmqt::QueueFlags::e_READ ? 1 : 0; - handleParams.writeCount() = role == bmqt::QueueFlags::e_WRITE ? 1 : 0; - handleParams.adminCount() = 0; - handleParams.flags() = role; - - mqbi::QueueHandle* queueHandle = d_queueState.handleCatalog().createHandle( - clientContext.d_requesterContext_sp, - handleParams, - &d_queueState.stats()); - d_testQueueHandles.push_back(bsl::make_pair(queueHandle, handleParams)); - - // Update the current handle parameters. - d_queueState.add(handleParams); - - bmqp_ctrlmsg::SubQueueIdInfo subStreamInfo; - subStreamInfo.appId() = appId; - queueHandle->registerSubStream(subStreamInfo, - subQueueId, - mqbi::QueueCounts(1, 0)); - - return queueHandle; -} - -void Test::advance(const mqbu::StorageKey& key) -{ - ++d_advance[key]; + d_monitor.onMessageSent(key); + d_haveUndelivered.insert(key); } bool Test::loggingCb(const mqbu::StorageKey& appKey, const bool enableLog) { BALL_LOG_SET_CATEGORY("MQBBLP.QUEUECONSUMPTIONMONITORTEST"); - bslma::ManagedPtr out; - out = d_storage.getIterator(appKey); - - bool haveUndelivered = !out->atEnd(); + bool haveUndelivered = d_haveUndelivered.contains(appKey); if (enableLog && haveUndelivered) { mwcu::MemOutStream out(s_allocator_p); @@ -323,16 +189,16 @@ TEST_F(Test, doNotMonitor) mwctst::ScopedLogObserver observer(ball::Severity::INFO, s_allocator_p); - d_monitor.registerSubStream(mqbu::StorageKey::k_NULL_KEY); + d_monitor.registerSubStream(d_storageKey); - ASSERT_EQ(d_monitor.state(mqbu::StorageKey::k_NULL_KEY), + ASSERT_EQ(d_monitor.state(d_storageKey), QueueConsumptionMonitor::State::e_ALIVE); d_monitor.onTimer(0); d_monitor.onTimer(1000000); - ASSERT_EQ(d_monitor.state(mqbu::StorageKey::k_NULL_KEY), + ASSERT_EQ(d_monitor.state(d_storageKey), QueueConsumptionMonitor::State::e_ALIVE); ASSERT_EQ(observer.records().size(), 0U); @@ -353,50 +219,19 @@ TEST_F(Test, emptyQueue) d_monitor.setMaxIdleTime(k_MAX_IDLE_TIME); - d_monitor.registerSubStream(mqbu::StorageKey::k_NULL_KEY); + d_monitor.registerSubStream(d_storageKey); d_monitor.onTimer(k_MAX_IDLE_TIME); - ASSERT_EQ(d_monitor.state(mqbu::StorageKey::k_NULL_KEY), + ASSERT_EQ(d_monitor.state(d_storageKey), QueueConsumptionMonitor::State::e_ALIVE); ASSERT_EQ(logObserver.records().size(), expectedLogRecords); d_monitor.onTimer(k_MAX_IDLE_TIME + 1); - ASSERT_EQ(d_monitor.state(mqbu::StorageKey::k_NULL_KEY), + ASSERT_EQ(d_monitor.state(d_storageKey), QueueConsumptionMonitor::State::e_ALIVE); ASSERT_EQ(logObserver.records().size(), expectedLogRecords); } -TEST_F(Test, logFormat) -// ------------------------------------------------------------------------ -// Concerns: State becomes IDLE after set period then returns to normal -// when message is processed - this is a typical, full scenario. -// -// Plan: Instantiate component, put message in queue, make time pass and -// check that state flips to IDLE according to specs, check logs, make more -// time pass and check that state remains 'idle', signal component that a -// message was consumed, check that state flips to 'alive', make more time -// pass, check that state remains 'alive'. -// ------------------------------------------------------------------------ -{ - mwctst::ScopedLogObserver logObserver(ball::Severity::INFO, s_allocator_p); - - const bsls::Types::Int64 k_MAX_IDLE_TIME = 10; - - d_monitor.setMaxIdleTime(k_MAX_IDLE_TIME); - - d_monitor.registerSubStream(mqbu::StorageKey::k_NULL_KEY); - - putMessage(); - - d_monitor.onTimer(k_MAX_IDLE_TIME); - d_monitor.onTimer(2 * k_MAX_IDLE_TIME + 1); - ASSERT_EQ(logObserver.records().size(), 1u); - ASSERT(mwctst::ScopedLogObserverUtil::recordMessageMatch( - logObserver.records().back(), - "ALARM \\[QUEUE_STUCK\\]", - s_allocator_p)); -} - TEST_F(Test, putAliveIdleSendAlive) // ------------------------------------------------------------------------ // Concerns: State becomes IDLE after set period then returns to normal @@ -416,27 +251,27 @@ TEST_F(Test, putAliveIdleSendAlive) d_monitor.setMaxIdleTime(k_MAX_IDLE_TIME); - d_monitor.registerSubStream(mqbu::StorageKey::k_NULL_KEY); + d_monitor.registerSubStream(d_storageKey); putMessage(); d_monitor.onTimer(k_MAX_IDLE_TIME); - ASSERT_EQ(d_monitor.state(mqbu::StorageKey::k_NULL_KEY), + ASSERT_EQ(d_monitor.state(d_storageKey), QueueConsumptionMonitor::State::e_ALIVE); ASSERT_EQ(logObserver.records().size(), expectedLogRecords); d_monitor.onTimer(2 * k_MAX_IDLE_TIME - 1); - ASSERT_EQ(d_monitor.state(mqbu::StorageKey::k_NULL_KEY), + ASSERT_EQ(d_monitor.state(d_storageKey), QueueConsumptionMonitor::State::e_ALIVE); ASSERT_EQ(logObserver.records().size(), expectedLogRecords); d_monitor.onTimer(2 * k_MAX_IDLE_TIME); - ASSERT_EQ(d_monitor.state(mqbu::StorageKey::k_NULL_KEY), + ASSERT_EQ(d_monitor.state(d_storageKey), QueueConsumptionMonitor::State::e_ALIVE); ASSERT_EQ(logObserver.records().size(), expectedLogRecords); d_monitor.onTimer(2 * k_MAX_IDLE_TIME + 1); - ASSERT_EQ(d_monitor.state(mqbu::StorageKey::k_NULL_KEY), + ASSERT_EQ(d_monitor.state(d_storageKey), QueueConsumptionMonitor::State::e_IDLE); ASSERT_EQ(logObserver.records().size(), ++expectedLogRecords); ASSERT(mwctst::ScopedLogObserverUtil::recordMessageMatch( @@ -445,12 +280,11 @@ TEST_F(Test, putAliveIdleSendAlive) s_allocator_p)); d_monitor.onTimer(2 * k_MAX_IDLE_TIME + 2); - ASSERT_EQ(d_monitor.state(mqbu::StorageKey::k_NULL_KEY), + ASSERT_EQ(d_monitor.state(d_storageKey), QueueConsumptionMonitor::State::e_IDLE); - d_monitor.onMessageSent(mqbu::StorageKey::k_NULL_KEY); - advance(mqbu::StorageKey::k_NULL_KEY); - ASSERT_EQ(d_monitor.state(mqbu::StorageKey::k_NULL_KEY), + d_monitor.onMessageSent(d_storageKey); + ASSERT_EQ(d_monitor.state(d_storageKey), QueueConsumptionMonitor::State::e_IDLE); ASSERT_EQ(logObserver.records().size(), expectedLogRecords); @@ -460,48 +294,10 @@ TEST_F(Test, putAliveIdleSendAlive) logObserver.records().back(), "no longer appears to be stuck", s_allocator_p)); - ASSERT_EQ(d_monitor.state(mqbu::StorageKey::k_NULL_KEY), + ASSERT_EQ(d_monitor.state(d_storageKey), QueueConsumptionMonitor::State::e_ALIVE); } -TEST_F(Test, putAliveIdleWithConsumer) -{ - // ------------------------------------------------------------------------ - // Concerns: Same as above, but with two read and one write clients. - // - // Plan: Start monitoring, create three clients (2 read and 1 write), put - // message in queue, create an 'idle' condition, check that the two read - // clients (but not the write client) are reported in the log. - // ------------------------------------------------------------------------ - mwctst::ScopedLogObserver logObserver(ball::Severity::INFO, s_allocator_p); - size_t expectedLogRecords = 3U; - - const bsls::Types::Int64 k_MAX_IDLE_TIME = 10; - d_monitor.setMaxIdleTime(k_MAX_IDLE_TIME); - - d_monitor.registerSubStream(mqbu::StorageKey::k_NULL_KEY); - - createClient(d_consumer1, bmqt::QueueFlags::e_READ); - createClient(d_consumer2, bmqt::QueueFlags::e_READ); - createClient(d_producer, bmqt::QueueFlags::e_WRITE); - - putMessage(); - - d_monitor.onTimer(k_MAX_IDLE_TIME); - ASSERT_EQ(d_monitor.state(mqbu::StorageKey::k_NULL_KEY), - QueueConsumptionMonitor::State::e_ALIVE); - ASSERT_EQ(logObserver.records().size(), expectedLogRecords); - - d_monitor.onTimer(2 * k_MAX_IDLE_TIME + 1); - ASSERT_EQ(d_monitor.state(mqbu::StorageKey::k_NULL_KEY), - QueueConsumptionMonitor::State::e_IDLE); - ASSERT_EQ(logObserver.records().size(), ++expectedLogRecords); - ASSERT(mwctst::ScopedLogObserverUtil::recordMessageMatch( - logObserver.records().back(), - "ALARM \\[QUEUE_STUCK\\]", - s_allocator_p)); -} - TEST_F(Test, putAliveIdleEmptyAlive) // ------------------------------------------------------------------------ // Concerns: Emptying the queue flips state back to 'alive'. @@ -515,21 +311,22 @@ TEST_F(Test, putAliveIdleEmptyAlive) d_monitor.setMaxIdleTime(k_MAX_IDLE_TIME); - d_monitor.registerSubStream(mqbu::StorageKey::k_NULL_KEY); + d_monitor.registerSubStream(d_storageKey); + putMessage(); d_monitor.onTimer(k_MAX_IDLE_TIME); - ASSERT_EQ(d_monitor.state(mqbu::StorageKey::k_NULL_KEY), + ASSERT_EQ(d_monitor.state(d_storageKey), QueueConsumptionMonitor::State::e_ALIVE); d_monitor.onTimer(2 * k_MAX_IDLE_TIME + 1); - ASSERT_EQ(d_monitor.state(mqbu::StorageKey::k_NULL_KEY), + ASSERT_EQ(d_monitor.state(d_storageKey), QueueConsumptionMonitor::State::e_IDLE); - d_storage.removeAll(d_storageKey); + d_haveUndelivered.erase(d_storageKey); d_monitor.onTimer(2 * k_MAX_IDLE_TIME + 1); - ASSERT_EQ(d_monitor.state(mqbu::StorageKey::k_NULL_KEY), + ASSERT_EQ(d_monitor.state(d_storageKey), QueueConsumptionMonitor::State::e_ALIVE); } @@ -547,35 +344,35 @@ TEST_F(Test, changeMaxIdleTime) d_monitor.setMaxIdleTime(k_MAX_IDLE_TIME); - d_monitor.registerSubStream(mqbu::StorageKey::k_NULL_KEY); + d_monitor.registerSubStream(d_storageKey); putMessage(); d_monitor.onTimer(0); - ASSERT_EQ(d_monitor.state(mqbu::StorageKey::k_NULL_KEY), + ASSERT_EQ(d_monitor.state(d_storageKey), QueueConsumptionMonitor::State::e_ALIVE); d_monitor.onTimer(k_MAX_IDLE_TIME + 1); - ASSERT_EQ(d_monitor.state(mqbu::StorageKey::k_NULL_KEY), + ASSERT_EQ(d_monitor.state(d_storageKey), QueueConsumptionMonitor::State::e_IDLE); mwctst::ScopedLogObserver logObserver(ball::Severity::INFO, s_allocator_p); d_monitor.setMaxIdleTime(k_MAX_IDLE_TIME * 2); - ASSERT_EQ(d_monitor.state(mqbu::StorageKey::k_NULL_KEY), + ASSERT_EQ(d_monitor.state(d_storageKey), QueueConsumptionMonitor::State::e_ALIVE); ASSERT_EQ(logObserver.records().size(), 0u); d_monitor.onTimer(k_MAX_IDLE_TIME * 2); - ASSERT_EQ(d_monitor.state(mqbu::StorageKey::k_NULL_KEY), + ASSERT_EQ(d_monitor.state(d_storageKey), QueueConsumptionMonitor::State::e_ALIVE); d_monitor.onTimer(k_MAX_IDLE_TIME * 2 + k_MAX_IDLE_TIME * 2); - ASSERT_EQ(d_monitor.state(mqbu::StorageKey::k_NULL_KEY), + ASSERT_EQ(d_monitor.state(d_storageKey), QueueConsumptionMonitor::State::e_ALIVE); d_monitor.onTimer(k_MAX_IDLE_TIME * 2 + k_MAX_IDLE_TIME * 2 + 1); - ASSERT_EQ(d_monitor.state(mqbu::StorageKey::k_NULL_KEY), + ASSERT_EQ(d_monitor.state(d_storageKey), QueueConsumptionMonitor::State::e_IDLE); } @@ -592,12 +389,12 @@ TEST_F(Test, reset) d_monitor.setMaxIdleTime(k_MAX_IDLE_TIME); - d_monitor.registerSubStream(mqbu::StorageKey::k_NULL_KEY); + d_monitor.registerSubStream(d_storageKey); putMessage(); d_monitor.onTimer(0); - ASSERT_EQ(d_monitor.state(mqbu::StorageKey::k_NULL_KEY), + ASSERT_EQ(d_monitor.state(d_storageKey), QueueConsumptionMonitor::State::e_ALIVE); mwctst::ScopedLogObserver logObserver(ball::Severity::INFO, s_allocator_p); @@ -635,10 +432,10 @@ TEST_F(Test, putAliveIdleSendAliveTwoSubstreams) d_storage.addVirtualStorage(errorDescription, "app2", key2); d_monitor.registerSubStream(key1); - d_monitor.registerSubStream(key2); - putMessage(); + putMessage(key1); + putMessage(key2); d_monitor.onTimer(k_MAX_IDLE_TIME); ASSERT_EQ(d_monitor.state(key1), QueueConsumptionMonitor::State::e_ALIVE); @@ -673,7 +470,6 @@ TEST_F(Test, putAliveIdleSendAliveTwoSubstreams) ASSERT_EQ(d_monitor.state(key2), QueueConsumptionMonitor::State::e_IDLE); d_monitor.onMessageSent(key1); - advance(key1); ASSERT_EQ(d_monitor.state(key1), QueueConsumptionMonitor::State::e_IDLE); ASSERT_EQ(d_monitor.state(key2), QueueConsumptionMonitor::State::e_IDLE); ASSERT_EQ(logObserver.records().size(), expectedLogRecords); @@ -690,7 +486,6 @@ TEST_F(Test, putAliveIdleSendAliveTwoSubstreams) ASSERT_EQ(d_monitor.state(key2), QueueConsumptionMonitor::State::e_IDLE); d_monitor.onMessageSent(key2); - advance(key2); d_monitor.onTimer(3 * k_MAX_IDLE_TIME + 3); ASSERT_EQ(logObserver.records().size(), expectedLogRecords += 1); ASSERT(mwctst::ScopedLogObserverUtil::recordMessageMatch( @@ -702,107 +497,6 @@ TEST_F(Test, putAliveIdleSendAliveTwoSubstreams) ASSERT_EQ(d_monitor.state(key2), QueueConsumptionMonitor::State::e_ALIVE); } -TEST_F(Test, putAliveIdleSendAliveTwoSubstreamsTwoConsumers) -// ------------------------------------------------------------------------ -// Concerns: State becomes IDLE after set period then returns to normal -// when message is processed - this is a typical, full scenario. -// -// Plan: Instantiate component, put message in queue, make time pass and -// check that state flips to IDLE according to specs, check logs, make more -// time pass and check that state remains 'idle', signal component that a -// message was consumed, check that state flips to 'alive', make more time -// pass, check that state remains 'alive'. -// ------------------------------------------------------------------------ -{ - mwctst::ScopedLogObserver logObserver(ball::Severity::INFO, s_allocator_p); - size_t expectedLogRecords = 3U; - - const bsls::Types::Int64 k_MAX_IDLE_TIME = 10; - - mqbu::StorageKey key1, key2; - key1.fromHex("ABCDEF1234"); - key2.fromHex("1234ABCDEF"); - - d_monitor.setMaxIdleTime(k_MAX_IDLE_TIME); - - mwcu::MemOutStream errorDescription(s_allocator_p); - d_storage.addVirtualStorage(errorDescription, "app1", key1); - d_storage.addVirtualStorage(errorDescription, "app2", key2); - - d_monitor.registerSubStream(key1); - - d_monitor.registerSubStream(key2); - - createClient(d_consumer1, bmqt::QueueFlags::e_READ, "app1"); - createClient(d_consumer2, bmqt::QueueFlags::e_READ, "app2"); - createClient(d_producer, bmqt::QueueFlags::e_WRITE); - - putMessage(); - - d_monitor.onTimer(k_MAX_IDLE_TIME); - ASSERT_EQ(d_monitor.state(key1), QueueConsumptionMonitor::State::e_ALIVE); - ASSERT_EQ(d_monitor.state(key2), QueueConsumptionMonitor::State::e_ALIVE); - ASSERT_EQ(logObserver.records().size(), expectedLogRecords); - - d_monitor.onTimer(2 * k_MAX_IDLE_TIME - 1); - ASSERT_EQ(d_monitor.state(key1), QueueConsumptionMonitor::State::e_ALIVE); - ASSERT_EQ(d_monitor.state(key2), QueueConsumptionMonitor::State::e_ALIVE); - ASSERT_EQ(logObserver.records().size(), expectedLogRecords); - - d_monitor.onTimer(2 * k_MAX_IDLE_TIME); - ASSERT_EQ(d_monitor.state(key1), QueueConsumptionMonitor::State::e_ALIVE); - ASSERT_EQ(d_monitor.state(key2), QueueConsumptionMonitor::State::e_ALIVE); - ASSERT_EQ(logObserver.records().size(), expectedLogRecords); - - d_monitor.onTimer(2 * k_MAX_IDLE_TIME + 1); - ASSERT_EQ(d_monitor.state(key1), QueueConsumptionMonitor::State::e_IDLE); - ASSERT_EQ(d_monitor.state(key2), QueueConsumptionMonitor::State::e_IDLE); - - ASSERT_EQ(logObserver.records().size(), expectedLogRecords += 2); - - for (bsl::vector::const_iterator iter = - logObserver.records().end() - 2; - iter != logObserver.records().end(); - ++iter) { - ASSERT(mwctst::ScopedLogObserverUtil::recordMessageMatch( - *iter, - "ALARM \\[QUEUE_STUCK\\]", - s_allocator_p)); - } - - d_monitor.onTimer(2 * k_MAX_IDLE_TIME + 2); - ASSERT_EQ(d_monitor.state(key1), QueueConsumptionMonitor::State::e_IDLE); - ASSERT_EQ(d_monitor.state(key2), QueueConsumptionMonitor::State::e_IDLE); - - d_monitor.onMessageSent(key1); - advance(key1); - ASSERT_EQ(d_monitor.state(key1), QueueConsumptionMonitor::State::e_IDLE); - ASSERT_EQ(d_monitor.state(key2), QueueConsumptionMonitor::State::e_IDLE); - ASSERT_EQ(logObserver.records().size(), expectedLogRecords); - - d_monitor.onTimer(3 * k_MAX_IDLE_TIME + 2); - ASSERT_EQ(logObserver.records().size(), expectedLogRecords += 1); - ASSERT(mwctst::ScopedLogObserverUtil::recordMessageMatch( - logObserver.records().back(), - "Queue 'bmq://bmq.test.local/test_queue\\?id=app1' no longer appears " - "to be stuck", - s_allocator_p)); - ASSERT_EQ(d_monitor.state(key1), QueueConsumptionMonitor::State::e_ALIVE); - ASSERT_EQ(d_monitor.state(key2), QueueConsumptionMonitor::State::e_IDLE); - - d_monitor.onMessageSent(key2); - advance(key2); - d_monitor.onTimer(3 * k_MAX_IDLE_TIME + 3); - ASSERT_EQ(logObserver.records().size(), expectedLogRecords += 1); - ASSERT(mwctst::ScopedLogObserverUtil::recordMessageMatch( - logObserver.records().back(), - "Queue 'bmq://bmq.test.local/test_queue\\?id=app2' no longer appears " - "to be stuck", - s_allocator_p)); - ASSERT_EQ(d_monitor.state(key1), QueueConsumptionMonitor::State::e_ALIVE); - ASSERT_EQ(d_monitor.state(key2), QueueConsumptionMonitor::State::e_ALIVE); -} - TEST_F(Test, usage) // ------------------------------------------------------------------------- // Concerns: Make sure the usage example is correct. @@ -817,7 +511,7 @@ TEST_F(Test, usage) monitor.setMaxIdleTime(20); - d_monitor.registerSubStream(mqbu::StorageKey::k_NULL_KEY); + d_monitor.registerSubStream(d_storageKey); putMessage(); putMessage(); @@ -836,8 +530,7 @@ TEST_F(Test, usage) monitor.onTimer(T += 15); // nothing is logged ASSERT_EQ(logObserver.records().size(), 1u); // 15 seconds later - T + 60s - consume first message, inform monitor: - monitor.onMessageSent(mqbu::StorageKey::k_NULL_KEY); - advance(mqbu::StorageKey::k_NULL_KEY); + monitor.onMessageSent(d_storageKey); // 15 seconds later - T + 75s monitor.onTimer(T += 15); // log INFO: back to active @@ -849,7 +542,7 @@ TEST_F(Test, usage) monitor.onTimer(T += 15); // log ALARM ASSERT_EQ(logObserver.records().size(), 3u); // 15 seconds later - T + 120s - d_storage.removeAll(d_storageKey); + d_haveUndelivered.erase(d_storageKey); monitor.onTimer(T += 15); // log INFO: back to active ASSERT_EQ(logObserver.records().size(), 4u); From 88cd3df6717593a26a2d74b5b6af0064f56afcc3 Mon Sep 17 00:00:00 2001 From: Aleksandr Ivanov Date: Fri, 11 Oct 2024 17:11:57 +0300 Subject: [PATCH 20/23] Print appId in queue uri Signed-off-by: Aleksandr Ivanov --- src/groups/mqb/mqbblp/mqbblp_rootqueueengine.cpp | 6 +++++- 1 file changed, 5 insertions(+), 1 deletion(-) diff --git a/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.cpp b/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.cpp index a8d25ce03..d23d9c260 100644 --- a/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.cpp +++ b/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.cpp @@ -1646,7 +1646,11 @@ bool RootQueueEngine::logAlarmCb(const mqbu::StorageKey& appKey, mwcu::MemOutStream out(&localAllocator); mqbi::Storage* const storage = d_queueState_p->storage(); - out << "Queue '" << d_queueState_p->uri() << "' "; + out << "Queue '" << d_queueState_p->uri(); + if (app->d_appId != bmqp::ProtocolUtil::k_DEFAULT_APP_ID) { + out << "?id=" << app->d_appId; + } + out << "' "; storage->capacityMeter()->printShortSummary(out); out << ", max idle time " << mwcu::PrintUtil::prettyTimeInterval( From 24d2027d7af260f95196bda6aaa01acf6954fd38 Mon Sep 17 00:00:00 2001 From: Aleksandr Ivanov Date: Mon, 14 Oct 2024 13:54:53 +0300 Subject: [PATCH 21/23] Fix code formatting Signed-off-by: Aleksandr Ivanov --- src/groups/mqb/mqbblp/mqbblp_queueengineutil.h | 2 +- src/groups/mqb/mqbblp/mqbblp_rootqueueengine.cpp | 7 ++++--- 2 files changed, 5 insertions(+), 4 deletions(-) diff --git a/src/groups/mqb/mqbblp/mqbblp_queueengineutil.h b/src/groups/mqb/mqbblp/mqbblp_queueengineutil.h index cd93538df..08e371716 100644 --- a/src/groups/mqb/mqbblp/mqbblp_queueengineutil.h +++ b/src/groups/mqb/mqbblp/mqbblp_queueengineutil.h @@ -551,7 +551,7 @@ struct QueueEngineUtil_AppState { bool isAtEndOfStorage() const; size_t putAsideListSize() const; - + size_t redeliveryListSize() const; Routers::Consumer* findQueueHandleContext(mqbi::QueueHandle* handle); diff --git a/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.cpp b/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.cpp index c14c62249..236dee496 100644 --- a/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.cpp +++ b/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.cpp @@ -1712,8 +1712,7 @@ bool RootQueueEngine::logAlarmCb(const mqbu::StorageKey& appKey, out << "\nFor appId: " << app->appId() << '\n'; out << "Put aside list size: " << app->putAsideListSize() << '\n'; out << "Redelivery list size: " << app->redeliveryListSize() << '\n'; - out << "Number of messages: " << storage->numMessages(appKey) - << '\n'; + out << "Number of messages: " << storage->numMessages(appKey) << '\n'; out << "Number of bytes: " << storage->numBytes(appKey) << "\n\n"; // Log consumer subscriptions @@ -1804,7 +1803,9 @@ bool RootQueueEngine::logAlarmCb(const mqbu::StorageKey& appKey, out << mwcu::PrintUtil::newlineAndIndent(level, spacesPerLevel) << "Current head of the queue:\n"; - mqbs::StoragePrintUtil::listMessage(&result.makeMessage(), storage, *headIt); + mqbs::StoragePrintUtil::listMessage(&result.makeMessage(), + storage, + *headIt); mqbcmd::HumanPrinter::print(out, result); out << "\n"; From e1b55b84321375d2803a425d06428ad27b9cc3f4 Mon Sep 17 00:00:00 2001 From: Aleksandr Ivanov Date: Tue, 15 Oct 2024 10:49:55 +0300 Subject: [PATCH 22/23] Fix review comments Signed-off-by: Aleksandr Ivanov --- .../mqbblp/mqbblp_queueconsumptionmonitor.cpp | 1 - .../mqbblp/mqbblp_queueconsumptionmonitor.h | 22 ++++++++++++------- .../mqbblp_queueconsumptionmonitor.t.cpp | 6 ++--- .../mqb/mqbblp/mqbblp_rootqueueengine.cpp | 15 ++++++++----- .../mqb/mqbblp/mqbblp_rootqueueengine.h | 3 +-- 5 files changed, 26 insertions(+), 21 deletions(-) diff --git a/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.cpp b/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.cpp index a10f4359f..da75b1534 100644 --- a/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.cpp +++ b/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.cpp @@ -215,7 +215,6 @@ void QueueConsumptionMonitor::onTimer(bsls::Types::Int64 currentTimer) // PRECONDITIONS BSLS_ASSERT_SAFE(d_queueState_p->queue()->dispatcher()->inDispatcherThread( d_queueState_p->queue())); - BSLS_ASSERT_SAFE(d_loggingCb); if (BSLS_PERFORMANCEHINT_PREDICT_UNLIKELY(d_maxIdleTime == 0)) { // monitoring is disabled diff --git a/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.h b/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.h index 2038a2b85..0d570e64d 100644 --- a/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.h +++ b/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.h @@ -210,7 +210,12 @@ class QueueConsumptionMonitor { static const char* toAscii(Transition::Enum value); }; - typedef bsl::function LoggingCb; + /// Callback function to log alarm info when queue state transitions to + /// idle. First argument is the app key, second argument is a boolean flag + /// to enable logging. If `enableLog` is `false`, logging is skipped. + /// Return `true` if there are un-delivered messages and `false` otherwise. + typedef bsl::function + LoggingCb; private: // PRIVATE TYPES @@ -257,9 +262,9 @@ class QueueConsumptionMonitor { SubStreamInfoMap d_subStreamInfos; + /// Callback to log alarm info if there are undelivered messages. + /// Return `true` if there are undelivered messages, `false` otherwise. LoggingCb d_loggingCb; - // Callback to log alarm info if there are undelivered messages. - // Return `true` if there are undelivered messages, `false` otherwise. // NOT IMPLEMENTED QueueConsumptionMonitor(const QueueConsumptionMonitor&) BSLS_CPP11_DELETED; @@ -278,8 +283,8 @@ class QueueConsumptionMonitor { // MANIPULATORS - /// Update the specified 'subStreamInfo', associated to the specified - /// 'appKey', and write log, upon transition to alive state. + /// Update the specified `subStreamInfo`, associated to the specified + /// `appKey`, and write log, upon transition to alive state. void onTransitionToAlive(SubStreamInfo* subStreamInfo, const mqbu::StorageKey& appKey); @@ -291,9 +296,10 @@ class QueueConsumptionMonitor { // CREATORS /// Create a `QueueConsumptionMonitor` object that monitors the queue - /// specified by `queueState`. Use the optionally specified - /// `basicAllocator` to supply memory. If `basicAllocator` is 0, the - /// currently installed default allocator is used. + /// specified by `queueState`. Use the specified `loggingCb` callback for + /// logging alarm data. Use the optionally specified `allocator` to supply + /// memory. If `allocator` is 0, the currently installed default allocator + /// is used. QueueConsumptionMonitor(QueueState* queueState, const LoggingCb& loggingCb, bslma::Allocator* allocator); diff --git a/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.t.cpp b/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.t.cpp index 3ca941e8b..e08c85940 100644 --- a/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.t.cpp +++ b/src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.t.cpp @@ -79,7 +79,7 @@ struct Test : mwctst::Test { // MANIPULATORS void putMessage(mqbu::StorageKey key = mqbu::StorageKey::k_NULL_KEY); - bool loggingCb(const mqbu::StorageKey& appKey, const bool enableLog); + bool loggingCb(const mqbu::StorageKey& appKey, bool enableLog); }; Test::Test() @@ -163,10 +163,8 @@ bool Test::loggingCb(const mqbu::StorageKey& appKey, const bool enableLog) bool haveUndelivered = d_haveUndelivered.contains(appKey); if (enableLog && haveUndelivered) { - mwcu::MemOutStream out(s_allocator_p); - out << "Test Alarm"; MWCTSK_ALARMLOG_ALARM("QUEUE_STUCK") - << out.str() << MWCTSK_ALARMLOG_END; + << "Test Alarm" << MWCTSK_ALARMLOG_END; } return haveUndelivered; diff --git a/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.cpp b/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.cpp index 236dee496..f2a362177 100644 --- a/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.cpp +++ b/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.cpp @@ -1618,7 +1618,7 @@ void RootQueueEngine::onTimer(bsls::Types::Int64 currentTimer) } bool RootQueueEngine::logAlarmCb(const mqbu::StorageKey& appKey, - const bool enableLog) const + bool enableLog) const { // executed by the *QUEUE DISPATCHER* thread @@ -1641,7 +1641,7 @@ bool RootQueueEngine::logAlarmCb(const mqbu::StorageKey& appKey, // No un-delivered messages, do nothing. return false; // RETURN } - else if (!enableLog) { + if (!enableLog) { // There are un-delivered messages, but log is disabled. return true; // RETURN } @@ -1655,7 +1655,7 @@ bool RootQueueEngine::logAlarmCb(const mqbu::StorageKey& appKey, int idx = 1; int numConsumers = 0; - QueueEngineUtil_AppState::Consumers& consumers = app->consumers(); + const QueueEngineUtil_AppState::Consumers& consumers = app->consumers(); for (QueueEngineUtil_AppState::Consumers::const_iterator citConsumer = consumers.begin(); citConsumer != consumers.end(); @@ -1738,8 +1738,8 @@ bool RootQueueEngine::logAlarmCb(const mqbu::StorageKey& appKey, } if (exprNum) { if (exprNum == k_EXPR_NUM_LIMIT) { - out << k_EXPR_NUM_LIMIT << " of " - << " consumer subscription expressions: "; + out << "First " << k_EXPR_NUM_LIMIT + << " of consumer subscription expressions: "; } else { out << "Consumer subscription expressions: "; @@ -1756,7 +1756,7 @@ bool RootQueueEngine::logAlarmCb(const mqbu::StorageKey& appKey, app->putAsideList().first()); if (rc == mqbi::StorageResult::e_SUCCESS) { // Log timestamp - out << "Oldest message in a 'Put aside' list:\n"; + out << "Oldest message in the 'Put aside' list:\n"; mqbcmd::Result result; mqbs::StoragePrintUtil::listMessage(&result.makeMessage(), storage, @@ -1776,11 +1776,14 @@ bool RootQueueEngine::logAlarmCb(const mqbu::StorageKey& appKey, else { BALL_LOG_WARN << "Failed to streamIn MessageProperties, rc = " << rc; + out << "Message Properties: Failed to acquire [rc: " << rc + << "]\n"; } } else { BALL_LOG_WARN << "Failed to get storage iterator for GUID: " << app->putAsideList().first() << ", rc = " << rc; + out << "'Put aside' list: Failed to acquire [rc: " << rc << "]\n"; } } diff --git a/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.h b/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.h index 9a964c689..8ca5012a4 100644 --- a/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.h +++ b/src/groups/mqb/mqbblp/mqbblp_rootqueueengine.h @@ -210,8 +210,7 @@ class RootQueueEngine BSLS_KEYWORD_FINAL : public mqbi::QueueEngine { /// If there are un-delivered messages for the specified `appKey` and /// `enableLog` is `true` it logs alarm data. Return `true` if there are /// un-delivered messages and `false` otherwise. - bool logAlarmCb(const mqbu::StorageKey& appKey, - const bool enableLog) const; + bool logAlarmCb(const mqbu::StorageKey& appKey, bool enableLog) const; public: // TRAITS From b4e100fc8ae4a38732d9701a951836a2a4b1e4e1 Mon Sep 17 00:00:00 2001 From: Aleksandr Ivanov Date: Tue, 15 Oct 2024 11:37:50 +0300 Subject: [PATCH 23/23] Fix failed IT Signed-off-by: Aleksandr Ivanov --- src/integration-tests/test_alarms.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/integration-tests/test_alarms.py b/src/integration-tests/test_alarms.py index ae1c561ab..3d296aa21 100644 --- a/src/integration-tests/test_alarms.py +++ b/src/integration-tests/test_alarms.py @@ -113,5 +113,5 @@ def test_alarms_subscription_mismatch(cluster: Cluster): assert leader.capture(r"Redelivery list size: 0") assert leader.capture(r"Consumer subscription expressions:") assert leader.capture(r"x == 1") - assert leader.capture(r"Oldest message in a 'Put aside' list:") + assert leader.capture(r"Oldest message in the 'Put aside' list:") assert leader.capture(r"Message Properties: \[ x \(INT32\) = 0 \]")