From 4ab21efc222ea6f1b0b2b79568e900ccc0cb8288 Mon Sep 17 00:00:00 2001 From: Bernard Normier Date: Fri, 7 Feb 2025 09:02:00 -0500 Subject: [PATCH] Implement Ice.Trace.Dispatch in C++ (#3512) --- cpp/include/Ice/OutgoingResponse.h | 2 + cpp/src/Ice/LoggerMiddleware.cpp | 88 ++++++++++++++------- cpp/src/Ice/LoggerMiddleware.h | 18 ++++- cpp/src/Ice/ObjectAdapterI.cpp | 19 ++++- cpp/src/Ice/OutgoingResponse.cpp | 27 +++++++ cpp/src/Ice/PropertiesAdminI.cpp | 21 +---- cpp/src/Ice/ThreadPool.cpp | 8 +- cpp/src/Ice/TraceLevels.cpp | 1 + cpp/src/Ice/TraceLevels.h | 3 + csharp/src/Ice/Internal/LoggerMiddleware.cs | 52 ++++++++---- 10 files changed, 164 insertions(+), 75 deletions(-) diff --git a/cpp/include/Ice/OutgoingResponse.h b/cpp/include/Ice/OutgoingResponse.h index 0e87c22857c..e31f925ff5c 100644 --- a/cpp/include/Ice/OutgoingResponse.h +++ b/cpp/include/Ice/OutgoingResponse.h @@ -27,6 +27,8 @@ namespace Ice UnknownException = 7 }; + ICE_API std::ostream& operator<<(std::ostream&, ReplyStatus); + /** * Represents the response to an incoming request. It's the argument to the sendResponse callback accepted by * Object::dispatch. diff --git a/cpp/src/Ice/LoggerMiddleware.cpp b/cpp/src/Ice/LoggerMiddleware.cpp index 8804d099c8a..3320c10de37 100644 --- a/cpp/src/Ice/LoggerMiddleware.cpp +++ b/cpp/src/Ice/LoggerMiddleware.cpp @@ -8,15 +8,23 @@ using namespace std; using namespace Ice; using namespace IceInternal; -LoggerMiddleware::LoggerMiddleware(Ice::ObjectPtr next, LoggerPtr logger, int warningLevel, ToStringMode toStringMode) +LoggerMiddleware::LoggerMiddleware( + Ice::ObjectPtr next, + LoggerPtr logger, + int traceLevel, + const char* traceCat, + int warningLevel, + ToStringMode toStringMode) : _next(std::move(next)), _logger(std::move(logger)), + _traceLevel(traceLevel), + _traceCat(traceCat), _warningLevel(warningLevel), _toStringMode(toStringMode) { assert(_next); assert(_logger); - assert(_warningLevel > 0); + assert(_traceLevel > 0 || _warningLevel > 0); } void @@ -32,19 +40,22 @@ LoggerMiddleware::dispatch(Ice::IncomingRequest& request, function_traceLevel > 0) + { + self->logDispatch(response.replyStatus(), response.current()); + } break; case ReplyStatus::ObjectNotExist: case ReplyStatus::FacetNotExist: case ReplyStatus::OperationNotExist: - if (self->_warningLevel > 1) + if (self->_traceLevel > 0 || self->_warningLevel > 1) { - self->warning(response.exceptionDetails(), response.current()); + self->logDispatchException(response.exceptionDetails(), response.current()); } break; default: - self->warning(response.exceptionDetails(), response.current()); + self->logDispatchException(response.exceptionDetails(), response.current()); break; } sendResponse(std::move(response)); @@ -52,65 +63,86 @@ LoggerMiddleware::dispatch(Ice::IncomingRequest& request, function 0) + { + logDispatch(ReplyStatus::UserException, request.current()); + } throw; } catch (const RequestFailedException& ex) { - if (_warningLevel > 1) + if (_traceLevel > 0 || _warningLevel > 1) { - warning(ex, request.current()); + logDispatchException(ex, request.current()); } throw; } - catch (const Ice::Exception& ex) + catch (const Ice::LocalException& ex) { - warning(ex, request.current()); + logDispatchException(ex, request.current()); throw; } catch (const std::exception& ex) { - warning(ex.what(), request.current()); + logDispatchException(ex.what(), request.current()); throw; } catch (...) { - warning("c++ exception", request.current()); + logDispatchException("c++ exception", request.current()); throw; } } void -LoggerMiddleware::warning(const Exception& ex, const Current& current) const noexcept +LoggerMiddleware::logDispatch(ReplyStatus replyStatus, const Current& current) const noexcept +{ + Trace out{_logger, _traceCat}; + out << "dispatch of " << current.operation << " to "; + printTarget(out, current); + out << " returned a response status with reply status " << replyStatus; +} + +void +LoggerMiddleware::logDispatchException(string_view exceptionDetails, const Current& current) const noexcept { - Warning out(_logger); - out << "dispatch exception: " << ex; - warning(out, current); + Warning out{_logger}; + out << "failed to dispatch " << current.operation << " to "; + printTarget(out, current); + + if (!exceptionDetails.empty()) + { + out << ":\n" << exceptionDetails; + } } void -LoggerMiddleware::warning(const string& exceptionDetails, const Current& current) const noexcept +LoggerMiddleware::logDispatchException(const LocalException& ex, const Current& current) const noexcept { - Warning out(_logger); - out << "dispatch exception: " << exceptionDetails; - warning(out, current); + ostringstream os; + os << ex; + logDispatchException(os.str(), current); } void -LoggerMiddleware::warning(Warning& out, const Current& current) const noexcept +LoggerMiddleware::printTarget(LoggerOutputBase& out, const Current& current) const noexcept { - out << "\nidentity: " << identityToString(current.id, _toStringMode); - out << "\nfacet: " << escapeString(current.facet, "", _toStringMode); - out << "\noperation: " << current.operation; + out << identityToString(current.id, _toStringMode); + + if (!current.facet.empty()) + { + out << " -f " << escapeString(current.facet, "", _toStringMode); + } if (current.con) { - for (Ice::ConnectionInfoPtr connInfo = current.con->getInfo(); connInfo; connInfo = connInfo->underlying) + for (ConnectionInfoPtr connInfo = current.con->getInfo(); connInfo; connInfo = connInfo->underlying) { - Ice::IPConnectionInfoPtr ipConnInfo = dynamic_pointer_cast(connInfo); + auto ipConnInfo = dynamic_pointer_cast(connInfo); if (ipConnInfo) { - out << "\nremote host: " << ipConnInfo->remoteAddress << " remote port: " << ipConnInfo->remotePort; + out << " over " << ipConnInfo->localAddress << ':' << ipConnInfo->localPort << "<->" + << ipConnInfo->remoteAddress << ':' << ipConnInfo->remotePort; break; } } diff --git a/cpp/src/Ice/LoggerMiddleware.h b/cpp/src/Ice/LoggerMiddleware.h index 169c79ca246..b2cab5b0ef6 100644 --- a/cpp/src/Ice/LoggerMiddleware.h +++ b/cpp/src/Ice/LoggerMiddleware.h @@ -14,17 +14,27 @@ namespace IceInternal class LoggerMiddleware final : public Ice::Object, public std::enable_shared_from_this { public: - LoggerMiddleware(Ice::ObjectPtr next, Ice::LoggerPtr logger, int warningLevel, Ice::ToStringMode toStringMode); + LoggerMiddleware( + Ice::ObjectPtr next, + Ice::LoggerPtr logger, + int traceLevel, + const char* traceCat, + int warningLevel, + Ice::ToStringMode toStringMode); void dispatch(Ice::IncomingRequest&, std::function) final; private: - void warning(const Ice::Exception&, const Ice::Current&) const noexcept; - void warning(const std::string&, const Ice::Current&) const noexcept; - void warning(Ice::Warning&, const Ice::Current&) const noexcept; + void logDispatch(Ice::ReplyStatus replyStatus, const Ice::Current& current) const noexcept; + void logDispatchException(std::string_view message, const Ice::Current& current) const noexcept; + void + logDispatchException(const Ice::LocalException& localException, const Ice::Current& current) const noexcept; + void printTarget(Ice::LoggerOutputBase& out, const Ice::Current& current) const noexcept; Ice::ObjectPtr _next; Ice::LoggerPtr _logger; + int _traceLevel; + const char* _traceCat; int _warningLevel; Ice::ToStringMode _toStringMode; }; diff --git a/cpp/src/Ice/ObjectAdapterI.cpp b/cpp/src/Ice/ObjectAdapterI.cpp index 93ade0bed48..e07fbaccbfe 100644 --- a/cpp/src/Ice/ObjectAdapterI.cpp +++ b/cpp/src/Ice/ObjectAdapterI.cpp @@ -833,10 +833,23 @@ Ice::ObjectAdapterI::initialize(optional router) if (logger) { int warningLevel = _instance->initializationData().properties->getIcePropertyAsInt("Ice.Warn.Dispatch"); - if (warningLevel > 0) + if (_instance->traceLevels()->dispatch > 0 || warningLevel > 0) { - use([logger, warningLevel, toStringMode = _instance->toStringMode()](ObjectPtr next) - { return make_shared(std::move(next), logger, warningLevel, toStringMode); }); + use( + [logger, + warningLevel, + traceLevel = _instance->traceLevels()->dispatch, + traceCat = _instance->traceLevels()->dispatchCat, + toStringMode = _instance->toStringMode()](ObjectPtr next) + { + return make_shared( + std::move(next), + logger, + traceLevel, + traceCat, + warningLevel, + toStringMode); + }); } } diff --git a/cpp/src/Ice/OutgoingResponse.cpp b/cpp/src/Ice/OutgoingResponse.cpp index 55612212f54..1ce637863e2 100644 --- a/cpp/src/Ice/OutgoingResponse.cpp +++ b/cpp/src/Ice/OutgoingResponse.cpp @@ -184,6 +184,33 @@ namespace } } // anonymous namespace +ostream& +Ice::operator<<(ostream& os, ReplyStatus replyStatus) +{ + switch (replyStatus) + { + case ReplyStatus::Ok: + return os << "Ok"; + case ReplyStatus::UserException: + return os << "UserException"; + case ReplyStatus::ObjectNotExist: + return os << "ObjectNotExist"; + case ReplyStatus::FacetNotExist: + return os << "FacetNotExist"; + case ReplyStatus::OperationNotExist: + return os << "OperationNotExist"; + case ReplyStatus::UnknownLocalException: + return os << "UnknownLocalException"; + case ReplyStatus::UnknownUserException: + return os << "UnknownUserException"; + case ReplyStatus::UnknownException: + return os << "UnknownException"; + default: + assert(false); + return os << static_cast(replyStatus); + } +} + OutgoingResponse::OutgoingResponse( ReplyStatus replyStatus, string exceptionId, diff --git a/cpp/src/Ice/PropertiesAdminI.cpp b/cpp/src/Ice/PropertiesAdminI.cpp index 18d6d18fdd1..834e6785603 100644 --- a/cpp/src/Ice/PropertiesAdminI.cpp +++ b/cpp/src/Ice/PropertiesAdminI.cpp @@ -161,26 +161,7 @@ namespace IceInternal auto callbacks = _updateCallbacks; for (const auto& cb : callbacks) { - try - { - cb(changes); - } - catch (const std::exception& ex) - { - if (_properties->getIcePropertyAsInt("Ice.Warn.Dispatch") > 1) - { - Warning out(_logger); - out << "properties admin update callback raised unexpected exception:\n" << ex; - } - } - catch (...) - { - if (_properties->getIcePropertyAsInt("Ice.Warn.Dispatch") > 1) - { - Warning out(_logger); - out << "properties admin update callback raised unexpected exception:\nunknown c++ exception"; - } - } + cb(changes); } } } diff --git a/cpp/src/Ice/ThreadPool.cpp b/cpp/src/Ice/ThreadPool.cpp index 7b24770ac28..d073b6048a1 100644 --- a/cpp/src/Ice/ThreadPool.cpp +++ b/cpp/src/Ice/ThreadPool.cpp @@ -417,18 +417,18 @@ IceInternal::ThreadPool::executeFromThisThread(function call, const Ice: } catch (const std::exception& ex) { - if (_instance->initializationData().properties->getIcePropertyAsInt("Ice.Warn.Dispatch") > 1) + if (_instance->initializationData().properties->getIcePropertyAsInt("Ice.Warn.Executor") > 1) { Warning out(_instance->initializationData().logger); - out << "dispatch exception:\n" << ex; + out << "executor exception:\n" << ex; } } catch (...) { - if (_instance->initializationData().properties->getIcePropertyAsInt("Ice.Warn.Dispatch") > 1) + if (_instance->initializationData().properties->getIcePropertyAsInt("Ice.Warn.Executor") > 1) { Warning out(_instance->initializationData().logger); - out << "dispatch exception:\nunknown c++ exception"; + out << "executor exception: unknown c++ exception"; } } } diff --git a/cpp/src/Ice/TraceLevels.cpp b/cpp/src/Ice/TraceLevels.cpp index 279ec06e5ea..20275542468 100644 --- a/cpp/src/Ice/TraceLevels.cpp +++ b/cpp/src/Ice/TraceLevels.cpp @@ -10,6 +10,7 @@ using namespace IceInternal; IceInternal::TraceLevels::TraceLevels(const PropertiesPtr& properties) { const string keyBase = "Ice.Trace."; + const_cast(dispatch) = properties->getIcePropertyAsInt(keyBase + dispatchCat); const_cast(network) = properties->getIcePropertyAsInt(keyBase + networkCat); const_cast(protocol) = properties->getIcePropertyAsInt(keyBase + protocolCat); const_cast(retry) = properties->getIcePropertyAsInt(keyBase + retryCat); diff --git a/cpp/src/Ice/TraceLevels.h b/cpp/src/Ice/TraceLevels.h index 48a810c06e3..3db9825d254 100644 --- a/cpp/src/Ice/TraceLevels.h +++ b/cpp/src/Ice/TraceLevels.h @@ -13,6 +13,9 @@ namespace IceInternal public: TraceLevels(const Ice::PropertiesPtr&); + const int dispatch{0}; + const char* dispatchCat{"Dispatch"}; + const int network{0}; const char* networkCat{"Network"}; diff --git a/csharp/src/Ice/Internal/LoggerMiddleware.cs b/csharp/src/Ice/Internal/LoggerMiddleware.cs index 27daa544f45..ff494c567c0 100644 --- a/csharp/src/Ice/Internal/LoggerMiddleware.cs +++ b/csharp/src/Ice/Internal/LoggerMiddleware.cs @@ -3,6 +3,7 @@ #nullable enable using System.Diagnostics; +using System.Text; namespace Ice.Internal; @@ -82,30 +83,43 @@ internal LoggerMiddleware(Object next, Logger logger, int traceLevel, string tra Debug.Assert(_traceLevel > 0 || _warningLevel > 0); } - private void logDispatch(ReplyStatus replyStatus, Current current) => - _logger.trace( - _traceCat, - $"dispatch of {current.operation} to {getTarget(current)} returned a response with reply status {replyStatus}"); + private void logDispatch(ReplyStatus replyStatus, Current current) + { + var sb = new StringBuilder(); + sb.Append("dispatch of "); + sb.Append(current.operation); + sb.Append(" to "); + printTarget(sb, current); + sb.Append(" returned a response with reply status "); + sb.Append(replyStatus); + + _logger.trace(_traceCat, sb.ToString()); + } private void logDispatchException(string? exceptionDetails, Current current) { - if (exceptionDetails is null) - { - _logger.warning($"failed to dispatch {current.operation} to {getTarget(current)}"); - } - else + var sb = new StringBuilder(); + sb.Append("failed to dispatch "); + sb.Append(current.operation); + sb.Append(" to "); + printTarget(sb, current); + + if (exceptionDetails is not null) { - _logger.warning( - $"failed to dispatch {current.operation} to {getTarget(current)}:\n{exceptionDetails}"); + sb.Append(":\n"); + sb.Append(exceptionDetails); } + + _logger.warning(sb.ToString()); } - private string getTarget(Current current) + private void printTarget(StringBuilder sb, Current current) { - string target = Ice.Util.identityToString(current.id, _toStringMode); + sb.Append(Ice.Util.identityToString(current.id, _toStringMode)); if (current.facet.Length > 0) { - target = $"{target} -f {current.facet}"; + sb.Append(" -f "); + sb.Append(Ice.UtilInternal.StringUtil.escapeString(current.facet, "", _toStringMode)); } if (current.con is not null) @@ -116,7 +130,14 @@ private string getTarget(Current current) { if (p is IPConnectionInfo ipInfo) { - target = $"{target} over {ipInfo.localAddress}:{ipInfo.localPort}<->{ipInfo.remoteAddress}:{ipInfo.remotePort}"; + sb.Append(" over "); + sb.Append(ipInfo.localAddress); + sb.Append(':'); + sb.Append(ipInfo.localPort); + sb.Append("<->"); + sb.Append(ipInfo.remoteAddress); + sb.Append(':'); + sb.Append(ipInfo.remotePort); break; } } @@ -125,6 +146,5 @@ private string getTarget(Current current) { } } - return target; } }