Fix RefCne to check prior TurnOn/Off request status

Inlcudes fixes to remove infinite loop of Turn On requests issued by RefCne
to ConnectivityService.
Fix to correct the debug message printed to logcat
Changed logcat macro to print all RefCne messages to ERROR to avoid recompiling
of an engineering build to do the same for test purposes.
Added return to after the check for invalid net preference
Fixed typo in the debug msg printed to logcat in SetPreferredNetwork

Change-Id: Id2d96176c2dfff69a2cd2937ad3960c1a7eb5061
CRs-fixed: 229108,227945

3 files changed, 109 insertions, 44 deletions

diff --git a/reference-cne/inc/RefCneDefs.h b/reference-cne/inc/RefCneDefs.h
index 8421d92..901cc23 100644
--- a/reference-cne/inc/RefCneDefs.h
+++ b/reference-cne/inc/RefCneDefs.h
@@ -49,14 +49,14 @@
 
   #define RCNE_LOG_TAG "RefCnE"
 
-  #define RCNE_MSG_WARN(...) LOG(LOG_WARN,RCNE_LOG_TAG,__VA_ARGS__)
+  #define RCNE_MSG_WARN(...) LOG(LOG_ERROR,RCNE_LOG_TAG,__VA_ARGS__)
   #define RCNE_MSG_WARN1 RCNE_MSG_WARN
   #define RCNE_MSG_WARN2 RCNE_MSG_WARN
   #define RCNE_MSG_WARN3 RCNE_MSG_WARN
   #define RCNE_MSG_WARN4 RCNE_MSG_WARN
   #define RCNE_MSG_WARN5 RCNE_MSG_WARN
 
-  #define RCNE_MSG_DEBUG(...) LOG(LOG_DEBUG,RCNE_LOG_TAG,__VA_ARGS__)
+  #define RCNE_MSG_DEBUG(...) LOG(LOG_ERROR,RCNE_LOG_TAG,__VA_ARGS__)
   #define RCNE_MSG_DEBUG1 RCNE_MSG_DEBUG
   #define RCNE_MSG_DEBUG2 RCNE_MSG_DEBUG
   #define RCNE_MSG_DEBUG3 RCNE_MSG_DEBUG
@@ -70,14 +70,14 @@
   #define RCNE_MSG_ERROR4 RCNE_MSG_ERROR
   #define RCNE_MSG_ERROR5 RCNE_MSG_ERROR
 
-  #define RCNE_MSG_VERBOSE(...) LOG(LOG_VERBOSE,RCNE_LOG_TAG,__VA_ARGS__)
+  #define RCNE_MSG_VERBOSE(...) LOG(LOG_ERROR,RCNE_LOG_TAG,__VA_ARGS__)
   #define RCNE_MSG_VERBOSE1 RCNE_MSG_VERBOSE
   #define RCNE_MSG_VERBOSE2 RCNE_MSG_VERBOSE
   #define RCNE_MSG_VERBOSE3 RCNE_MSG_VERBOSE
   #define RCNE_MSG_VERBOSE4 RCNE_MSG_VERBOSE
   #define RCNE_MSG_VERBOSE5 RCNE_MSG_VERBOSE
 
-  #define RCNE_MSG_INFO(...) LOG(LOG_INFO,RCNE_LOG_TAG,__VA_ARGS__)
+  #define RCNE_MSG_INFO(...) LOG(LOG_ERROR,RCNE_LOG_TAG,__VA_ARGS__)
   #define RCNE_MSG_INFO1 RCNE_MSG_INFO
   #define RCNE_MSG_INFO2 RCNE_MSG_INFO
   #define RCNE_MSG_INFO3 RCNE_MSG_INFO
diff --git a/reference-cne/src/CRefCne.cpp b/reference-cne/src/CRefCne.cpp
index c3ef46a..34e354e 100644
--- a/reference-cne/src/CRefCne.cpp
+++ b/reference-cne/src/CRefCne.cpp
@@ -162,7 +162,7 @@ void CRefCne::RefCneCmdHdlr
       break;
     default:
       {
-        RCNE_MSG_ERROR("Command hdlr: Unrecognized command recvd [%d]",cmd);
+        RCNE_MSG_ERROR("Command hdlr: unrecognized cmd [%d] recvd",cmd);
       }
   }
 
@@ -188,14 +188,15 @@ void CRefCne::ProcessStateChange
   cne_rat_type  myPrefNet = GetPreferredNetwork();
   /* Check if the preferred network is set, if not then phone is
    * in boot up process, so do nothing */
-  if (myPrefNet == NULL)
+  if ((myPrefNet != CNE_RAT_WLAN) && (myPrefNet!= CNE_RAT_WWAN))
   {
-    RCNE_MSG_ERROR("Invalid network preference: [%d]", myPrefNet);
+    RCNE_MSG_ERROR("Preferred network unset; waiting until it is set");
+    return;
   }
 
   CRefCneRadio* pref;
   CRefCneRadio* nonpref;
