Added tracing for IceLocatorDiscovery (ICE-8072)

6 files changed, 96 insertions, 6 deletions

diff --git a/cpp/src/Ice/PropertyNames.cpp b/cpp/src/Ice/PropertyNames.cpp
index 910a0cc2ace..5e48748d91c 100644
--- a/cpp/src/Ice/PropertyNames.cpp
+++ b/cpp/src/Ice/PropertyNames.cpp
@@ -6,7 +6,7 @@
 // ICE_LICENSE file included in this distribution.
 //
 // **********************************************************************
-// Generated by makeprops.py from file ./config/PropertyNames.xml, Tue May 16 17:04:55 2017
+// Generated by makeprops.py from file ../config/PropertyNames.xml, Wed Feb 14 10:24:07 2018
 
 // IMPORTANT: Do not edit this file -- any edits made here will be lost!
 
@@ -422,6 +422,7 @@ const IceInternal::Property IceLocatorDiscoveryPropsData[] =
     IceInternal::Property("IceLocatorDiscovery.Port", false, 0),
     IceInternal::Property("IceLocatorDiscovery.Interface", false, 0),
     IceInternal::Property("IceLocatorDiscovery.InstanceName", false, 0),
+    IceInternal::Property("IceLocatorDiscovery.Trace.Lookup", false, 0),
 };
 
 const IceInternal::PropertyArray
@@ -1002,6 +1003,7 @@ const IceInternal::Property IceGridPropsData[] =
     IceInternal::Property("IceGrid.Registry.Trace.Admin", false, 0),
     IceInternal::Property("IceGrid.Registry.Trace.Application", false, 0),
     IceInternal::Property("IceGrid.Registry.Trace.Adapter", false, 0),
+    IceInternal::Property("IceGrid.Registry.Trace.Discovery", false, 0),
     IceInternal::Property("IceGrid.Registry.Trace.Locator", false, 0),
     IceInternal::Property("IceGrid.Registry.Trace.Node", false, 0),
     IceInternal::Property("IceGrid.Registry.Trace.Object", false, 0),
diff --git a/cpp/src/Ice/PropertyNames.h b/cpp/src/Ice/PropertyNames.h
index 68085fa56c4..0e04b10933f 100644
--- a/cpp/src/Ice/PropertyNames.h
+++ b/cpp/src/Ice/PropertyNames.h
@@ -6,7 +6,7 @@
 // ICE_LICENSE file included in this distribution.
 //
 // **********************************************************************
-// Generated by makeprops.py from file ./config/PropertyNames.xml, Tue May 16 17:04:55 2017
+// Generated by makeprops.py from file ../config/PropertyNames.xml, Wed Feb 14 10:24:07 2018
 
 // IMPORTANT: Do not edit this file -- any edits made here will be lost!
 
diff --git a/cpp/src/IceGrid/RegistryI.cpp b/cpp/src/IceGrid/RegistryI.cpp
index 960995a68d6..a3501a10b08 100644
--- a/cpp/src/IceGrid/RegistryI.cpp
+++ b/cpp/src/IceGrid/RegistryI.cpp
@@ -53,8 +53,10 @@ class LookupI : public IceLocatorDiscovery::Lookup
 {
 public:
 
-    LookupI(const std::string& instanceName, const WellKnownObjectsManagerPtr& wellKnownObjects) :
-        _instanceName(instanceName), _wellKnownObjects(wellKnownObjects)
+    LookupI(const std::string& instanceName,
+            const WellKnownObjectsManagerPtr& wellKnownObjects,
+            const TraceLevelsPtr& traceLevels) :
+        _instanceName(instanceName), _wellKnownObjects(wellKnownObjects), _traceLevels(traceLevels)
     {
     }
 
@@ -63,11 +65,21 @@ public:
     {
         if(!instanceName.empty() && instanceName != _instanceName)
         {
+            if(_traceLevels->discovery > 1)
+            {
+                Trace out(_traceLevels->logger, _traceLevels->discoveryCat);
+                out << "ignored discovery lookup for instance name `" << instanceName << "':\nreply = " << reply;
+            }
             return; // Ignore.
         }
 
         if(reply)
         {
+            if(_traceLevels->discovery > 0)
+            {
+                Trace out(_traceLevels->logger, _traceLevels->discoveryCat);
+                out << "replying to discovery lookup:\nreply = " << reply;
+            }
             reply->begin_foundLocator(_wellKnownObjects->getLocator());
         }
     }
@@ -82,6 +94,7 @@ private:
 
     const string _instanceName;
     const WellKnownObjectsManagerPtr _wellKnownObjects;
+    const TraceLevelsPtr _traceLevels;
 };
 
 class FinderI : public Ice::LocatorFinder
