From: Michal Rakowski <michal.rakowski@baculasystems.com>
Date: Mon, 14 Jun 2021 09:07:44 +0000 (+0200)
Subject: Fix #6001 About adding more logging for daemon<->daemon connection
X-Git-Tag: Release-11.3.2~481
X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=6234896226d653cae6b4dd7255e0c11810408466;p=thirdparty%2Fbacula.git

Fix #6001 About adding more logging for daemon<->daemon connection
---

diff --git a/bacula/src/dird/fd_cmds.c b/bacula/src/dird/fd_cmds.c
index 117dd0cac..8e3f7e679 100644
--- a/bacula/src/dird/fd_cmds.c
+++ b/bacula/src/dird/fd_cmds.c
@@ -99,7 +99,7 @@ int connect_to_file_daemon(JCR *jcr, int retry_interval, int max_retry_time,
 
    if (!is_bsock_open(jcr->file_bsock)) {
       char name[MAX_NAME_LENGTH + 100];
-      POOL_MEM buf;
+      POOL_MEM buf, tmp;
 
       bstrncpy(name, _("Client: "), sizeof(name));
       bstrncat(name, jcr->client->name(), sizeof(name));
@@ -157,6 +157,17 @@ int connect_to_file_daemon(JCR *jcr, int retry_interval, int max_retry_time,
       return 0;
    }
 
+   if (jcr->JobId > 0) {
+      /* Print connection info only for real jobs */
+      POOL_MEM buf, tmp;
+      CLIENT *client = jcr->client;
+
+      build_connecting_info_log(_("Client"), client->name(),
+            get_client_address(jcr, client, tmp.addr()), client->FDport,
+            fd->tls ? true : false, buf.addr());
+      Jmsg(jcr, M_INFO, 0, "%s", buf.c_str());
+   }
+
    /*
     * Now send JobId and authorization key
     */
diff --git a/bacula/src/dird/msgchan.c b/bacula/src/dird/msgchan.c
index fb6f62e25..2c70e6ddc 100644
--- a/bacula/src/dird/msgchan.c
+++ b/bacula/src/dird/msgchan.c
@@ -129,7 +129,6 @@ bool connect_to_storage_daemon(JCR *jcr, int retry_interval,
    Dmsg2(100, "Connect to Storage daemon %s:%d\n", store->address,
       store->SDport);
    sd->set_source_address(director->DIRsrc_addr);
-   //TODO is translating needed/useful here?
    Mmsg(buf, _("Storage Daemon \"%s\""), store->name());
    if (!sd->connect(jcr, retry_interval, max_retry_time, heart_beat, buf.c_str(),
          store->address, NULL, store->SDport, verbose)) {
@@ -150,6 +149,15 @@ bool connect_to_storage_daemon(JCR *jcr, int retry_interval,
       sd->close();
       return false;
    }
+
+   if (jcr->JobId > 0) {
+      /* Print connection info only for real jobs */
+      build_connecting_info_log(_("Storage"), store->name(),
+            get_storage_address(jcr->client, store), store->SDport,
+            sd->tls ? true : false, buf.addr());
+      Jmsg(jcr, M_INFO, 0, "%s", buf.c_str());
+   }
+
    return true;
 }
 
diff --git a/bacula/src/filed/job.c b/bacula/src/filed/job.c
index 3b48318b9..c29412f7c 100644
--- a/bacula/src/filed/job.c
+++ b/bacula/src/filed/job.c
@@ -2676,7 +2676,7 @@ static int storage_cmd(JCR *jcr)
 {
    int stored_port = 0;            /* storage daemon port */
    int enable_ssl;                 /* enable ssl to sd */
-   POOL_MEM sd_auth_key(PM_MESSAGE);
+   POOL_MEM sd_auth_key(PM_MESSAGE), buf;
    BSOCK *dir = jcr->dir_bsock;
    BSOCK *sd;
 
@@ -2787,6 +2787,16 @@ static int storage_cmd(JCR *jcr)
          goto bail_out;
       }
    }
+
+   if (jcr->JobId > 0 && !jcr->sd_calls_client) {
+      /* Print connection info only for real jobs.
+       * We don't have storage name here, log connection info w/o it anyway */
+      build_connecting_info_log(_("Storage"), "",
+            jcr->stored_addr, stored_port,
+            jcr->store_bsock->tls ? true : false, buf.addr());
+      Jmsg(jcr, M_INFO, 0, "%s", buf.c_str());
+   }
+
    memset(jcr->sd_auth_key, 0, strlen(jcr->sd_auth_key));
    Dmsg0(110, "Authenticated with SD.\n");
 
diff --git a/bacula/src/jcr.h b/bacula/src/jcr.h
index 5e89c983b..3c2bae804 100644
--- a/bacula/src/jcr.h
+++ b/bacula/src/jcr.h
@@ -499,6 +499,7 @@ public:
    POOLMEM *fileset_md5;              /* MD5 for FileSet */
    char stored_addr[MAX_NAME_LENGTH]; /* storage daemon address */
    char client_addr[MAX_NAME_LENGTH]; /* client daemon address */
+   int client_port;                   /* client port */
    VOL_LIST *VolList;                 /* list to read, freed at the end of the job */
    int32_t NumWriteVolumes;           /* number of volumes written */
    int32_t NumReadVolumes;            /* total number of volumes to read */
diff --git a/bacula/src/lib/message.c b/bacula/src/lib/message.c
index ba7a11a07..b27876be1 100644
--- a/bacula/src/lib/message.c
+++ b/bacula/src/lib/message.c
@@ -2102,3 +2102,15 @@ void free_daemon_message_queue()
    free(daemon_msg_queue);
    V(daemon_msg_queue_mutex);
 }
+
+char *build_connecting_info_log(const char *daemon, const char *name, const char *addr, int port, bool tls, POOLMEM *&buf)
+{
+   if (*name) {
+      Mmsg(buf, conn_info_w_name, daemon, name, addr, port,
+            tls ? _("with TLS") : _("without encryption"));
+   } else {
+      Mmsg(buf, conn_info_wo_name, daemon, addr, port,
+            tls ? _("with TLS") : _("without encryption"));
+   }
+   return buf;
+}
diff --git a/bacula/src/lib/message.h b/bacula/src/lib/message.h
index c6d13ad72..bc647ac5c 100644
--- a/bacula/src/lib/message.h
+++ b/bacula/src/lib/message.h
@@ -177,6 +177,9 @@ struct MQUEUE_ITEM {
 #define    DT_ASX        (1<<16)                /* used by Alain for personal debugging */
 #define    DT_ALL        (0x7FFF0000)           /* all (up to debug_level 65635, 15 flags available) */
 
+const char conn_info_w_name[] = "Connected to %s \"%s\" at %s:%d %s\n";
+const char conn_info_wo_name[] = "Connected to %s at %s:%d %s\n";
+
 const char *debug_get_tag(uint32_t pos, const char **desc);
 bool debug_find_tag(const char *tagname, bool add, int64_t *current_level);
 bool debug_parse_tags(const char *options, int64_t *current_level);
@@ -193,6 +196,7 @@ const char *get_basename(const char *pathname);
 bool is_message_type_set(JCR *jcr, int type);
 void set_trace_for_tools(FILE *new_trace_fd); // called by Bacula's tools only
 void update_trace_file_location(bool safe);
+char *build_connecting_info_log(const char *daemon, const char *name, const char *addr, int port, bool tls, POOLMEM *&buf);
 
 class BDB;                                              /* define forward reference */
 typedef bool (*sql_insert_log)(JCR *jcr, JobId_t jobid, utime_t mtime, char *msg);
diff --git a/bacula/src/stored/dircmd.c b/bacula/src/stored/dircmd.c
index 859d5c264..264109760 100644
--- a/bacula/src/stored/dircmd.c
+++ b/bacula/src/stored/dircmd.c
@@ -307,14 +307,14 @@ static bool die_cmd(JCR *jcr)
  */
 static bool client_cmd(JCR *jcr)
 {
-   int client_port;                 /* client port */
    int enable_ssl;                 /* enable ssl */
    BSOCK *dir = jcr->dir_bsock;
    BSOCK *cl = new_bsock();        /* client bsock */
+   POOL_MEM buf;
 
    Dmsg1(100, "ClientCmd: %s", dir->msg);
    jcr->sd_calls_client = true;
-   if (sscanf(dir->msg, "client address=%127s port=%d ssl=%d", jcr->client_addr, &client_port,
+   if (sscanf(dir->msg, "client address=%127s port=%d ssl=%d", jcr->client_addr, &jcr->client_port,
               &enable_ssl) != 3) {
       /* destroy() OK because cl is local */
       cl->destroy();
@@ -324,20 +324,21 @@ static bool client_cmd(JCR *jcr)
       goto bail_out;
    }
 
-   Dmsg3(110, "Connect to client: %s:%d ssl=%d\n", jcr->client_addr, client_port,
+   Dmsg3(110, "Connect to client: %s:%d ssl=%d\n", jcr->client_addr, jcr->client_port,
          enable_ssl);
    /* Open command communications with Client */
    /* Try to connect for 1 hour at 10 second intervals */
    if (!cl->connect(jcr, 10, (int)me->ClientConnectTimeout, me->heartbeat_interval,
-                _("Client daemon"), jcr->client_addr, NULL, client_port, 1)) {
+                _("Client daemon"), jcr->client_addr, NULL, jcr->client_port, 1)) {
       /* destroy() OK because cl is local */
       cl->destroy();
       Jmsg(jcr, M_FATAL, 0, _("[SF0102] Failed to connect to Client daemon: %s:%d\n"),
-          jcr->client_addr, client_port);
+          jcr->client_addr, jcr->client_port);
       Dmsg2(100, "Failed to connect to Client daemon: %s:%d\n",
-          jcr->client_addr, client_port);
+          jcr->client_addr, jcr->client_port);
       goto bail_out;
    }
+
    Dmsg0(110, "SD connection OK to Client.\n");
 
    jcr->file_bsock = cl;
@@ -422,6 +423,15 @@ static bool storage_cmd(JCR *jcr)
       goto bail_out;
    }
 
+   if (jcr->JobId > 0) {
+      POOL_MEM buf;
+      /* Print connection info only for real jobs */
+      build_connecting_info_log(_("Storage"), "",
+            jcr->stored_addr, stored_port,
+            sd->tls ? true : false, buf.addr());
+      Jmsg(jcr, M_INFO, 0, "%s", buf.c_str());
+   }
+
    /*
     * We are a client so we read from the socket we just
     *   opened as if we were a FD, so set file_bsock and
diff --git a/bacula/src/stored/job.c b/bacula/src/stored/job.c
index 739744679..a0ad05fdb 100644
--- a/bacula/src/stored/job.c
+++ b/bacula/src/stored/job.c
@@ -204,6 +204,17 @@ bool run_cmd(JCR *jcr)
       } else {
          jcr->authenticated = true;
       }
+
+      if (jcr->JobId > 0) {
+         POOL_MEM buf;
+         /* Print connection info only for real jobs.
+          * We don't have client name here, log connection info w/o it anyway */
+         build_connecting_info_log(_("Client"), "",
+               jcr->client_addr, jcr->client_port,
+               jcr->file_bsock->tls ? true : false, buf.addr());
+         Jmsg(jcr, M_INFO, 0, "%s", buf.c_str());
+      }
+
    } else if (!jcr->sd_client) {
       /* We wait to receive connection from Client */
       gettimeofday(&tv, &tz);