-  if (myPrefNet == CNE_RAT_WLAN )
+  if (myPrefNet == CNE_RAT_WLAN)
   {
     RCNE_MSG_INFO("PSC: Preferred RAT is Wifi, non-preferred RAT is WWAN");
     pref = RefCneWifi;
@@ -223,27 +224,87 @@ void CRefCne::ProcessStateChange
        *  If both Radios are up turn off the non-preferred network
        */
       {
-        RCNE_MSG_INFO("PSC: both radios are up; disconnecting"
-                       " non-preferred radio");
-        nonpref->TurnOff();
-        nonpref->SetPending(REF_CNE_NET_PENDING_DISCONNECT);
+        RCNE_MSG_INFO("PSC: both radios are up; checking connect/ disconnect"
+                      " request status");
+	switch (nonpref->iIsConActionPending())
+	{
+          case REF_CNE_NET_PENDING_CONNECT:
+            /**
+             * Check for power-up or out of coverage scenarios
+             */
+            {
+              RCNE_MSG_INFO("PSC: device was in start up or perhaps out of"
+                             " range for all networks and now it's in range");
+              RCNE_MSG_DEBUG("PSC: turning off non-pref network...");
+              nonpref->TurnOff();
+              nonpref->SetPending(REF_CNE_NET_PENDING_DISCONNECT);
+            }
+            break;
+          case REF_CNE_NET_PENDING_DISCONNECT:
+            {
+              RCNE_MSG_DEBUG("PSC: non-pref network is in pending disconnect"
+                             " state; waiting for disconnect event");
+            }
+            break;
+          default:
+            /**
+             * Check for special cases if both networks are up
+             */
+            {
+              RCNE_MSG_DEBUG("PSC: no pending request found for non-pref net,"
+                             " checking for pref net request status");
+              if (pref->iIsConActionPending() == REF_CNE_NET_PENDING_CONNECT)
+              {
+                RCNE_MSG_DEBUG("PSC: pref network [%d]  is now available,"
+                               " turning off non-pref network",myPrefNet);
+                pref->ClearPending();
+                nonpref->TurnOff();
+                nonpref->SetPending(REF_CNE_NET_PENDING_DISCONNECT);
+              }
+              else
+              {
+                RCNE_MSG_DEBUG("PSC: unexpected bringup of non-pref network"
+                               "  -- special case ?");
+              }
+            }
+        }
       }
-	  break;
+      break;
     case ONE_RADIO_IS_CONNECTED:
       /**
-       * If only one radio is up check if it is the preferred one,
+       * If only one network is up, check if it is the preferred one,
        * if not then turn on the preferred network
        */
       {
         if (pref->bIsDataConnected() == FALSE)
         {
-          RCNE_MSG_INFO("PSC: Non preferred radio is up; reconnecting"
-                        " preferred radio");
-          pref->TurnOn();
-          pref->SetPending(REF_CNE_NET_PENDING_CONNECT);
-        } else
+          RCNE_MSG_INFO("PSC: non pref network is up; requesting"
+                         " pref net connection");
+          if (pref->iIsConActionPending() == REF_CNE_NET_PENDING_CONNECT)
+          {
+            RCNE_MSG_DEBUG("PSC: pref net is in pending connect state");
+          }
+          else
+          {
+            pref->TurnOn();
+            pref->SetPending(REF_CNE_NET_PENDING_CONNECT);
+          }
+          if (nonpref->iIsConActionPending() == REF_CNE_NET_PENDING_CONNECT)
+          {
+            nonpref->ClearPending();
+          }
+        }
+        else
         {
           RCNE_MSG_INFO("PSC: Preferred radio is connected");
+          if (pref->iIsConActionPending() == REF_CNE_NET_PENDING_CONNECT)
+          {
+            pref->ClearPending();
+          }
+          if (nonpref->iIsConActionPending() == REF_CNE_NET_PENDING_DISCONNECT)
+          {
+            nonpref->ClearPending();
+          }
         }
       }
 	  break;
@@ -253,16 +314,30 @@ void CRefCne::ProcessStateChange
        * both networks
        */
       {
-        RCNE_MSG_INFO("All radios are disconnected; trying to reconnect");
-        pref->TurnOn();
-        pref->SetPending(REF_CNE_NET_PENDING_CONNECT);
-        nonpref->TurnOn();
-        nonpref->SetPending(REF_CNE_NET_PENDING_CONNECT);
+        RCNE_MSG_WARN("All radios are disconnected; trying to reconnect");
+        if (pref->iIsConActionPending() == REF_CNE_NET_NOT_PENDING)
+        {
+          pref->TurnOn();
+          pref->SetPending(REF_CNE_NET_PENDING_CONNECT);
+        }
+        else
+        {
+          RCNE_MSG_DEBUG("PSC: pref net is in pending connect state");
+        }
+        if (nonpref->iIsConActionPending() == REF_CNE_NET_NOT_PENDING)
+        {
+          nonpref->TurnOn();
+          nonpref->SetPending(REF_CNE_NET_PENDING_CONNECT);
+        }
+        else
+        {
+          RCNE_MSG_DEBUG("PSC: non-pref net is in pending connect state");
+        }
       }
