Implement Ice.Trace.Dispatch in C++ (#3512)

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.

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,85 +40,109 @@ LoggerMiddleware::dispatch(Ice::IncomingRequest& request, function<void(Outgoing
                 {
                     case ReplyStatus::Ok:
                     case ReplyStatus::UserException:
-                        // no warning
+                        if (self->_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));
             });
     }
     catch (const UserException&)
     {
-        // No warning.
+        if (_traceLevel > 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<Ice::IPConnectionInfo>(connInfo);
+            auto ipConnInfo = dynamic_pointer_cast<IPConnectionInfo>(connInfo);
             if (ipConnInfo)
             {
-                out << "\nremote host: " << ipConnInfo->remoteAddress << " remote port: " << ipConnInfo->remotePort;
+                out << " over " << ipConnInfo->localAddress << ':' << ipConnInfo->localPort << "<->"
+                    << ipConnInfo->remoteAddress << ':' << ipConnInfo->remotePort;
                 break;
             }
         }

cpp/src/Ice/LoggerMiddleware.h

@@ -14,17 +14,27 @@ namespace IceInternal
     class LoggerMiddleware final : public Ice::Object, public std::enable_shared_from_this<LoggerMiddleware>
     {
     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<void(Ice::OutgoingResponse)>) 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;
     };

cpp/src/Ice/ObjectAdapterI.cpp

@@ -833,10 +833,23 @@ Ice::ObjectAdapterI::initialize(optional<RouterPrx> 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<LoggerMiddleware>(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<LoggerMiddleware>(
+                        std::move(next),
+                        logger,
+                        traceLevel,
+                        traceCat,
+                        warningLevel,
+                        toStringMode);
+                });
         }
     }
 

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<int>(replyStatus);
+    }
+}
+
 OutgoingResponse::OutgoingResponse(
     ReplyStatus replyStatus,
     string exceptionId,

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);
             }
         }
     }

cpp/src/Ice/ThreadPool.cpp

@@ -417,18 +417,18 @@ IceInternal::ThreadPool::executeFromThisThread(function<void()> 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";
             }
         }
     }

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<int&>(dispatch) = properties->getIcePropertyAsInt(keyBase + dispatchCat);
     const_cast<int&>(network) = properties->getIcePropertyAsInt(keyBase + networkCat);
     const_cast<int&>(protocol) = properties->getIcePropertyAsInt(keyBase + protocolCat);
     const_cast<int&>(retry) = properties->getIcePropertyAsInt(keyBase + retryCat);

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"};