WHISTLE-244: fix the loggin format, and cleaned up the failover

opensips/opensips.cfg

@@ -12,8 +12,8 @@ memdump=3
 memlog=2
 # open_files_limit=2048
 server_signature=no
-server_header="Server: 2600hz Trunk Store"
-user_agent_header="User-Agent: 2600hz Trunk Store"
+server_header="Server: 2600hz"
+user_agent_header="User-Agent: 2600hz"
 
 ######################################################################
 ## Core Fork Parameters
@@ -137,8 +137,8 @@ modparam("sl", "enable_stats", 1)
 ######################################################################
 ## SIP Transaction UA Module Parameters
 ######################################################################
-modparam("tm", "fr_timer", 5)
-# modparam("tm", "fr_inv_timer", 60)
+modparam("tm", "fr_timer", 2)
+modparam("tm", "fr_inv_timer", 60)
 # modparam("tm", "wt_timer", 5)
 # modparam("tm", "delete_timer", 2)
 # modparam("tm", "T1_timer", 500)
@@ -146,7 +146,7 @@ modparam("tm", "fr_timer", 5)
 # modparam("tm", "ruri_matching", 1)
 # modparam("tm", "via1_matching", 1)
 # modparam("tm", "unix_tx_timeout", 2)
-# modparam("tm", "restart_fr_on_each_reply", 1)
+modparam("tm", "restart_fr_on_each_reply", 1)
 # modparam("tm", "fr_timer_avp", "$avp(i:24)")
 # modparam("tm", "fr_inv_timer_avp", "$avp(i:25)")
 # modparam("tm", "tw_append",