-	  break;
+      break;
     default:
       {
-        RCNE_MSG_WARN("PSC: number of active networks is invalid");
+        RCNE_MSG_ERROR("PSC: number of active networks is invalid");
         //ASSERT(0);
       }
   }
@@ -300,14 +375,6 @@ ref_cne_ret_enum_type CRefCne::UpdateWlanInfoCmd
   RCNE_MSG_DEBUG("UWLICH: WLAN info status is valid, will update status");
   RefCneWifi->UpdateStatus(WlanInfoCmd->status);
   RCNE_MSG_DEBUG("UWLICH: WLAN info status updated");
-  if ( (RefCneWifi->bIsDataConnected()
-        && (RefCneWifi->iIsConActionPending()== REF_CNE_NET_PENDING_CONNECT) )
-       || (!RefCneWifi->bIsDataConnected()
-           && (RefCneWifi->iIsConActionPending()== REF_CNE_NET_PENDING_DISCONNECT) ) )
-  {
-    RCNE_MSG_DEBUG("UWLICH: Was in connection action pending state; clearing it");
-    RefCneWifi->ClearPending();
-  }
   RCNE_MSG_INFO("UWLICH: handled Wlan update info cmd");
   return(REF_CNE_RET_OK);
 }
@@ -344,14 +411,6 @@ ref_cne_ret_enum_type CRefCne::UpdateWwanInfoCmd
   RCNE_MSG_DEBUG("UWWICH: wwan status is valid, now updating status");
   RefCneWwan->UpdateStatus(WwanInfoCmd->status);
   RCNE_MSG_DEBUG("UWWICH: wwan status is updated");
-  if ( (RefCneWwan->bIsDataConnected()
-        && (RefCneWwan->iIsConActionPending()== REF_CNE_NET_PENDING_CONNECT) )
-       || (!RefCneWwan->bIsDataConnected()
-           && (RefCneWwan->iIsConActionPending()== REF_CNE_NET_PENDING_DISCONNECT) ) )
-  {
-    RCNE_MSG_DEBUG("UWWICH: Was in connection action pending state; clearing it");
-    RefCneWwan->ClearPending();
-  }
   RCNE_MSG_INFO("UWWICH: handled Wwan update info cmd");
   return(REF_CNE_RET_OK);
 }
@@ -384,7 +443,6 @@ ref_cne_ret_enum_type CRefCne::SetPrefNetCmd
     RCNE_MSG_ERROR("SPNCH: Invalid Network ID [%d] received",*pPrefNetwork);
     return(REF_CNE_RET_ERROR);
   }
-  RCNE_MSG_INFO("SPNCH: setting preferred network to [%d]",*pPrefNetwork);
   SetPreferredNetwork(pPrefNetwork);
   RCNE_MSG_DEBUG("SPNCH: handled set preferred network cmd");
   return(REF_CNE_RET_OK);
@@ -405,6 +463,10 @@ void CRefCne::SetPreferredNetwork
   cne_rat_type* pNetId
 )
 {
+  (*pNetId) ?
+    RCNE_MSG_DEBUG("SPN: setting preferred network to [wlan]") :
+    RCNE_MSG_DEBUG("SPN: setting preferred network to [wwan]");
+
   m_siPrefNetwork = *pNetId;
   return;
 }
diff --git a/reference-cne/src/CRefCneRadio.cpp b/reference-cne/src/CRefCneRadio.cpp
index 0d55214..f724bce 100644
--- a/reference-cne/src/CRefCneRadio.cpp
+++ b/reference-cne/src/CRefCneRadio.cpp
@@ -151,6 +151,7 @@ void CRefCneRadio::ClearPending
 (
 )
 {
+  RCNE_MSG_DEBUG("CP: cleared network [%d] request status",m_iMyRatType);
   m_iRequestState = REF_CNE_NET_NOT_PENDING;
 }
 /*=============================================================================
@@ -203,7 +204,7 @@ void CRefCneRadio::UpdateStatus
         m_iNetConState = REF_CNE_NET_STATE_CONNECTED;
 		RCNE_MSG_DEBUG("refcne %d radio state is connected",m_iMyRatType);
       }
-	  break;
+      break;
     default:
       {
         m_iNetConState = REF_CNE_NET_STATE_DISCONNECTED;
@@ -274,6 +275,8 @@ void CRefCneRadio::SetPending
   ref_cne_net_con_req_enum_type flag
 )
 {
+  RCNE_MSG_DEBUG("SP: setting network [%d] request status to [%d]",
+                 m_iMyRatType,flag);
   m_iRequestState = flag;
 }