Added timestamps and logging

common/utils/LOG/log.c

@@ -43,7 +43,7 @@
 #include <string.h>
 #include <linux/prctl.h>
 #include "common/config/config_userapi.h"
-
+#include <time.h>
 // main log variables
 
 log_mem_cnt_t log_mem_d[2];
@@ -476,20 +476,29 @@ char *log_getthreadname(char *threadname,
 }
 
 static int log_header(char *log_buffer,
-		              int buffsize,
-					  int comp,
-					  int level,
-					  const char *format)
+                      int buffsize,
+                      int comp,
+                      int level,
+                      const char *format)
 {
   char threadname[PR_SET_NAME];
-  return  snprintf(log_buffer, buffsize, "%s%s[%s]%c %s %s%s",
-                   log_level_highlight_end[level],
-                   ( (g_log->flag & FLAG_NOCOLOR)?"":log_level_highlight_start[level]),
-                   g_log->log_component[comp].name,
-                   ( (g_log->flag & FLAG_LEVEL)?g_log->level2string[level]:' '),
-                   ( (g_log->flag & FLAG_THREAD)?log_getthreadname(threadname,PR_SET_NAME+1):""),
-                   format,
-                   log_level_highlight_end[level]);
+  struct timeval tv;
+  gettimeofday(&tv, NULL);
+  struct tm tm;
+  localtime_r(&tv.tv_sec, &tm);
+
+  return snprintf(log_buffer, buffsize, "%02d:%02d:%02d.%06ld %s%s[%s]%c %s %s%s",
+                  tm.tm_hour,
+                  tm.tm_min,
+                  tm.tm_sec,
+                  tv.tv_usec,
+                  log_level_highlight_end[level],
+                  ((g_log->flag & FLAG_NOCOLOR) ? "" : log_level_highlight_start[level]),
+                  g_log->log_component[comp].name,
+                  ((g_log->flag & FLAG_LEVEL) ? g_log->level2string[level] : ' '),
+                  ((g_log->flag & FLAG_THREAD) ? log_getthreadname(threadname, PR_SET_NAME + 1) : ""),
+                  format,
+                  log_level_highlight_end[level]);
 }
 
 void logRecord_mt(const char *file,

openair2/PHY_INTERFACE/phy_stub_UE.c

@@ -74,8 +74,6 @@ void fill_rx_indication_UE_MAC(module_id_t Mod_id,
   nfapi_rx_indication_pdu_t *pdu;
   int timing_advance_update;
 
-  LOG_I(MAC, "Entered fill_rx_indication_UE_MAC\n");
-
   pthread_mutex_lock(&fill_ul_mutex.rx_mutex);
 
   UL_INFO->rx_ind.header.message_id = NFAPI_RX_ULSCH_INDICATION;
@@ -1186,7 +1184,7 @@ void ue_init_standalone_socket(const char *addr, int tx_port, int rx_port)
 void *ue_standalone_pnf_task(void *context)
 {
   struct sockaddr_in server_address;
-  int addr_len = sizeof(server_address);
+  socklen_t addr_len = sizeof(server_address);
   char buffer[1024];
 
   int sd = ue_rx_sock_descriptor;
@@ -1313,7 +1311,7 @@ const char *hexdump(const void *data, size_t data_len, char *out, size_t out_len
     return out;
 }
 
-  void send_standalone_msg(UL_IND_t * UL, nfapi_message_id_e msg_type)
+  void send_standalone_msg(UL_IND_t *UL, nfapi_message_id_e msg_type)
   {
     int encoded_size = -1;
     char buffer[1024];
@@ -1321,7 +1319,8 @@ const char *hexdump(const void *data, size_t data_len, char *out, size_t out_len
     {
     case NFAPI_RACH_INDICATION:
       encoded_size = nfapi_p7_message_pack(&UL->rach_ind, buffer, sizeof(buffer), NULL);
-      LOG_E(MAC, "RACH_IND sent to Proxy, Size: %d\n", encoded_size);
+      LOG_E(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:
       encoded_size = nfapi_p7_message_pack(&UL->crc_ind, buffer, sizeof(buffer), NULL);

targets/RT/USER/lte-enb.c

@@ -261,7 +261,7 @@ static inline int rxtx(PHY_VARS_eNB *eNB,
   eNB->UL_INFO.subframe  = proc->subframe_rx;
   eNB->UL_INFO.module_id = eNB->Mod_id;
   eNB->UL_INFO.CC_id     = eNB->CC_id;
-  eNB->if_inst->UL_indication(&eNB->UL_INFO, proc);
+  eNB->if_inst->UL_indication(&eNB->UL_INFO, proc); // Andrew calling eNB maclayer check the UL_INFO structure
   AssertFatal((ret= pthread_mutex_unlock(&eNB->UL_INFO_mutex))==0,"error unlocking UL_INFO_mutex, return %d\n",ret);
   /* this conflict resolution may be totally wrong, to be tested */
   /* CONFLICT RESOLUTION: BEGIN */

targets/RT/USER/lte-ue.c

@@ -1039,7 +1039,6 @@ static void *UE_phy_stub_standalone_pnf_task(void *arg)
   int num_lone = 0;
   int last_sfn_sf = -1;
 
-  uint64_t last_subframe_start = clock_usec();
   while (!oai_exit) {
     bool sent_any = false;
     int sfn_sf = current_sfn_sf;
@@ -1048,24 +1047,19 @@ static void *UE_phy_stub_standalone_pnf_task(void *arg)
       continue;
     }
 
-    uint64_t subframe_start = clock_usec();
-    // LOG_I(MAC, "subframe elapsed %" PRIu64 "usec\n",
-    //       subframe_start - last_subframe_start);
-    last_subframe_start = subframe_start;
-
     last_sfn_sf = sfn_sf;
     // FDD and TDD tx timing settings.
     // XXX:It is the result of timing adjustment in debug.
     proc->subframe_tx = NFAPI_SFNSF2SF(sfn_sf);
     proc->frame_tx = NFAPI_SFNSF2SFN(sfn_sf);
 
-
+    LOG_E(MAC, "received from proxy frame %d subframe %d\n", proc->frame_tx,
+          proc->subframe_tx);
 
     nfapi_dl_config_request_t *dl_config_req = get_queue(&dl_config_req_queue);
     nfapi_tx_request_pdu_t *tx_request_pdu_list = get_queue(&tx_req_pdu_queue);
     nfapi_ul_config_request_t *ul_config_req = get_queue(&ul_config_req_queue);
     nfapi_hi_dci0_request_t *hi_dci0_req = get_queue(&hi_dci0_req_queue);
-
     if ((dl_config_req != NULL) != (tx_request_pdu_list != NULL)) {
       uint64_t start = clock_usec();
       uint64_t deadline = start + 10000;
@@ -1136,7 +1130,6 @@ static void *UE_phy_stub_standalone_pnf_task(void *arg)
         }
       }
     }
-
     if (hi_dci0_req) {
       nfapi_hi_dci0_request_body_t *hi_dci0_body = &hi_dci0_req->hi_dci0_request_body;
       for (int i = 0; i < hi_dci0_body->number_of_dci + hi_dci0_body->number_of_hi; i++) {
@@ -1149,15 +1142,19 @@ static void *UE_phy_stub_standalone_pnf_task(void *arg)
     }
 
     for (ue_index = 0; ue_index < ue_num; ue_index++) {
+      ue_Mod_id = ue_thread_id + NB_THREAD_INST * ue_index;
+      UE = PHY_vars_UE_g[ue_Mod_id][0];
 
 #if UE_TIMING_TRACE
       start_meas(&UE->generic_stat);
 #endif
-
+      int rx_frame = proc->subframe_tx < 4 ? (proc->frame_tx + 1023) % 1024 : proc->frame_tx; // subtracting 4 from subframe_tx
+      int rx_subframe = proc->subframe_tx < 4 ? proc->subframe_tx + 6 : proc->subframe_tx - 4;
+      LOG_E(MAC, "rx_frame %d rx_subframe %d\n", rx_frame, rx_subframe);
       if (UE->mac_enabled == 1) {
         ret = ue_scheduler(ue_Mod_id,
-                           proc->subframe_tx < 4 ? (proc->frame_tx + 1023) % 1024 : proc->frame_tx, // subtracting 4 from subframe_tx
-                           proc->subframe_tx < 4 ? proc->subframe_tx + 6 : proc->subframe_tx - 4,
+                           rx_frame,
+                           rx_subframe,
                            proc->frame_tx,
                            proc->subframe_tx,
                            subframe_select(&UE->frame_parms, proc->subframe_tx),