Increased sprout error logs from EANTC work

include/scscfsproutlet.h

@@ -185,7 +185,7 @@ class SCSCFSproutlet : public Sproutlet
   /// @param tsx_start_time_usec  - The time the request was received.
   /// @param video_call           - True if INVITE was for a video session,
   ///                               false otherwise.
-  void track_session_setup_time(uint64_t tsx_start_time_usec, bool video_call);
+  uint64_t track_session_setup_time(uint64_t tsx_start_time_usec, bool video_call);
 
   /// Translate RequestURI using ENUM service if appropriate.
   ///

src/Makefile

@@ -9,6 +9,7 @@ SPROUT_COMMON_SOURCES := logger.cpp \
                          stack.cpp \
                          dnsparser.cpp \
                          dnscachedresolver.cpp \
+                         static_dns_cache.cpp \
                          baseresolver.cpp \
                          sipresolver.cpp \
                          bono.cpp \

src/authenticationsproutlet.cpp

@@ -870,7 +870,7 @@ void AuthenticationSproutletTsx::create_challenge(pjsip_digest_credential* crede
       // We've failed to store the nonce in memcached, so we have no hope of
       // successfully authenticating any repsonse to a 401 Unauthorized.  Send
       // a 500 Server Internal Error instead.
-      TRC_DEBUG("Failed to store nonce in memcached");
+      TRC_DEBUG("Failed to store nonce in memcached, for impi %s", impi.c_str());
       rsp->line.status.code = PJSIP_SC_INTERNAL_SERVER_ERROR;
       rsp->line.status.reason = *pjsip_get_status_text(PJSIP_SC_INTERNAL_SERVER_ERROR);
 

src/compositesproutlet.cpp

@@ -1,5 +1,5 @@
 /**
- * @file compositesproutlet.h
+ * @file compositesproutlet.cpp
  *
  * Copyright (C) Metaswitch Networks 2017
  * If license terms are provided to you in a COPYING file in the root directory

src/dnsresolver.cpp

@@ -1,5 +1,5 @@
 /**
- * @file enumservice.cpp class implementation for an ENUM service provider
+ * @file dnsresolver.cpp class implementation for a DNS resolver
  *
  * Copyright (C) Metaswitch Networks 2015
  * If license terms are provided to you in a COPYING file in the root directory

src/enumservice.cpp

@@ -1,5 +1,5 @@
 /**
- * @file dnsresolver.cpp class implementation for a DNS resolver
+ * @file enumservice.cpp class implementation for an ENUM service provider
  *
  * Copyright (C) Metaswitch Networks 2017
  * If license terms are provided to you in a COPYING file in the root directory

src/icscfsproutlet.cpp

@@ -403,6 +403,7 @@ void ICSCFSproutletRegTsx::on_rx_response(pjsip_msg* rsp, int fork_id)
         // capabilitires, or the HSS is temporarily unavailable). There was at
         // least one valid S-CSCF (as this is retry processing). The I-CSCF
         // must return 504 (TS 24.229, 5.3.1.3) in this case.
+        TRC_ERROR("I-CSCF can't select an S-CSCF for REGISTER request");
         rsp->line.status.code = PJSIP_SC_SERVER_TIMEOUT;
         rsp->line.status.reason =
           *pjsip_get_status_text(rsp->line.status.code);

src/main.cpp

@@ -89,6 +89,7 @@ extern "C" {
 #include "sprout_alarmdefinition.h"
 #include "sproutlet_options.h"
 #include "astaire_impistore.h"
+#include "updater.h"
 
 enum OptionTypes
 {
@@ -2033,7 +2034,15 @@ int main(int argc, char* argv[])
                                            hc);
 
   // Create a DNS resolver and a SIP specific resolver.
-  dns_resolver = new DnsCachedResolver(opt.dns_servers, opt.dns_timeout);
+  dns_resolver = new DnsCachedResolver(opt.dns_servers,
+                                       opt.dns_timeout,
+                                       "/etc/clearwater/dns.json");
+
+  // Reload dns.json on SIGHUP
+  Updater<void, DnsCachedResolver>* dns_updater =
+         new Updater<void, DnsCachedResolver>(dns_resolver,
+                                              std::mem_fun(&DnsCachedResolver::reload_static_records));
+
   if (opt.pcscf_enabled)
   {
     sip_resolver = new SIPResolver(dns_resolver, opt.sip_blacklist_duration, 0);
@@ -2595,6 +2604,7 @@ int main(int argc, char* argv[])
   delete enum_service;
   delete scscf_acr_factory;
 
+  delete dns_updater;
   delete sip_resolver;
   delete http_resolver;
   delete astaire_resolver;

src/rphservice.cpp

@@ -221,9 +221,9 @@ SIPEventPriorityLevel RPHService::lookup_priority(std::string rph_value,
     // We received a message with an unknown RPH value. This could be because:
     //  - It is not defined in the IANA namespace.
     //  - It is not assigned a priority value in the rph.json file.
-    TRC_WARNING("An unknown RPH value \"%s\" was received on an incoming message."
-                " This message will be handled, but will not be prioritized.",
-                rph_value.c_str());
+    TRC_DEBUG("An unknown RPH value \"%s\" was received on an incoming message."
+              " This message will be handled, but will not be prioritized.",
+              rph_value.c_str());
     SAS::Event event(trail, SASEvent::RPH_VALUE_UNKNOWN, 0);
     event.add_var_param(rph_value);
     SAS::report_event(event);

src/scscfsproutlet.cpp

@@ -341,7 +341,7 @@ void SCSCFSproutlet::track_app_serv_comm_success(const std::string& uri,
   }
 }
 
-void SCSCFSproutlet::track_session_setup_time(uint64_t tsx_start_time_usec,
+uint64_t SCSCFSproutlet::track_session_setup_time(uint64_t tsx_start_time_usec,
                                               bool video_call)
 {
   // Calculate how long it has taken to setup the session.
@@ -357,6 +357,8 @@ void SCSCFSproutlet::track_session_setup_time(uint64_t tsx_start_time_usec,
   {
     _audio_session_setup_time_tbl->accumulate(ringing_usec);
   }
+
+  return ringing_usec;
 }
 
 SCSCFSproutletTsx::SCSCFSproutletTsx(SCSCFSproutlet* scscf,
@@ -858,7 +860,15 @@ void SCSCFSproutletTsx::on_tx_response(pjsip_msg* rsp)
       ((st_code == PJSIP_SC_RINGING) ||
        PJSIP_IS_STATUS_IN_CLASS(st_code, 200)))
   {
-    _scscf->track_session_setup_time(_tsx_start_time_usec, _video_call);
+    uint64_t setup_time = _scscf->track_session_setup_time(_tsx_start_time_usec, _video_call);
+    if (setup_time > 2000000)
+    {
+      pjsip_cid_hdr* cid = PJSIP_MSG_CID_HDR(rsp);
+      TRC_VERBOSE("Call setup time exceeded 2 seconds for Call-ID %.*s (was %lu us)",
+                  cid->id.slen,
+                  cid->id.ptr,
+                  setup_time);
+    }
     _record_session_setup_time = false;
   }
 }
@@ -1115,6 +1125,7 @@ pjsip_status_code SCSCFSproutletTsx::determine_served_user(pjsip_msg* req)
           if ((http_code == HTTP_SERVER_UNAVAILABLE) || (http_code == HTTP_GATEWAY_TIMEOUT))
           {
             // Send a SIP 504 response if we got a 500/503 HTTP response.
+            TRC_VERBOSE("AS retargeting failed to lookup IFCs for served user");
             status_code = PJSIP_SC_SERVER_TIMEOUT;
           }
           else
@@ -1228,7 +1239,7 @@ pjsip_status_code SCSCFSproutletTsx::determine_served_user(pjsip_msg* req)
       }
       else
       {
-        TRC_DEBUG("Failed to retrieve ServiceProfile for %s", served_user.c_str());
+        TRC_VERBOSE("Failed to retrieve ServiceProfile for %s", served_user.c_str());
 
         if ((http_code == HTTP_SERVER_UNAVAILABLE) || (http_code == HTTP_GATEWAY_TIMEOUT))
         {

src/thread_dispatcher.cpp

@@ -523,7 +523,7 @@ static void reject_rx_msg_overload(pjsip_rx_data* rdata, SAS::TrailId trail)
 {
   // Respond statelessly with a 503 Service Unavailable, including a
   // Retry-After header with a zero length timeout.
-  TRC_DEBUG("Rejected request due to overload");
+  TRC_VERBOSE("Rejected request due to overload");
 
   SAS::Marker start_marker(trail, MARKER_ID_START, 1u);
   SAS::report_marker(start_marker);