From: Lukas Sismis <lsismis@oisf.net>
Date: Thu, 22 Jun 2023 12:09:36 +0000 (+0200)
Subject: dpdk: refactor log messages
X-Git-Tag: suricata-7.0.0~53
X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=2fdc0e497e1217ec808b061fe30ddd5a2799dd41;p=thirdparty%2Fsuricata.git

dpdk: refactor log messages

Be more consistent with the log message format,
remove some unnecessary device name queries.

Ticket: #6116
---

diff --git a/src/runmode-dpdk.c b/src/runmode-dpdk.c
index da0ff052ed..339344d14f 100644
--- a/src/runmode-dpdk.c
+++ b/src/runmode-dpdk.c
@@ -417,7 +417,7 @@ static int ConfigSetThreads(DPDKIfaceConfig *iconf, const char *entry_str)
                 remaining_auto_cpus--;
             }
         }
-        SCLogPerf("%s: auto-assigned %u threads", iconf->iface, iconf->threads);
+        SCLogConfig("%s: auto-assigned %u threads", iconf->iface, iconf->threads);
         SCReturnInt(0);
     }
 
@@ -446,7 +446,7 @@ static int ConfigSetRxQueues(DPDKIfaceConfig *iconf, uint16_t nb_queues)
     SCEnter();
     iconf->nb_rx_queues = nb_queues;
     if (iconf->nb_rx_queues < 1) {
-        SCLogError("Interface %s requires to have positive number of RX queues", iconf->iface);
+        SCLogError("%s: positive number of RX queues is required", iconf->iface);
         SCReturnInt(-ERANGE);
     }
 
@@ -458,7 +458,7 @@ static int ConfigSetTxQueues(DPDKIfaceConfig *iconf, uint16_t nb_queues)
     SCEnter();
     iconf->nb_tx_queues = nb_queues;
     if (iconf->nb_tx_queues < 1) {
-        SCLogError("Interface %s requires to have positive number of TX queues", iconf->iface);
+        SCLogError("%s: positive number of TX queues is required", iconf->iface);
         SCReturnInt(-ERANGE);
     }
 