@@ -291,9 +291,14 @@ modparam("mi_fifo", "fifo_name", "/tmp/opensips_fifo")
 ######################################################################
 route
 {
+    xlog("L_INFO", "$ci|start|recieved $oP request $rm $ou");
+    xlog("L_INFO", "$ci|log|source $si:$sp");
+    xlog("L_INFO", "$ci|log|from $fu");
+    xlog("L_INFO", "$ci|log|to $tu");
+
     if (!mf_process_maxfwd_header("10"))
     {
-        xlog("L_WARN", "To many hops to [$ou] from [$si:$sp]");
+        xlog("L_WARN", "$ci|end|to many hops");
 
         sl_send_reply("483", "We refuse to process this endless imbroglio");
 
@@ -302,86 +307,76 @@ route
 
     if (src_ip==myself) 
     {
-        xlog("L_WARN", "Src IP [$ou] from [$si:$sp]");
+        xlog("L_WARN", "$ci|end|sourced from this server");
 
         exit;
     }
 
-    xlog("L_INFO", "Received [$rm] [$ou] from [$si:$sp]");
-    xlog("L_DBG", "    From: [$fu]");
-    xlog("L_DBG", "      To: [$tu]");
-
     if (is_method("OPTIONS|SUBSCRIBE"))
     {
-        xlog("L_NOTICE", "      Method [$rm] is not supported, sending 503 to [$si:$sp]");
+        xlog("L_NOTICE", "$ci|end|unsupported method");
 
         sl_send_reply("503", "Rawr!!");
 
         exit;
     }
 
-    t_on_reply("1");
 
-    t_on_failure("1");
+    if (ds_is_in_list("$si", "$sp", "1") || ds_is_in_list("$si", "$sp", "2"))
+    {           
+        xlog("L_INFO", "$ci|log|originated from internal source");
+
+        # Flag 26 marks the source as a interal server   
+        setflag(26);
+    }
+    else
+    {
+        xlog("L_INFO", "$ci|log|originated from external source");
+    }
 
     if (has_totag())
     {
-        # sequential request withing a dialog should
+        # sequential request within a dialog should
         # take the path determined by record-routing
         if (loose_route())
         {
             append_hf("P-hint: rr-enforced\r\n");
 
-            if (is_method("INVITE"))
+            if (isflagset(26) && is_method("ACK")) 
             {
-                # even if in most of the cases is useless, do RR for
-                # re-INVITEs alos, as some buggy clients do change route set
-                # during the dialog.
-                xlog("L_INFO", "      Record route for loosely routed INVITE on an existing dialog");
-
-                #record_route();
-            }
-
-            if ((ds_is_in_list("$si", "$sp", "1") || ds_is_in_list("$si", "$sp", "2")) && is_method("ACK")) 
-            {
-                xlog("L_INFO", "      Stored [$tU] as belonging to media server [$fd]");
+                xlog("L_INFO", "$ci|log|maintaining contact association to media server $fd");
 
                 cache_store("memcached_callid_hash", "$tU ", "$fd", 3600);
             }
+            
+            xlog("L_INFO", "$ci|log|forwarding based on the route set");
 
-            # route it out to whatever destination was set by loose_route()
-            # in $du (destination URI).
             route(1);
         }
-        else
+        else if ( is_method("ACK") )
         {
-            if ( is_method("ACK") )
+            if ( t_check_trans() )
             {
-                if ( t_check_trans() )
-                {
-                    # non loose-route, but stateful ACK; must be an ACK after
-                    # a 487 or e.g. 404 from upstream server
-                    xlog("L_INFO", "      Forwarding a stateful ACK for a known dialog");
-
-                    t_relay();
-
-                    exit;
-                }
-                else
-                {
-                    # ACK without matching transaction ->
-                    # ignore and discard
-                    xlog("L_NOTICE", "      Recieved ACK from [$si:$sp] for unknown dialog, ignoring");
-
-                    exit;
-                }
-            }
+                # non loose-route, but stateful ACK; must be an ACK after
+                # a 487 or e.g. 404 from upstream server
+                xlog("L_INFO", "$ci|log|in dialog request belongs to a known transaction");
 
-            xlog("L_WARN", "      Recieved [$rm] for a dialog but the RR is invalid, sending 486 to [$si:$sp]");
+                route(1);
+            }
+            else
+            {
+                # ACK without matching transaction ->
+                # ignore and discard
+                xlog("L_NOTICE", "$ci|end|no matching transaction");
 
-            sl_send_reply("486", "PC Load Letter");
+                exit;
+            }
         }
 
+        xlog("L_WARN", "$ci|end|could not route in dialog");
+
+        sl_send_reply("486", "PC Load Letter");
+
         exit;
     }
 
@@ -392,7 +387,13 @@ route
         # then pass it along to concerned parties
         if (t_check_trans())
         {
-            t_relay();
+            xlog("L_INFO", "$ci|log|request belogs to a known transaction");
+
+            route(1);
+        }
+        else
+        {
+            xlog("L_NOTICE", "$ci|end|no matching transaction");
         }
 
         exit;
@@ -402,15 +403,12 @@ route
     # and do standard processing of the message
     t_check_trans();
 
-    # Since it is possible to suppress a second provisional response, the first one can be sent pre-emptively
-    sl_send_reply("100", "Thinking about it...");
-
     # preloaded route checking
     if (loose_route())
     {
         if (!is_method("ACK"))
         {
-            xlog("L_WARN", "    Attempt to route with preloaded Route's [$fu/$tu/$ru/$ci] from [$si:$sp]");
+            xlog("L_WARN", "$ci|end|initial request contained a preloaded route set");
 
             sl_send_reply("403", "Please leave the routing up to us");
 
@@ -422,56 +420,58 @@ route
     {
         if (!add_path_received())
         {
-            xlog("L_ERR", "    Unable to add path for [$rm] [$tu] from [$si:$sp], sending 503");
+            xlog("L_ERR", "$ci|end|unable to add path");
 
             sl_send_reply("503", "Internal path befuddlement");
 
             exit;
         }
-    }
-
-    # is not from media servers
-    if (!ds_is_in_list("$si", "$sp", "1") && !ds_is_in_list("$si", "$sp", "2"))
-    {              
-        if ($ct.fields(uri) && cache_fetch("memcached_callid_hash", "$(ct.fields(uri){uri.user})", $avp(i:55))) 
-        {
-            $rd = $avp(i:55);
 
-            xlog("L_INFO", "      Reconized contact [$ct.fields(uri)] as belonging to media server [$rd]");
-        }
-        else if (cache_fetch("memcached_callid_hash", "$ci", $avp(i:55)))
-        {
-            $rd = $avp(i:55);
+        xlog("L_INFO", "$ci|log|added path");
+    }
 
-            xlog("L_INFO", "      Reconized call-id [$ci] as belonging to media server [$rd]");
+    # is from media servers
+    if (isflagset(26))
+    {
+        xlog("L_INFO", "$ci|log|originated from internal source");
+    }
+    # not from media severs has a contact uri and is in memcache
+    else if ($ct.fields(uri) && cache_fetch("memcached_callid_hash", "$(ct.fields(uri){uri.user})", $avp(i:55))) 
+    {
+        $rd = $avp(i:55);
+        
+        xlog("L_INFO", "$ci|log|contact $(ct.fields(uri){uri.user}) is associated with media server");
+    }
+    # not from media servers and call id is in memcache
+    else if (cache_fetch("memcached_callid_hash", "$ci", $avp(i:55)))
+    {
+        $rd = $avp(i:55);
 
-            if ($ct.fields(uri) && is_method("INVITE")) 
-            {
-                xlog("L_INFO", "      Stored [$(ct.fields(uri){uri.user})] as belonging to media server [$rd]");
+        xlog("L_INFO", "$ci|log|call-id is associated with media server $rd");
 
-                cache_store("memcached_callid_hash", "$(ct.fields(uri){uri.user})", "$rd", 3600);
-            }
-        }
-        else
+        if ($ct.fields(uri) && is_method("INVITE")) 
         {
-            xlog("L_INFO", "      Selecting domain from set 1 using round-robin");
- 
-            ds_select_domain("1", "4");
+            xlog("L_INFO", "$ci|log|associated contact $(ct.fields(uri){uri.user}) with media server $rd");
+
+            cache_store("memcached_callid_hash", "$(ct.fields(uri){uri.user})", "$rd", 3600);
         }
-            
-        remove_hf("X-AUTH-IP");
+    }
+    # not from media servers and no information in memcache
+    else
+    {
+        ds_select_domain("1", "4");
 
-        append_hf("X-AUTH-IP: $si\r\n");
-    } 
+        xlog("L_INFO", "$ci|log|routing call to arbitrary media server");
+    }
 
     # record routing
     if (!is_method("REGISTER|MESSAGE"))
     {
         # Record the route that this request has taken
         # so we remain in the signaling path
-        xlog("L_INFO", "      Adding record route to this message");
-
         record_route();
+
+        xlog("L_INFO", "$ci|log|added this server to the route set");
     }
 
     route(1);
@@ -479,16 +479,33 @@ route
 
 route[1]
 {
-    route("nat_test_and_correct");
+    route("nat_test_and_correct");   
+
+    if ($(rd{ip.isip}) && (ds_is_in_list("$rd", "", "1") || ds_is_in_list("$rd", "", "2"))) 
+    {
+        remove_hf("X-AUTH-IP");
+
+        append_hf("X-AUTH-IP: $si\r\n");
+
+        t_on_reply("internal_reply");
+
+        t_on_failure("internal_fault");
+    }
+    else
+    {
+        t_on_reply("external_reply");
+    }
 
     if (!t_relay())
     {
-        xlog("L_ERR", "    Unable to relay [$rm] [$ru] to [$du], sending 500");
+        xlog("L_ERR", "$ci|end|unable to relay message");
 
         sl_reply_error();
     }
-
-    xlog("L_INFO", "    Sent [$rm] [$ru] to [$rd]");
+    else
+    {
+        xlog("L_INFO", "$ci|pass|$rd");
+    }
 
     exit;
 }
@@ -497,79 +514,86 @@ route[nat_test_and_correct]
 {
     if (client_nat_test("3")) 
     {
-        xlog("L_INFO", "     NAT (SIP): Private IP in contact field or via address differs from source");
+        xlog("L_INFO", "$ci|log|via address differs from source or RFC1918 address in contact");
 
         force_rport();
 
-        if ((method=="REGISTER" || method=="SUBSCRIBE" || (method=="INVITE" && !has_totag())))
-        {
-            xlog("L_INFO", "     NAT (SIP): Activating keep alive pings");
-
-            nat_keepalive();
-        }
+        #xlog("L_INFO", "$ci|log|forced rport");
 
         fix_contact();
+
+        #xlog("L_INFO", "$ci|log|fixed contact");
     }
 
     if (has_body("application/sdp") && nat_uac_test("8"))
     {
-        xlog("L_INFO", "     NAT (SDP): Private IP in SDP");
+        xlog("L_INFO", "$ci|log|SDP contains a RFC1918 address");
+
+        #xlog("L_INFO", "$ci|log|rewrite SDP connection data with source address");
+
+        #xlog("L_INFO", "$ci|log|rewrite SDP origin with source address ");
 
         fix_nated_sdp("10");
     }
 }
 
-onreply_route[1]
+onreply_route[external_reply]
 {
+    xlog("L_INFO", "$ci|start|recieved external reply $rs $rr");
+    xlog("L_INFO", "$ci|log|source $si:$sp");
+
+    route("nat_test_and_correct");
+
+    xlog("L_INFO", "$ci|pass|$(<request>si)");
+}
+
+onreply_route[internal_reply]
+{
+    xlog("L_INFO", "$ci|start|recieved internal reply $rs $rr");
+    xlog("L_INFO", "$ci|log|source $si:$sp");
+
     route("nat_test_and_correct");
 
     if (t_check_status("(407)|(401)"))
     {
         cache_store("memcached_callid_hash", "$ci ", "$si", 60);
 
-        xlog("L_INFO", "      Stored call-id [$ci] as belonging to media server [$si]");
+        xlog("L_INFO", "$ci|log|associated call-id with media server $si");
     }
+
+    xlog("L_INFO", "$ci|pass|$(<request>si)");
 }
 
-failure_route[1]
+failure_route[internal_fault]
 {
     if (t_was_cancelled()) 
     {
+        xlog("L_INFO", "$ci|end|transaction was cancelled");
+
         exit;
     }
 
     if (t_check_status("(408)|(5[0-9][0-9])"))
     {
-        xlog("L_ERR", "    Media server [$rd] replied with error [$rs] for [$ru], disabling");
+        xlog("L_INFO", "$ci|start|recieved or generated negative reply $rm");
+        xlog("L_INFO", "$ci|log|source $si:$sp");
+        xlog("L_INFO", "$ci|log|status $rs");
+        xlog("L_INFO", "$ci|log|reason $rr");
+
+        xlog("L_ERR", "$ci|log|moving media server $rd to probing mode");
 
         ds_mark_dst("p");
 
-#        if (ds_next_domain())
         if(ds_select_domain("1", "4"))
         {
-            xlog("L_ERR", "    Hunting for avaliable media server...");
-
-            xlog("L_INFO", "    Sent [$rm] [$ru] to [$rd]");
+            xlog("L_INFO", "$ci|log|routing call to arbitrary media server");
 
             if ($ct.fields(uri) && is_method("INVITE")) 
             {
-                xlog("L_INFO", "      Stored [$(ct.fields(uri){uri.user})] as belonging to media server [$rd]");
+                xlog("L_INFO", "$ci|log|associated contact $(ct.fields(uri){uri.user}) with media server $rd");
 
                 cache_store("memcached_callid_hash", "$(ct.fields(uri){uri.user})", "$rd", 3600);
             }
-
-            t_relay();
-
-            exit;
         }
     }
-    else if(!cache_fetch("memcached_callid_hash", "$ci", $avp(i:55)))
-    {
-        xlog("L_INFO", "    Failed to route call from carrier, sending 486");
-
-        t_reply("486", "The ratio of people to cake is too big");
-    }
-
-    exit;
 }
-