@@ -624,7 +637,7 @@ RegistryI::startImpl()
         {
             Ice::Identity lookupId = stringToIdentity("IceLocatorDiscovery/Lookup");
             discoveryAdapter = _communicator->createObjectAdapter("IceGrid.Registry.Discovery");
-            discoveryAdapter->add(new LookupI(_instanceName, _wellKnownObjects), lookupId);
+            discoveryAdapter->add(new LookupI(_instanceName, _wellKnownObjects, _traceLevels), lookupId);
         }
         catch(const Ice::LocalException& ex)
         {
diff --git a/cpp/src/IceGrid/TraceLevels.cpp b/cpp/src/IceGrid/TraceLevels.cpp
index 86b4b913e2d..39e54efc1a2 100644
--- a/cpp/src/IceGrid/TraceLevels.cpp
+++ b/cpp/src/IceGrid/TraceLevels.cpp
@@ -37,6 +37,8 @@ TraceLevels::TraceLevels(const Ice::CommunicatorPtr& communicator, const string&
     locatorCat("Locator"),
     session(0),
     sessionCat("Session"),
+    discovery(0),
+    discoveryCat("Discovery"),
     logger(communicator->getLogger())
 {
     Ice::PropertiesPtr properties = communicator->getProperties();
@@ -53,6 +55,7 @@ TraceLevels::TraceLevels(const Ice::CommunicatorPtr& communicator, const string&
     const_cast<int&>(patch) = properties->getPropertyAsInt(keyBase + patchCat);
     const_cast<int&>(locator) = properties->getPropertyAsInt(keyBase + locatorCat);
     const_cast<int&>(session) = properties->getPropertyAsInt(keyBase + sessionCat);
+    const_cast<int&>(discovery) = properties->getPropertyAsInt(keyBase + discoveryCat);
 }
 
 TraceLevels::~TraceLevels()
diff --git a/cpp/src/IceGrid/TraceLevels.h b/cpp/src/IceGrid/TraceLevels.h
index 5a35dcf78af..022929151f3 100644
--- a/cpp/src/IceGrid/TraceLevels.h
+++ b/cpp/src/IceGrid/TraceLevels.h
@@ -57,6 +57,9 @@ public:
     const int session;
     const char* sessionCat;
 
+    const int discovery;
+    const char* discoveryCat;
+
     const Ice::LoggerPtr logger;
 };
 
diff --git a/cpp/src/IceLocatorDiscovery/PluginI.cpp b/cpp/src/IceLocatorDiscovery/PluginI.cpp
index c8af4b35fd9..d2711f48012 100644
--- a/cpp/src/IceLocatorDiscovery/PluginI.cpp
+++ b/cpp/src/IceLocatorDiscovery/PluginI.cpp
@@ -115,6 +115,7 @@ private:
     const int _retryCount;
     const IceUtil::Time _retryDelay;
     const IceUtil::TimerPtr _timer;
+    const int _traceLevel;
 
     string _instanceName;
     bool _warned;
@@ -573,6 +574,7 @@ LocatorI::LocatorI(const string& name,
     _retryCount(p->getPropertyAsIntWithDefault(name + ".RetryCount", 3)),
     _retryDelay(IceUtil::Time::milliSeconds(p->getPropertyAsIntWithDefault(name + ".RetryDelay", 2000))),
     _timer(IceInternal::getInstanceTimer(lookup->ice_getCommunicator())),
+    _traceLevel(p->getPropertyAsInt(name + ".Trace.Lookup")),
     _instanceName(instanceName),
     _warned(false),
     _locator(lookup->ice_getCommunicator()->getDefaultLocator()),
@@ -696,6 +698,13 @@ LocatorI::foundLocator(const Ice::LocatorPrxPtr& locator)
     Lock sync(*this);
     if(!locator || (!_instanceName.empty() && locator->ice_getIdentity().category != _instanceName))
     {
+        if(_traceLevel > 2)
+        {
+            Ice::Trace out(_lookup->ice_getCommunicator()->getLogger(), "Lookup");
+            out << "ignoring locator reply: instance name doesn't match\n";
+            out << "expected = " << _instanceName;
+            out << "received = " << locator->ice_getIdentity().category;
+        }
         return;
     }
 
@@ -727,6 +736,16 @@ LocatorI::foundLocator(const Ice::LocatorPrxPtr& locator)
         _pendingRetryCount = 0;
     }
 
+    if(_traceLevel > 0)
+    {
+        Ice::Trace out(_lookup->ice_getCommunicator()->getLogger(), "Lookup");
+        out << "locator lookup succeeded:\nlocator = " << locator;
+        if(!_instanceName.empty())
+        {
+            out << "\ninstance name = " << _instanceName;
+        }
+    }
+
     Ice::LocatorPrxPtr l = _pendingRequests.empty() ? _locators[locator->ice_getIdentity().category] : _locator;
     if(l)
     {
@@ -813,6 +832,15 @@ LocatorI::invoke(const Ice::LocatorPrxPtr& locator, const RequestPtr& request)
             _pendingRetryCount = _retryCount;
             try
             {
+                if(_traceLevel > 1)
+                {
+                    Ice::Trace out(_lookup->ice_getCommunicator()->getLogger(), "Lookup");
+                    out << "looking up locator:\nlookup = " << _lookup;
+                    if(!_instanceName.empty())
+                    {
+                        out << "\ninstance name = " << _instanceName;
+                    }
+                }
                 for(vector<pair<LookupPrxPtr, LookupReplyPrxPtr> >::const_iterator l = _lookups.begin();
                     l != _lookups.end(); ++l)
                 {
@@ -836,8 +864,19 @@ LocatorI::invoke(const Ice::LocatorPrxPtr& locator, const RequestPtr& request)
                 }
                 _timer->schedule(ICE_SHARED_FROM_THIS, _timeout);
             }
-            catch(const Ice::LocalException&)
+            catch(const Ice::LocalException& ex)
             {
+                if(_traceLevel > 0)
+                {
+                    Ice::Trace out(_lookup->ice_getCommunicator()->getLogger(), "Lookup");
+                    out << "locator lookup failed:\nlookup = " << _lookup;
+                    if(!_instanceName.empty())
+                    {
+                        out << "\ninstance name = " << _instanceName;
+                    }
+                    out << "\n" << ex;
+                }
+
                 for(vector<RequestPtr>::const_iterator p = _pendingRequests.begin(); p != _pendingRequests.end(); ++p)
                 {
                     (*p)->invoke(_voidLocator);
@@ -868,6 +907,17 @@ LocatorI::exception(const Ice::LocalException& ex)
             _warnOnce = false;
         }
 
+        if(_traceLevel > 0)
+        {
+            Ice::Trace out(_lookup->ice_getCommunicator()->getLogger(), "Lookup");
+            out << "locator lookup failed:\nlookup = " << _lookup;
+            if(!_instanceName.empty())
+            {
+                out << "\ninstance name = " << _instanceName;
+            }
+            out << "\n" << ex;
+        }
+
         if(_pendingRequests.empty())
         {
             notify();
@@ -891,6 +941,15 @@ LocatorI::runTimerTask()
     {
         try
         {
+            if(_traceLevel > 1)
+            {
+                Ice::Trace out(_lookup->ice_getCommunicator()->getLogger(), "Lookup");
+                out << "retrying locator lookup:\nlookup = " << _lookup << "\nretry count = " << _pendingRetryCount;
+                if(!_instanceName.empty())
+                {
+                    out << "\ninstance name = " << _instanceName;
+                }
+            }
             _failureCount = 0;
             for(vector<pair<LookupPrxPtr, LookupReplyPrxPtr> >::const_iterator l = _lookups.begin();
                 l != _lookups.end(); ++l)
@@ -922,6 +981,16 @@ LocatorI::runTimerTask()
         _pendingRetryCount = 0;
     }
 
+    if(_traceLevel > 0)
+    {
+        Ice::Trace out(_lookup->ice_getCommunicator()->getLogger(), "Lookup");
+        out << "locator lookup timed out:\nlookup = " << _lookup;
+        if(!_instanceName.empty())
+        {
+            out << "\ninstance name = " << _instanceName;
+        }
+    }
+
     if(_pendingRequests.empty())
     {
         notify();