@@ -469,7 +469,7 @@ static int ConfigSetMempoolSize(DPDKIfaceConfig *iconf, intmax_t entry_int)
 {
     SCEnter();
     if (entry_int <= 0) {
-        SCLogError("Interface %s requires to have positive memory pool size", iconf->iface);
+        SCLogError("%s: positive memory pool size is required", iconf->iface);
         SCReturnInt(-ERANGE);
     }
 
@@ -486,8 +486,8 @@ static int ConfigSetMempoolCacheSize(DPDKIfaceConfig *iconf, const char *entry_s
         //   RTE_MEMPOOL_CACHE_MAX_SIZE (by default 512) and "mempool-size / 1.5"
         // and at the same time "mempool-size modulo cache_size == 0".
         if (iconf->mempool_size == 0) {
-            SCLogError("Cannot calculate mempool cache size of a mempool with size %d",
-                    iconf->mempool_size);
+            SCLogError("%s: cannot calculate mempool cache size of a mempool with size %d",
+                    iconf->iface, iconf->mempool_size);
             SCReturnInt(-EINVAL);
         }
 
@@ -497,16 +497,13 @@ static int ConfigSetMempoolCacheSize(DPDKIfaceConfig *iconf, const char *entry_s
     }
 
     if (StringParseUint32(&iconf->mempool_cache_size, 10, 0, entry_str) < 0) {
-        SCLogError("Mempool cache size entry for interface %s contain non-numerical "
-                   "characters - \"%s\"",
+        SCLogError("%s: mempool cache size entry contain non-numerical characters - \"%s\"",
                 iconf->iface, entry_str);
         SCReturnInt(-EINVAL);
     }
 
     if (iconf->mempool_cache_size <= 0 || iconf->mempool_cache_size > RTE_MEMPOOL_CACHE_MAX_SIZE) {
-        SCLogError(
-                "Interface %s requires to have mempool cache size set to a positive number smaller "
-                "than %" PRIu32,
+        SCLogError("%s: mempool cache size requires a positive number smaller than %" PRIu32,
                 iconf->iface, RTE_MEMPOOL_CACHE_MAX_SIZE);
         SCReturnInt(-ERANGE);
     }
@@ -518,7 +515,7 @@ static int ConfigSetRxDescriptors(DPDKIfaceConfig *iconf, intmax_t entry_int)
 {
     SCEnter();
     if (entry_int <= 0) {
-        SCLogError("Interface %s requires to have positive number of RX descriptors", iconf->iface);
+        SCLogError("%s: positive number of RX descriptors is required", iconf->iface);
         SCReturnInt(-ERANGE);
     }
 
@@ -530,7 +527,7 @@ static int ConfigSetTxDescriptors(DPDKIfaceConfig *iconf, intmax_t entry_int)
 {
     SCEnter();
     if (entry_int <= 0) {
-        SCLogError("Interface %s requires to have positive number of TX descriptors", iconf->iface);
+        SCLogError("%s: positive number of TX descriptors is required", iconf->iface);
         SCReturnInt(-ERANGE);
     }
 
@@ -547,8 +544,7 @@ static int ConfigSetRSSHashFunctions(DPDKIfaceConfig *iconf, const char *entry_s
     }
 
     if (StringParseUint64(&iconf->rss_hf, 0, 0, entry_str) < 0) {
-        SCLogError("RSS hash functions entry for interface %s contain non-numerical "
-                   "characters - \"%s\"",
+        SCLogError("%s: RSS hash functions entry contain non-numerical characters - \"%s\"",
                 iconf->iface, entry_str);
         SCReturnInt(-EINVAL);
     }
@@ -560,8 +556,8 @@ static int ConfigSetMtu(DPDKIfaceConfig *iconf, intmax_t entry_int)
 {
     SCEnter();
     if (entry_int < RTE_ETHER_MIN_MTU || entry_int > RTE_ETHER_MAX_JUMBO_FRAME_LEN) {
-        SCLogError("Interface %s requires to have size of MTU between %" PRIu32 " and %" PRIu32,
-                iconf->iface, RTE_ETHER_MIN_MTU, RTE_ETHER_MAX_JUMBO_FRAME_LEN);
+        SCLogError("%s: MTU size can only be between %" PRIu32 " and %" PRIu32, iconf->iface,
+                RTE_ETHER_MIN_MTU, RTE_ETHER_MAX_JUMBO_FRAME_LEN);
         SCReturnInt(-ERANGE);
     }
 
@@ -617,8 +613,8 @@ static int ConfigSetCopyIface(DPDKIfaceConfig *iconf, const char *entry_str)
 
     retval = rte_eth_dev_get_port_by_name(entry_str, &iconf->out_port_id);
     if (retval < 0) {
-        SCLogError("%s: name of the copy interface (%s) is invalid (err %d)", iconf->iface,
-                entry_str, retval);
+        SCLogError("%s: name of the copy interface (%s) is invalid (err %s)", iconf->iface,
+                entry_str, rte_strerror(-retval));
         SCReturnInt(retval);
     }
 
@@ -630,16 +626,15 @@ static int ConfigSetCopyMode(DPDKIfaceConfig *iconf, const char *entry_str)
 {
     SCEnter();
     if (entry_str == NULL) {
-        SCLogWarning("Interface %s has no copy mode specified, changing to %s ", iconf->iface,
+        SCLogWarning("%s: no copy mode specified, changing to %s ", iconf->iface,
                 DPDK_CONFIG_DEFAULT_COPY_MODE);
         entry_str = DPDK_CONFIG_DEFAULT_COPY_MODE;
     }
 
     if (strcmp(entry_str, "none") != 0 && strcmp(entry_str, "tap") != 0 &&
             strcmp(entry_str, "ips") != 0) {
-        SCLogWarning(
-                "Copy mode \"%s\" is not one of the possible values (none|tap|ips) for interface "
-                "%s. Changing to %s",
+        SCLogWarning("%s: copy mode \"%s\" is not one of the possible values (none|tap|ips). "
+                     "Changing to %s",
                 entry_str, iconf->iface, DPDK_CONFIG_DEFAULT_COPY_MODE);
         entry_str = DPDK_CONFIG_DEFAULT_COPY_MODE;
     }
@@ -1169,7 +1164,7 @@ static int DeviceConfigureQueues(DPDKIfaceConfig *iconf, const struct rte_eth_de
     // +4 for VLAN header
     mtu_size = iconf->mtu + RTE_ETHER_CRC_LEN + RTE_ETHER_HDR_LEN + 4;
     mbuf_size = ROUNDUP(mtu_size, 1024) + RTE_PKTMBUF_HEADROOM;
-    SCLogInfo("%s: creating packet mbuf pool %s of size %d, cache size %d, mbuf size %d",
+    SCLogConfig("%s: creating packet mbuf pool %s of size %d, cache size %d, mbuf size %d",
             iconf->iface, mempool_name, iconf->mempool_size, iconf->mempool_cache_size, mbuf_size);
 
     iconf->pkt_mempool = rte_pktmbuf_pool_create(mempool_name, iconf->mempool_size,
@@ -1189,8 +1184,8 @@ static int DeviceConfigureQueues(DPDKIfaceConfig *iconf, const struct rte_eth_de
         rxq_conf.rx_thresh.wthresh = 0;
         rxq_conf.rx_free_thresh = 0;
         rxq_conf.rx_drop_en = 0;
-        SCLogPerf("%s: rx queue setup: queue:%d port:%d rx_desc:%d tx_desc:%d rx: hthresh: %d "
-                  "pthresh %d wthresh %d free_thresh %d drop_en %d offloads %lu",
+        SCLogConfig("%s: rx queue setup: queue:%d port:%d rx_desc:%d tx_desc:%d rx: hthresh: %d "
+                    "pthresh %d wthresh %d free_thresh %d drop_en %d offloads %lu",
                 iconf->iface, queue_id, iconf->port_id, iconf->nb_rx_desc, iconf->nb_tx_desc,
                 rxq_conf.rx_thresh.hthresh, rxq_conf.rx_thresh.pthresh, rxq_conf.rx_thresh.wthresh,
                 rxq_conf.rx_free_thresh, rxq_conf.rx_drop_en, rxq_conf.offloads);
@@ -1209,7 +1204,7 @@ static int DeviceConfigureQueues(DPDKIfaceConfig *iconf, const struct rte_eth_de
     for (uint16_t queue_id = 0; queue_id < iconf->nb_tx_queues; queue_id++) {
         txq_conf = dev_info->default_txconf;
         txq_conf.offloads = port_conf->txmode.offloads;
-        SCLogPerf("%s: tx queue setup: queue:%d port:%d", iconf->iface, queue_id, iconf->port_id);
+        SCLogConfig("%s: tx queue setup: queue:%d port:%d", iconf->iface, queue_id, iconf->port_id);
         retval = rte_eth_tx_queue_setup(
                 iconf->port_id, queue_id, iconf->nb_tx_desc, iconf->socket_id, &txq_conf);
         if (retval < 0) {
@@ -1236,7 +1231,7 @@ static int DeviceValidateOutIfaceConfig(DPDKIfaceConfig *iconf)
 
     retval = ConfigLoad(out_iconf, iconf->out_iface);
     if (retval < 0) {
-        SCLogError("Fail to load config of interface %s", iconf->out_iface);
+        SCLogError("%s: fail to load config of interface", iconf->out_iface);
         out_iconf->DerefFunc(out_iconf);
         SCReturnInt(-EINVAL);
     }
@@ -1336,7 +1331,8 @@ static int32_t DeviceVerifyPostConfigure(
             dev_info->max_rx_queues != post_conf_dev_info.max_rx_queues ||
             dev_info->max_tx_queues != post_conf_dev_info.max_tx_queues ||
             dev_info->max_mtu != post_conf_dev_info.max_mtu) {
-        SCLogWarning("Device information severely changed after configuration, reconfiguring");
+        SCLogWarning("%s: device information severely changed after configuration, reconfiguring",
+                iconf->iface);
         return -EAGAIN;
     }
 
diff --git a/src/source-dpdk.c b/src/source-dpdk.c
index 51b60fd409..1282857215 100644
--- a/src/source-dpdk.c
+++ b/src/source-dpdk.c
@@ -218,8 +218,8 @@ static void DevicePreStopPMDSpecificActions(DPDKThreadVars *ptv, const char *dri
         struct rte_flow_error flush_error = { 0 };
         int32_t retval = rte_flow_flush(ptv->port_id, &flush_error);
         if (retval != 0) {
-            SCLogError("Unable to flush rte_flow rules: %s Flush error msg: %s",
-                    rte_strerror(-retval), flush_error.message);
+            SCLogError("%s: unable to flush rte_flow rules: %s Flush error msg: %s",
+                    ptv->livedev->dev, rte_strerror(-retval), flush_error.message);
         }
 #endif /* RTE_VERSION > RTE_VERSION_NUM(20, 0, 0, 0) */
     }
@@ -529,16 +529,16 @@ static TmEcode ReceiveDPDKThreadInit(ThreadVars *tv, const void *initdata, void
     if (queue_id == dpdk_config->threads - 1) {
         retval = rte_eth_dev_start(ptv->port_id);
         if (retval < 0) {
-            SCLogError("Error (%s) during device startup of %s", rte_strerror(-retval),
-                    dpdk_config->iface);
+            SCLogError("%s: error (%s) during device startup", dpdk_config->iface,
+                    rte_strerror(-retval));
             goto fail;
         }
 
         struct rte_eth_dev_info dev_info;
         retval = rte_eth_dev_info_get(ptv->port_id, &dev_info);
         if (retval != 0) {
-            SCLogError("Error (%s) when getting device info of %s", rte_strerror(-retval),
-                    dpdk_config->iface);
+            SCLogError("%s: error (%s) when getting device info", dpdk_config->iface,
+                    rte_strerror(-retval));
             goto fail;
         }
 
@@ -619,30 +619,19 @@ static void ReceiveDPDKThreadExitStats(ThreadVars *tv, void *data)
 
     if (ptv->queue_id == 0) {
         struct rte_eth_stats eth_stats;
-        char port_name[RTE_ETH_NAME_MAX_LEN];
-
-        retval = rte_eth_dev_get_name_by_port(ptv->port_id, port_name);
-        if (unlikely(retval != 0)) {
-            SCLogError("Failed to convert port id %d to the interface name: %s", ptv->port_id,
-                    strerror(-retval));
-            SCReturn;
-        }
-
-        PrintDPDKPortXstats(ptv->port_id, port_name);
-
+        PrintDPDKPortXstats(ptv->port_id, ptv->livedev->dev);
         retval = rte_eth_stats_get(ptv->port_id, &eth_stats);
         if (unlikely(retval != 0)) {
-            SCLogError("Failed to get stats for interface %s: %s", port_name, strerror(-retval));
+            SCLogError("%s: failed to get stats (%s)", ptv->livedev->dev, strerror(-retval));
             SCReturn;
         }
-        SCLogPerf("Total RX stats of %s: packets %" PRIu64 " bytes: %" PRIu64 " missed: %" PRIu64
+        SCLogPerf("%s: total RX stats: packets %" PRIu64 " bytes: %" PRIu64 " missed: %" PRIu64
                   " errors: %" PRIu64 " nombufs: %" PRIu64,
-                port_name, eth_stats.ipackets, eth_stats.ibytes, eth_stats.imissed,
+                ptv->livedev->dev, eth_stats.ipackets, eth_stats.ibytes, eth_stats.imissed,
                 eth_stats.ierrors, eth_stats.rx_nombuf);
         if (ptv->copy_mode == DPDK_COPY_MODE_TAP || ptv->copy_mode == DPDK_COPY_MODE_IPS)
-            SCLogPerf("Total TX stats of %s: packets %" PRIu64 " bytes: %" PRIu64
-                      " errors: %" PRIu64,
-                    port_name, eth_stats.opackets, eth_stats.obytes, eth_stats.oerrors);
+            SCLogPerf("%s: total TX stats: packets %" PRIu64 " bytes: %" PRIu64 " errors: %" PRIu64,
+                    ptv->livedev->dev, eth_stats.opackets, eth_stats.obytes, eth_stats.oerrors);
     }
 
     DPDKDumpCounters(ptv);
@@ -659,18 +648,12 @@ static TmEcode ReceiveDPDKThreadDeinit(ThreadVars *tv, void *data)
     SCEnter();
     DPDKThreadVars *ptv = (DPDKThreadVars *)data;
 
-    int retval;
     if (ptv->queue_id == 0) {
         struct rte_eth_dev_info dev_info;
-        char iface[RTE_ETH_NAME_MAX_LEN];
-        retval = rte_eth_dev_get_name_by_port(ptv->port_id, iface);
-        if (retval != 0) {
-            SCLogError("Error (err=%d) when getting device name (port %d)", retval, ptv->port_id);
-            SCReturnInt(TM_ECODE_FAILED);
-        }
-        retval = rte_eth_dev_info_get(ptv->port_id, &dev_info);
+        int retval = rte_eth_dev_info_get(ptv->port_id, &dev_info);
         if (retval != 0) {
-            SCLogError("Error (err=%d) during getting device info (port %s)", retval, iface);
+            SCLogError("%s: error (%s) when getting device info", ptv->livedev->dev,
+                    rte_strerror(-retval));
             SCReturnInt(TM_ECODE_FAILED);
         }
 
diff --git a/src/util-dpdk.c b/src/util-dpdk.c
index 291ab075e0..462b4b8cb7 100644
--- a/src/util-dpdk.c
+++ b/src/util-dpdk.c
@@ -49,10 +49,10 @@ void DPDKCloseDevice(LiveDevice *ldev)
             return;
         }
 
-        SCLogInfo("%s: closing device", ldev->dev);
+        SCLogPerf("%s: closing device", ldev->dev);
         rte_eth_dev_close(port_id);
 
-        SCLogInfo("%s: releasing packet mempool", ldev->dev);
+        SCLogDebug("%s: releasing packet mempool", ldev->dev);
         rte_mempool_free(ldev->dpdk_vars.pkt_mp);
     }
 #endif