Merge branch 'episys/master' into episys/andrew/debugging_rach+fixing_rx_unpack

common/utils/LOG/log.c

@@ -477,6 +477,50 @@ char *log_getthreadname(char *threadname,
   }
 }
 
+#if LOG_MINIMAL
+void logMinimal(int comp, int level, const char *format, ...)
+{
+    struct timespec ts;
+    if (clock_gettime(CLOCK_MONOTONIC, &ts) == -1)
+        abort();
+
+    char buf[MAX_LOG_TOTAL];
+    int n = snprintf(buf, sizeof(buf), "%lu.%06lu [%s] %c ",
+                     ts.tv_sec,
+                     ts.tv_nsec / 1000,
+                     g_log->log_component[comp].name,
+                     level);
+    if (n < 0 || n >= sizeof(buf))
+    {
+        fprintf(stderr, "%s: n=%d\n", __func__, n);
+        return;
+    }
+
+    va_list args;
+    va_start(args, format);
+    int m = vsnprintf(buf + n, sizeof(buf) - n, format, args);
+    va_end(args);
+
+    if (m < 0)
+    {
+        fprintf(stderr, "%s: n=%d m=%d\n", __func__, n, m);
+        return;
+    }
+
+    int len = n + m;
+    if (len > sizeof(buf) - 1)
+    {
+        len = sizeof(buf) - 1;
+    }
+    if (buf[len - 1] != '\n')
+    {
+        buf[len++] = '\n';
+    }
+
+    write(STDOUT_FILENO, buf, len);
+}
+#endif // LOG_MINIMAL
+
 static int log_header(char *log_buffer,
                       int buffsize,
                       int comp,

common/utils/LOG/log.h

@@ -387,10 +387,32 @@ int32_t write_file_matlab(const char *fname, const char *vname, void *data, int
 #define LOG_DUMP_DOUBLE     1
 // debugging macros
 #define LOG_F  LOG_I           /* because  LOG_F was originaly to dump a message or buffer but is also used as a regular level...., to dump use LOG_DUMPMSG */
+
+#define LOG_MINIMAL 1 /* 1 for minimal logging: E, W and A */
+
+#if LOG_MINIMAL
+
+  void logMinimal(int component, int level, const char *format, ...) __attribute__((format(printf, 3, 4)));
+# define LOG_E(COMPONENT, ...) do if (1) logMinimal(COMPONENT, 'E', __VA_ARGS__); while (0)
+# define LOG_W(COMPONENT, ...) do if (1) logMinimal(COMPONENT, 'W', __VA_ARGS__); while (0)
+# define LOG_A(COMPONENT, ...) do if (1) logMinimal(COMPONENT, 'A', __VA_ARGS__); while (0) /* logs intended for analysis */
+# define LOG_I(COMPONENT, ...) do if (0) logMinimal(COMPONENT, 'I', __VA_ARGS__); while (0)
+# define LOG_D(COMPONENT, ...) do if (0) logMinimal(COMPONENT, 'D', __VA_ARGS__); while (0)
+# define LOG_T(COMPONENT, ...) do if (0) logMinimal(COMPONENT, 'T', __VA_ARGS__); while (0)
+
+# define LOG_M(FILE, VECTOR, DATA, LEN, DEC, FORMAT) ((void) 0)
+# define LOG_DUMPFLAG(D) 0
+# define LOG_DEBUGFLAG(D) 0
+# define LOG_DUMPMSG(C, B, S, X...) ((void) 0)
+# define VLOG(C, L, F, ARGS) ((void) 0)
+
+#else // LOG_MINIMAL
+
 #  if T_TRACER
 /* per component, level dependent macros */
 #    define LOG_E(c, x...) do { if (T_stdout) { if( g_log->log_component[c].level >= OAILOG_ERR    ) logRecord_mt(__FILE__, __FUNCTION__, __LINE__,c, OAILOG_ERR, x)     ;} else { T(T_LEGACY_ ## c ## _ERROR, T_PRINTF(x))   ;}} while (0)
 #    define LOG_W(c, x...) do { if (T_stdout) { if( g_log->log_component[c].level >= OAILOG_WARNING) logRecord_mt(__FILE__, __FUNCTION__, __LINE__,c, OAILOG_WARNING, x) ;} else { T(T_LEGACY_ ## c ## _WARNING, T_PRINTF(x)) ;}} while (0)
+#    define LOG_A LOG_I
 #    define LOG_I(c, x...) do { if (T_stdout) { if( g_log->log_component[c].level >= OAILOG_INFO   ) logRecord_mt(__FILE__, __FUNCTION__, __LINE__,c, OAILOG_INFO, x)    ;} else { T(T_LEGACY_ ## c ## _INFO, T_PRINTF(x))    ;}} while (0)
 #    define LOG_D(c, x...) do { if (T_stdout) { if( g_log->log_component[c].level >= OAILOG_DEBUG  ) logRecord_mt(__FILE__, __FUNCTION__, __LINE__,c, OAILOG_DEBUG, x)   ;} else { T(T_LEGACY_ ## c ## _DEBUG, T_PRINTF(x))   ;}} while (0)
 #    define LOG_T(c, x...) do { if (T_stdout) { if( g_log->log_component[c].level >= OAILOG_TRACE  ) logRecord_mt(__FILE__, __FUNCTION__, __LINE__,c, OAILOG_TRACE, x)   ;} else { T(T_LEGACY_ ## c ## _TRACE, T_PRINTF(x))   ;}} while (0)
@@ -403,11 +425,10 @@ int32_t write_file_matlab(const char *fname, const char *vname, void *data, int
 /* bitmask dependent macros, to generate debug file such as matlab file or message dump */
 #    define LOG_DUMPFLAG(D) (g_log->dump_mask & D)
 #    define LOG_M(file, vector, data, len, dec, format) do { write_file_matlab(file, vector, data, len, dec, format);} while(0)/* */
-/* define variable only used in LOG macro's */
-#    define LOG_VAR(A,B) A B
 #  else /* T_TRACER: remove all debugging and tracing messages, except errors */
 #    define LOG_I(c, x...) do {logRecord_mt(__FILE__, __FUNCTION__, __LINE__,c, OAILOG_INFO, x) ; } while(0)/* */
 #    define LOG_W(c, x...) do {logRecord_mt(__FILE__, __FUNCTION__, __LINE__,c, OAILOG_WARNING, x) ; } while(0)/* */
+#    define LOG_A LOG_I
 #    define LOG_E(c, x...) do {logRecord_mt(__FILE__, __FUNCTION__, __LINE__,c, OAILOG_ERR, x) ; } while(0)/* */
 #    define LOG_D(c, x...) do {logRecord_mt(__FILE__, __FUNCTION__, __LINE__,c, OAILOG_DEBUG, x) ; } while(0)/* */
 #    define LOG_T(c, x...) /* */
@@ -417,8 +438,9 @@ int32_t write_file_matlab(const char *fname, const char *vname, void *data, int
 #    define LOG_DEBUGFLAG(D)  ( 0 )
 #    define LOG_DUMPFLAG(D) ( 0 )
 #    define LOG_M(file, vector, data, len, dec, format) do { write_file_matlab(file, vector, data, len, dec, format);} while(0)
-#    define LOG_VAR(A,B)
 #  endif /* T_TRACER */
+#endif // LOG_MINIMAL
+
 /* avoid warnings for variables only used in LOG macro's but set outside debug section */
 #define GCC_NOTUSED   __attribute__((unused))
 #define LOG_USEDINLOG_VAR(A,B) GCC_NOTUSED A B

executables/main-ocp.c

@@ -1065,14 +1065,14 @@ void init_pdcp(void) {
 }
 
 static  void wait_nfapi_init(char *thread_name) {
-  printf( "waiting for NFAPI PNF connection and population of global structure (%s)\n",thread_name);
+  LOG_I(ENB_APP, "waiting for NFAPI PNF connection and population of global structure (%s)\n",thread_name);
   pthread_mutex_lock( &nfapi_sync_mutex );
 
   while (nfapi_sync_var<0)
     pthread_cond_wait( &nfapi_sync_cond, &nfapi_sync_mutex );
 
   pthread_mutex_unlock(&nfapi_sync_mutex);
-  printf( "NFAPI: got sync (%s)\n", thread_name);
+  LOG_I(ENB_APP, "NFAPI: got sync (%s)\n", thread_name);
 }
 
 void terminate_task(module_id_t mod_id, task_id_t from, task_id_t to) {

nfapi/oai_integration/nfapi_vnf.c

@@ -1182,7 +1182,7 @@ int oai_nfapi_dl_config_req(nfapi_dl_config_request_t *dl_config_req) {
             {
                 uint16_t dl_rnti = dl_config_req->dl_config_request_body.dl_config_pdu_list[i].dlsch_pdu.dlsch_pdu_rel8.rnti;
                 uint16_t numPDUs = dl_config_req->dl_config_request_body.number_pdu;
-                LOG_I(MAC, "(OAI eNB) Sending dl_config_req at VNF during Frame: %d and Subframe: %d,"
+                LOG_A(MAC, "(OAI eNB) Sending dl_config_req at VNF during Frame: %d and Subframe: %d,"
                            " with a RNTI value of: %x and with number of PDUs: %u\n",
                       NFAPI_SFNSF2SFN(dl_config_req->sfn_sf),NFAPI_SFNSF2SF(dl_config_req->sfn_sf), dl_rnti, numPDUs);
             }

openair1/PHY/INIT/lte_init.c

@@ -95,7 +95,7 @@ void phy_config_request(PHY_Config_t *phy_config) {
   int                 Ncp            = cfg->subframe_config.dl_cyclic_prefix_type.value;
   int                 p_eNB          = cfg->rf_config.tx_antenna_ports.value;
   uint32_t            dl_CarrierFreq = cfg->nfapi_config.earfcn.value;
-  LOG_I(PHY,"Configuring MIB for instance %d, CCid %d : (band %d,N_RB_DL %d, N_RB_UL %d, Nid_cell %d,eNB_tx_antenna_ports %d,Ncp %d,DL freq %u,phich_config.resource %d, phich_config.duration %d)\n",
+  LOG_A(PHY,"Configuring MIB for instance %d, CCid %d : (band %d,N_RB_DL %d, N_RB_UL %d, Nid_cell %d,eNB_tx_antenna_ports %d,Ncp %d,DL freq %u,phich_config.resource %d, phich_config.duration %d)\n",
         Mod_id, CC_id, eutra_band, dl_Bandwidth, ul_Bandwidth, Nid_cell, p_eNB,Ncp,dl_CarrierFreq,
         cfg->phich_config.phich_resource.value,
         cfg->phich_config.phich_duration.value);

openair1/PHY/INIT/nr_init.c

@@ -466,7 +466,7 @@ void nr_phy_config_request(NR_PHY_Config_t *phy_config) {
   AssertFatal(fp->ul_CarrierFreq==(fp->dl_CarrierFreq+dlul_offset), "Disagreement in uplink frequency for band %d\n", fp->nr_band);
   
   fp->threequarter_fs = openair0_cfg[0].threequarter_fs;
-  LOG_I(PHY,"Configuring MIB for instance %d, : (Nid_cell %d,DL freq %llu, UL freq %llu)\n",
+  LOG_A(PHY,"Configuring MIB for instance %d, : (Nid_cell %d,DL freq %llu, UL freq %llu)\n",
         Mod_id,
         gNB_config->cell_config.phy_cell_id.value,
         (unsigned long long)fp->dl_CarrierFreq,

openair2/F1AP/f1ap_du_rrc_message_transfer.c

@@ -718,7 +718,7 @@ int DU_send_UL_RRC_MESSAGE_TRANSFER(instance_t instance,
           LOG_E(F1AP, "Did not find the UE context associated with UE RNTOI %x, ue_context_p is NULL\n", rnti);
 
         } else {
-          LOG_I(F1AP, "Processing RRCConnectionSetupComplete UE %x\n", rnti);
+          LOG_A(F1AP, "Processing RRCConnectionSetupComplete UE %x\n", rnti);
           ue_context_p->ue_context.Status = RRC_CONNECTED;
         }
         break;

openair2/LAYER2/MAC/config.c

@@ -797,7 +797,7 @@ int rrc_mac_config_req_eNB(module_id_t Mod_idP,
     RC.mac[Mod_idP]->common_channels[CC_idP].Ncp = Ncp;
     RC.mac[Mod_idP]->common_channels[CC_idP].eutra_band = eutra_band;
     RC.mac[Mod_idP]->common_channels[CC_idP].dl_CarrierFreq = dl_CarrierFreq;
-    LOG_I(MAC,
+    LOG_A(MAC,
           "Configuring MIB for instance %d, CCid %d : (band %d,N_RB_DL %d,Nid_cell %d,p %d,DL freq %u,phich_config.resource %d, phich_config.duration %d)\n",
           Mod_idP,
           CC_idP,
@@ -1048,7 +1048,7 @@ int rrc_mac_config_req_eNB(module_id_t Mod_idP,
     while(RC.mac[Mod_idP]->if_inst->PHY_config_req == NULL) {
       // DJP AssertFatal(RC.mac[Mod_idP]->if_inst->PHY_config_req != NULL,"if_inst->phy_config_request is null\n");
       usleep(100 * 1000);
-      printf("Waiting for PHY_config_req\n");
+      LOG_I(MAC, "Waiting for PHY_config_req\n");
     }
   }
 

openair2/LAYER2/MAC/eNB_scheduler_RA.c

@@ -925,7 +925,7 @@ generate_Msg4(module_id_t module_idP,
               module_idP, CC_idP, frameP, subframeP, UE_id, rrc_sdu_length);
         //          AssertFatal(rrc_sdu_length > 0,
         //          "[MAC][eNB Scheduler] CCCH not allocated, rrc_sdu_length: %d\n", rrc_sdu_length);
-        LOG_I(MAC,"[eNB %d][RAPROC] CC_id %d Frame %d, subframeP %d: Generating Msg4 with RRC Piggyback (RNTI %x)\n",
+        LOG_A(MAC,"[eNB %d][RAPROC] CC_id %d Frame %d, subframeP %d: Generating Msg4 with RRC Piggyback (RNTI %x)\n",
               module_idP, CC_idP, frameP, subframeP, ra->rnti);
         /// Choose first 4 RBs for Msg4, should really check that these are free!
         first_rb = 0;

openair2/LAYER2/MAC/rar_tools_ue.c

@@ -96,7 +96,7 @@ uint16_t ue_process_rar(const module_id_t module_idP, const int CC_id, const fra
     return (0xffff);
   }
 
-  LOG_I(MAC,
+  LOG_A(MAC,
         "[UE %d][RAPROC] Frame %d Received RAR (%02x|%02x.%02x.%02x.%02x.%02x.%02x) for preamble %d/%d\n",
         module_idP, frameP, *(uint8_t *) rarh, rar[0], rar[1], rar[2],
         rar[3], rar[4], rar[5], rarh->RAPID, preamble_index);

openair2/PHY_INTERFACE/phy_stub_UE.c

@@ -1352,7 +1352,7 @@ static void print_rx_ind(nfapi_rx_indication_t *p)
     {
     case NFAPI_RACH_INDICATION:
       encoded_size = nfapi_p7_message_pack(&UL->rach_ind, buffer, sizeof(buffer), NULL);
-      LOG_I(MAC, "RACH_IND sent to Proxy, Size: %d Frame %d Subframe %d\n", encoded_size,
+      LOG_A(MAC, "RACH_IND sent to Proxy, Size: %d Frame %d Subframe %d\n", encoded_size,
             NFAPI_SFNSF2SFN(UL->rach_ind.sfn_sf), NFAPI_SFNSF2SF(UL->rach_ind.sfn_sf));
       break;
     case NFAPI_CRC_INDICATION:

openair2/RRC/LTE/rrc_UE.c

@@ -505,7 +505,7 @@ static void rrc_ue_generate_RRCConnectionSetupComplete( const protocol_ctxt_t *c
   }
 
   size = do_RRCConnectionSetupComplete(ctxt_pP->module_id, buffer, Transaction_id, nas_msg_length, nas_msg);
-  LOG_I(RRC,"[UE %d][RAPROC] Frame %d Subframe %d : Logical Channel UL-DCCH (SRB1), Generating RRCConnectionSetupComplete (bytes%d, eNB %d)\n",
+  LOG_A(RRC,"[UE %d][RAPROC] Frame %d Subframe %d : Logical Channel UL-DCCH (SRB1), Generating RRCConnectionSetupComplete (bytes%d, eNB %d)\n",
         ctxt_pP->module_id,ctxt_pP->frame, ctxt_pP->subframe, size, eNB_index);
   LOG_D(RLC,
         "[FRAME %05d][RRC_UE][MOD %02d][][--- PDCP_DATA_REQ/%d Bytes (RRCConnectionSetupComplete to eNB %d MUI %d) --->][PDCP][MOD %02d][RB %02d]\n",
@@ -606,7 +606,7 @@ int rrc_ue_decode_ccch( const protocol_ctxt_t *const ctxt_pP, const SRB_INFO *co
           break;
 
         case LTE_DL_CCCH_MessageType__c1_PR_rrcConnectionSetup:
-          LOG_I(RRC,
+          LOG_A(RRC,
                 "[UE%d][RAPROC] Frame %d : Logical Channel DL-CCCH (SRB0), Received RRCConnectionSetup RNTI %x\n",
                 ctxt_pP->module_id,
                 ctxt_pP->frame,
@@ -1618,7 +1618,7 @@ rrc_ue_process_ueCapabilityEnquiry(
         xer_fprint(stdout, &asn_DEF_LTE_UL_DCCH_Message, (void *)&ul_dcch_msg);
       }
 
-      LOG_I(RRC,"UECapabilityInformation Encoded %zd bits (%zd bytes)\n",enc_rval.encoded,(enc_rval.encoded+7)/8);
+      LOG_A(RRC,"UECapabilityInformation Encoded %zd bits (%zd bytes)\n",enc_rval.encoded,(enc_rval.encoded+7)/8);
       rrc_data_req_ue (
         ctxt_pP,
         DCCH,

openair2/RRC/LTE/rrc_eNB.c

@@ -150,7 +150,7 @@ init_SI(
   LOG_D(RRC,"%s()\n\n\n\n",__FUNCTION__);
 
   if(configuration->radioresourceconfig[CC_id].mbms_dedicated_serving_cell == TRUE) {
-    LOG_I(RRC, "Configuring MIB FeMBMS (N_RB_DL %d)\n",
+    LOG_A(RRC, "Configuring MIB FeMBMS (N_RB_DL %d)\n",
           (int)configuration->N_RB_DL[CC_id]);
     RC.rrc[ctxt_pP->module_id]->carrier[CC_id].MIB_FeMBMS = (uint8_t *) malloc16(4);
     do_MIB_FeMBMS(&RC.rrc[ctxt_pP->module_id]->carrier[CC_id],
@@ -250,7 +250,7 @@ init_SI(
     carrier->N_RB_DL         = configuration->N_RB_DL[CC_id];
     carrier->pbch_repetition = configuration->pbch_repetition[CC_id];
     LOG_I(RRC, "configuration->schedulingInfoSIB1_BR_r13[CC_id] %d\n",(int)configuration->schedulingInfoSIB1_BR_r13[CC_id]);
-    LOG_I(RRC, "Configuring MIB (N_RB_DL %d,phich_Resource %d,phich_Duration %d)\n",
+    LOG_A(RRC, "Configuring MIB (N_RB_DL %d,phich_Resource %d,phich_Duration %d)\n",
           (int)configuration->N_RB_DL[CC_id],
           (int)configuration->radioresourceconfig[CC_id].phich_resource,
           (int)configuration->radioresourceconfig[CC_id].phich_duration);
@@ -1161,7 +1161,7 @@ rrc_eNB_process_RRCConnectionSetupComplete(
 )
 //-----------------------------------------------------------------------------
 {
-  LOG_I(RRC, PROTOCOL_RRC_CTXT_UE_FMT" [RAPROC] Logical Channel UL-DCCH, " "processing LTE_RRCConnectionSetupComplete from UE (SRB1 Active)\n",
+  LOG_A(RRC, PROTOCOL_RRC_CTXT_UE_FMT" [RAPROC] Logical Channel UL-DCCH, " "processing LTE_RRCConnectionSetupComplete from UE (SRB1 Active)\n",
         PROTOCOL_RRC_CTXT_UE_ARGS(ctxt_pP));
   ue_context_pP->ue_context.Srb1.Active = 1;
   ue_context_pP->ue_context.Status = RRC_CONNECTED;
@@ -7883,7 +7883,7 @@ rrc_eNB_decode_dcch(
           xer_fprint(stdout, &asn_DEF_LTE_UL_DCCH_Message, (void *)ul_dcch_msg);
         }
 
-        LOG_I(RRC, "got UE capabilities for UE %x\n", ctxt_pP->rnti);
+        LOG_A(RRC, "got UE capabilities for UE %x\n", ctxt_pP->rnti);
 
         int eutra_index = -1;
 

openair3/NAS/UE/ESM/PdnConnectivity.c

@@ -356,7 +356,7 @@ int esm_proc_pdn_connectivity_accept(nas_user_t *user, int pti, esm_proc_pdn_typ
     int     pid = RETURNerror;
     char    apn_first_char[4];
 
-    LOG_VAR(char,    str[128]);
+    char str[128] __attribute__((unused));
 
     if (isprint(apn->value[0])) {
         apn_first_char[0] = '\0';

targets/RT/USER/lte-ru.c

@@ -1544,6 +1544,7 @@ static void *ru_stats_thread(void *param) {
 static void *ru_thread_tx( void *param ) {
   RU_t *ru         = (RU_t *)param;
   RU_proc_t *proc  = &ru->proc;
+  __attribute__((unused))
   LTE_DL_FRAME_PARMS *fp = ru->frame_parms;
   PHY_VARS_eNB *eNB;
   L1_proc_t *eNB_proc;
@@ -1958,6 +1959,7 @@ static void *ru_thread( void *param ) {
 // This thread run the initial synchronization like a UE
 void *ru_thread_synch(void *arg) {
   RU_t *ru = (RU_t *)arg;
+  __attribute__((unused))
   LTE_DL_FRAME_PARMS *fp = ru->frame_parms;
   int64_t peak_val, avg;
   static int ru_thread_synch_status = 0;

targets/RT/USER/lte-ue.c

@@ -1057,7 +1057,7 @@ static void *UE_phy_stub_standalone_pnf_task(void *arg)
           NFAPI_SFNSF2SFN(sfn_sf), NFAPI_SFNSF2SF(sfn_sf));
     if (dl_config_req != NULL) {
       uint16_t dl_num_pdus = dl_config_req->dl_config_request_body.number_pdu;
-      LOG_I(MAC, "(OAI UE) Received dl_config_req from proxy at Frame: %d, Subframe: %d,"
+      LOG_A(MAC, "(OAI UE) Received dl_config_req from proxy at Frame: %d, Subframe: %d,"
             " with number of PDUs: %u\n",
             NFAPI_SFNSF2SFN(dl_config_req->sfn_sf), NFAPI_SFNSF2SF(dl_config_req->sfn_sf),
             dl_num_pdus);