Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

placate shutdown logging #260

Merged
merged 2 commits into from
Apr 25, 2024
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
4 changes: 0 additions & 4 deletions src/groups/mqb/mqba/mqba_clientsession.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -908,8 +908,6 @@ void ClientSession::invalidateDispatched()
// PRECONDITIONS
BSLS_ASSERT_SAFE(dispatcher()->inDispatcherThread(this));

BALL_LOG_INFO << description() << ": invalidateDispatched";

if (d_operationState == e_DEAD) {
return; // RETURN
}
Expand Down Expand Up @@ -2827,8 +2825,6 @@ void ClientSession::invalidate()
// PRECONDITIONS
BSLS_ASSERT_SAFE(!dispatcher()->inDispatcherThread(this));

BALL_LOG_INFO << description() << ": invalidate";

dispatcher()->execute(
bdlf::BindUtil::bind(&ClientSession::invalidateDispatched, this),
this);
Expand Down
2 changes: 1 addition & 1 deletion src/groups/mqb/mqba/mqba_domainmanager.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -60,7 +60,7 @@ namespace BloombergLP {
namespace mqba {

namespace {
const int k_MAX_WAIT_SECONDS_AT_SHUTDOWN = 20;
const int k_MAX_WAIT_SECONDS_AT_SHUTDOWN = 40;
} // close unnamed namespace

// ===========================
Expand Down
34 changes: 23 additions & 11 deletions src/groups/mqb/mqbblp/mqbblp_clusterqueuehelper.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -62,6 +62,7 @@
#include <mwcu_printutil.h>

// BDE
#include <ball_logthrottle.h>
#include <ball_severity.h>
#include <bdlb_nullablevalue.h>
#include <bdlb_print.h>
Expand Down Expand Up @@ -92,6 +93,17 @@ const char k_MAXIMUM_NUMBER_OF_QUEUES_REACHED[] =
"maximum number of queues reached";
const char k_SELF_NODE_IS_STOPPING[] = "self node is stopping";

const int k_MAX_INSTANT_MESSAGES = 10;
// Maximum messages logged with throttling in a short period of time.

const bsls::Types::Int64 k_NS_PER_MESSAGE =
bdlt::TimeUnitRatio::k_NANOSECONDS_PER_MINUTE / k_MAX_INSTANT_MESSAGES;
// Time interval between messages logged with throttling.

#define BMQ_LOGTHROTTLE_INFO() \
BALL_LOGTHROTTLE_INFO(k_MAX_INSTANT_MESSAGES, k_NS_PER_MESSAGE) \
<< "[THROTTLED] "

/// This function is a simple wrapper around the specified `callback`, to
/// ensure that the specified `refCount` is decremented after it gets
/// invoked with the specified `status`, `queue` and `confirmationCookie`.
Expand Down Expand Up @@ -1688,11 +1700,11 @@ void ClusterQueueHelper::onConfigureQueueResponse(

if (d_cluster_p->isStopping()) {
// Self is stopping. Drop the response.
BALL_LOG_INFO << d_cluster_p->description()
<< ": Dropping (re)configureQueue response "
<< "[reason: 'stopping'"
<< ", request: " << requestContext->request()
<< ", response: " << requestContext->response() << "]";
BMQ_LOGTHROTTLE_INFO()
<< d_cluster_p->description()
678098 marked this conversation as resolved.
Show resolved Hide resolved
<< ": Dropping (re)configureQueue response [reason: 'stopping'"
<< ", request: " << requestContext->request()
<< ", response: " << requestContext->response() << "]";
return; // RETURN
}

Expand Down Expand Up @@ -3295,12 +3307,12 @@ void ClusterQueueHelper::sendCloseQueueRequest(
// will be advertised upstream. So just like above, we indicate
// success via 'callback'.

BALL_LOG_WARN << d_cluster_p->description()
<< ": Failed to send close-queue request: "
<< request->request() << ", for queue ["
<< handleParameters.uri() << "] to "
<< upstreamNode->nodeDescription() << ", rc: " << rc
<< ", but still indicating success.";
BMQ_LOGTHROTTLE_INFO()
<< d_cluster_p->description()
678098 marked this conversation as resolved.
Show resolved Hide resolved
<< ": Failed to send close-queue request: " << request->request()
<< ", for queue [" << handleParameters.uri() << "] to "
<< upstreamNode->nodeDescription() << ", rc: " << rc
<< ", but still indicating success.";

if (callback) {
// As above, we use 'E_SUCCESS' for the category. Perhaps a more
Expand Down
18 changes: 11 additions & 7 deletions src/groups/mqb/mqbblp/mqbblp_queuehandle.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -69,6 +69,10 @@ const bsls::Types::Int64 k_NS_PER_MESSAGE =
bdlt::TimeUnitRatio::k_NANOSECONDS_PER_SECOND;
// Time interval between messages logged with throttling.

#define BMQ_LOGTHROTTLE_INFO() \
BALL_LOGTHROTTLE_INFO(k_MAX_INSTANT_MESSAGES, k_NS_PER_MESSAGE) \
<< "[THROTTLED] "

typedef bsl::function<void()> CompletionCallback;

/// Utility function used in `mwcu::OperationChain` as the operation
Expand Down Expand Up @@ -613,11 +617,11 @@ void QueueHandle::registerSubscription(unsigned int downstreamSubId,
const bmqp_ctrlmsg::ConsumerInfo& ci,
unsigned int upstreamId)
{
BALL_LOGTHROTTLE_INFO(k_MAX_INSTANT_MESSAGES, k_NS_PER_MESSAGE)
<< "QueueHandle [" << this
<< "] registering Subscription [id = " << downstreamId
<< ", downstreamSubQueueId = " << downstreamSubId
<< ", upstreamId = " << upstreamId << "]";
BMQ_LOGTHROTTLE_INFO() << "QueueHandle [" << this
<< "] registering Subscription [id = "
<< downstreamId
<< ", downstreamSubQueueId = " << downstreamSubId
<< ", upstreamId = " << upstreamId << "]";

const bsl::shared_ptr<Downstream>& subStream = downstream(downstreamSubId);

Expand Down Expand Up @@ -719,7 +723,7 @@ bool QueueHandle::unregisterSubStream(
itSubscription != d_subscriptions.end();) {
const SubscriptionSp& subscription = itSubscription->second;
if (subscription->d_downstreamSubQueueId == downstreamSubQueueId) {
BALL_LOGTHROTTLE_INFO(k_MAX_INSTANT_MESSAGES, k_NS_PER_MESSAGE)
BMQ_LOGTHROTTLE_INFO()
<< "Queue '" << d_queue_sp->description() << "' handle "
<< this << " removing Subscription "
<< itSubscription->first;
Expand Down Expand Up @@ -878,7 +882,7 @@ void QueueHandle::deliverMessage(

// Increasing resource usage ('update()' above) made us hit our
// maxUnconfirmed limit.
BALL_LOGTHROTTLE_INFO(k_MAX_INSTANT_MESSAGES, k_NS_PER_MESSAGE)
BMQ_LOGTHROTTLE_INFO()
<< "Queue '" << d_queue_sp->description()
<< "' with subscription [" << subscriptions[i] << "]"
<< " of client '"
Expand Down
68 changes: 39 additions & 29 deletions src/groups/mqb/mqbblp/mqbblp_relayqueueengine.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -74,6 +74,10 @@ const bsls::Types::Int64 k_NS_PER_MESSAGE =
bdlt::TimeUnitRatio::k_NANOSECONDS_PER_MINUTE / k_MAX_INSTANT_MESSAGES;
// Time interval between messages logged with throttling.

#define BMQ_LOGTHROTTLE_INFO() \
BALL_LOGTHROTTLE_INFO(k_MAX_INSTANT_MESSAGES, k_NS_PER_MESSAGE) \
<< "[THROTTLED] "
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Overall, what do you thing about defining this macro in one of our helper headers, with an unique prefix?

Do we actually need to make these constants k_MAX_INSTANT_MESSAGES/k_NS_PER_MESSAGE different?

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Overall, what do you thing about defining this macro in one of our helper headers, with an unique prefix?

Do we actually need to make these constants k_MAX_INSTANT_MESSAGES/k_NS_PER_MESSAGE different?

No opinion on this. For now, let's not centralize this


// ====================
// class LimitedPrinter
// ====================
Expand Down Expand Up @@ -279,27 +283,29 @@ void RelayQueueEngine::onHandleConfiguredDispatched(
return; // RETURN
}

if (bmqp_ctrlmsg::StatusCategory::E_SUCCESS == status.category()) {
BALL_LOG_INFO << "Received success 'configure-stream' response for "
<< "handle [" << handle << "] for queue ["
<< d_queueState_p->uri() << "], for parameters "
<< downStreamParameters;
}
else {
BALL_LOG_WARN
<< "#QUEUE_CONFIGURE_FAILURE "
<< "Received failed 'configure-stream' response for handle '"
<< handle->client() << ":" << handle->id() << "' for queue '"
<< d_queueState_p->uri() << "', for parameters "
<< downStreamParameters << ", but assuming success.";
}

BALL_LOGTHROTTLE_INFO_BLOCK(k_MAX_INSTANT_MESSAGES, k_NS_PER_MESSAGE)
{
if (bmqp_ctrlmsg::StatusCategory::E_SUCCESS == status.category()) {
BALL_LOG_INFO
<< "[THROTTLED] Received success 'configure-stream' response"
<< " for handle [" << handle << "] for queue ["
<< d_queueState_p->uri() << "], for parameters "
<< downStreamParameters;
}
else {
BALL_LOG_WARN
<< "[THROTTLED] #QUEUE_CONFIGURE_FAILURE "
<< "Received failed 'configure-stream' response for handle '"
<< handle->client() << ":" << handle->id() << "' for queue '"
<< d_queueState_p->uri() << "', for parameters "
<< downStreamParameters << ", but assuming success.";
}

mqbcmd::RoundRobinRouter outrr(d_allocator_p);
context->d_routing_sp->loadInternals(&outrr);

BALL_LOG_OUTPUT_STREAM << "For queue [" << d_queueState_p->uri()
BALL_LOG_OUTPUT_STREAM << "[THROTTLED] For queue ["
<< d_queueState_p->uri()
<< "] new routing will be "
<< LimitedPrinter(outrr, 2048, d_allocator_p);
}
Expand Down Expand Up @@ -332,7 +338,8 @@ void RelayQueueEngine::onHandleConfiguredDispatched(
mqbcmd::QueueEngine outqe(d_allocator_p);
loadInternals(&outqe);

BALL_LOG_OUTPUT_STREAM << "For queue [" << d_queueState_p->uri()
BALL_LOG_OUTPUT_STREAM << "[THROTTLED] For queue ["
<< d_queueState_p->uri()
<< "], the engine config is "
<< LimitedPrinter(outqe, 2048, d_allocator_p);
}
Expand Down Expand Up @@ -687,9 +694,10 @@ void RelayQueueEngine::configureApp(
&previousParameters,
upstreamSubQueueId);

BALL_LOG_INFO << "For queue '" << d_queueState_p->uri() << "', about to "
<< "rebuild upstream state [current stream parameters: "
<< previousParameters << "]";
BMQ_LOGTHROTTLE_INFO()
<< "For queue '" << d_queueState_p->uri()
678098 marked this conversation as resolved.
Show resolved Hide resolved
<< "', about to rebuild upstream state [current stream parameters: "
<< previousParameters << "]";

rebuildUpstreamState(context->d_routing_sp.get(),
&appState,
Expand All @@ -708,12 +716,13 @@ void RelayQueueEngine::configureApp(
if (hadParameters && previousParameters == streamParamsToSend) {
// Last advertised stream parameters for this queue are same as the
// newly advertised ones. No need to send any notification upstream.
BALL_LOG_INFO << "For queue [" << d_queueState_p->uri()
<< "], last advertised stream parameter by the queue"
<< " were same as newly advertised ones: "
<< previousParameters
<< ". Not sending configure-queue request upstream, but"
<< " returning success to downstream client.";

BMQ_LOGTHROTTLE_INFO()
<< "For queue [" << d_queueState_p->uri()
678098 marked this conversation as resolved.
Show resolved Hide resolved
<< "], last advertised stream parameter by the queue"
<< " were same as newly advertised ones: " << previousParameters
<< ". Not sending configure-queue request upstream, but"
<< " returning success to downstream client.";

// Set the parameters and inform downstream client of success
handle->setStreamParameters(streamParameters);
Expand Down Expand Up @@ -788,9 +797,10 @@ void RelayQueueEngine::rebuildUpstreamState(Routers::AppContext* context,

d_queueState_p->setUpstreamParameters(upstreamParams, upstreamSubQueueId);

BALL_LOG_INFO << "For queue '" << d_queueState_p->uri() << "', rebuilt "
<< "upstream parameters [new upstream parameters: "
<< upstreamParams << "]";
BMQ_LOGTHROTTLE_INFO()
<< "For queue '" << d_queueState_p->uri()
678098 marked this conversation as resolved.
Show resolved Hide resolved
<< "', rebuilt upstream parameters [new upstream parameters: "
<< upstreamParams << "]";
}

void RelayQueueEngine::applyConfiguration(App_State& app,
Expand Down
4 changes: 2 additions & 2 deletions src/groups/mqb/mqbnet/mqbnet_tcpsessionfactory.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -94,10 +94,10 @@ namespace {
BALL_LOG_SET_NAMESPACE_CATEGORY("MQBNET.TCPSESSIONFACTORY");

const int k_CONNECT_INTERVAL = 2;
const int k_SESSION_DESTROY_WAIT = 10;
const int k_SESSION_DESTROY_WAIT = 20;
// Maximum time to wait (in seconds) for all session to be destroyed
// during stop sequence.
const int k_CLIENT_CLOSE_WAIT = 10;
const int k_CLIENT_CLOSE_WAIT = 20;
// Time to wait incrementally (in seconds) for all clients and
// proxies to be destroyed during stop sequence.

Expand Down
Loading