Merge pull request #448 from bareos/dev/franku/master/ndmp-log-messages

ndmp: add more log messages for errors

core/src/dird/ndmp_dma_storage.cc

@@ -2,7 +2,7 @@
    BAREOS® - Backup Archiving REcovery Open Sourced
 
    Copyright (C) 2011-2015 Planets Communications B.V.
-   Copyright (C) 2013-2019 Bareos GmbH & Co. KG
+   Copyright (C) 2013-2020 Bareos GmbH & Co. KG
 
    This program is Free Software; you can redistribute it and/or
    modify it under the terms of version three of the GNU Affero General Public
@@ -259,6 +259,8 @@ extern "C" void NdmpRobotStatusHandler(struct ndmlog* log,
  */
 static void CleanupNdmpSession(struct ndm_session* ndmp_sess)
 {
+  Dmsg0(200, "Start to clean up ndmp session.\n");
+
   /*
    * Destroy the session.
    */
@@ -301,36 +303,53 @@ static bool NdmpRunStorageJob(JobControlRecord* jcr,
   /*
    * Initialize the session structure.
    */
-  if (ndma_session_initialize(ndmp_sess)) { goto bail_out; }
+  if (ndma_session_initialize(ndmp_sess)) {
+    Dmsg0(200, "Could not initialize ndma session.\n");
+    return false;
+  }
 
   /*
    * Copy the actual job to perform.
    */
   memcpy(&ndmp_sess->control_acb->job, ndmp_job, sizeof(struct ndm_job_param));
-  if (!NdmpValidateJob(jcr, &ndmp_sess->control_acb->job)) { goto bail_out; }
+  if (!NdmpValidateJob(jcr, &ndmp_sess->control_acb->job)) {
+    Dmsg0(200, "Could not validate ndma job.\n");
+    return false;
+  }
 
   /*
    * Commission the session for a run.
    */
-  if (ndma_session_commission(ndmp_sess)) { goto bail_out; }
+  if (ndma_session_commission(ndmp_sess)) {
+    Dmsg0(200, "Could not commission the ndma session.\n");
+    return false;
+  }
 
   /*
    * Setup the DMA.
    */
-  if (ndmca_connect_control_agent(ndmp_sess)) { goto bail_out; }
+  if (ndmca_connect_control_agent(ndmp_sess)) {
+    Dmsg0(200, "Could not connect to control agent.\n");
+    return false;
+  }
 
   ndmp_sess->conn_open = 1;
   ndmp_sess->conn_authorized = 1;
 
+  char ndm_job_type = ndmp_sess->control_acb->job.operation & 0xff;
+  Dmsg2(200, "ndma job.operation - job_type: %#x - %c\n",
+        ndmp_sess->control_acb->job.operation, ndm_job_type);
+
   /*
    * Let the DMA perform its magic.
    */
-  if (ndmca_control_agent(ndmp_sess) != 0) { goto bail_out; }
+  int err{};
+  if ((err = ndmca_control_agent(ndmp_sess)) != 0) {
+    Dmsg1(200, "Ndma control agent error: %d\n", err);
+    return false;
+  }
 
   return true;
-
-bail_out:
-  return false;
 }
 
 /**
@@ -345,11 +364,17 @@ static bool GetRobotElementStatus(JobControlRecord* jcr,
   /*
    * See if this is an autochanger.
    */
-  if (!store->autochanger || !store->ndmp_changer_device) { return false; }
+  if (!store->autochanger || !store->ndmp_changer_device) {
+    Dmsg2(200, "Autochanger: %s - NDMP Changer device: %s\n",
+          store->autochanger ? "true" : "false",
+          store->ndmp_changer_device ? store->ndmp_changer_device : "(NULL)");
+    return false;
+  }
 
   if (!NdmpBuildStorageJob(jcr, store, false, /* Setup Tape Agent */
                            true,              /* Setup Robot Agent */
                            NDM_JOB_OP_INIT_ELEM_STATUS, &ndmp_job)) {
+    Dmsg0(200, "Could not build NDMP storage job\n");
     return false;
   }
 
@@ -360,9 +385,12 @@ static bool GetRobotElementStatus(JobControlRecord* jcr,
    */
   ndmp_job.robot_target =
       (struct ndmscsi_target*)malloc(sizeof(struct ndmscsi_target));
-  if (ndmscsi_target_from_str(ndmp_job.robot_target,
-                              store->ndmp_changer_device) != 0) {
+  int error_number = ndmscsi_target_from_str(ndmp_job.robot_target,
+                              store->ndmp_changer_device);
+  if (error_number != 0) {
     free(ndmp_job.robot_target);
+    Dmsg1(200, "Could not create NDMP target name from string: %d\n",
+          error_number);
     return false;
   }
   ndmp_job.have_robot = 1;
@@ -376,6 +404,7 @@ static bool GetRobotElementStatus(JobControlRecord* jcr,
 
   if (!NdmpRunStorageJob(jcr, store, *ndmp_sess, &ndmp_job)) {
     CleanupNdmpSession(*ndmp_sess);
+    Dmsg0(200, "NdmpRunStorageJob failed.\n");
     return false;
   }
 
@@ -618,7 +647,10 @@ bool NdmpUpdateStorageMappings(JobControlRecord* jcr, StorageResource* store)
 {
   struct ndm_session* ndmp_sess;
 
-  if (!GetRobotElementStatus(jcr, store, &ndmp_sess)) { return false; }
+  if (!GetRobotElementStatus(jcr, store, &ndmp_sess)) {
+    Dmsg0(200, "Could not get robot element status.\n");
+    return false;
+  }
 
   NdmpFillStorageMappings(store, ndmp_sess);
 
@@ -634,7 +666,10 @@ bool NdmpUpdateStorageMappings(UaContext* ua, StorageResource* store)
 {
   struct ndm_session* ndmp_sess;
 
-  if (!GetRobotElementStatus(ua->jcr, store, &ndmp_sess)) { return false; }
+  if (!GetRobotElementStatus(ua->jcr, store, &ndmp_sess)) {
+    Dmsg0(200, "Could not get robot element status.\n");
+    return false;
+  }
 
   NdmpFillStorageMappings(store, ndmp_sess);
 
@@ -653,7 +688,10 @@ slot_number_t NdmpGetNumSlots(UaContext* ua, StorageResource* store)
   /*
    * See if the mappings are already determined.
    */
-  if (!NdmpUpdateStorageMappings(ua, store)) { return slots; }
+  if (!NdmpUpdateStorageMappings(ua, store)) {
+    Dmsg0(200, "NdmpUpdateStorageMappings failed\n");
+    return slots;
+  }
 
   return store->runtime_storage_status->storage_mapping.se_count +
          store->runtime_storage_status->storage_mapping.iee_count;
@@ -669,7 +707,10 @@ drive_number_t NdmpGetNumDrives(UaContext* ua, StorageResource* store)
   /*
    * See if the mappings are already determined.
    */
-  if (!NdmpUpdateStorageMappings(ua, store)) { return drives; }
+  if (!NdmpUpdateStorageMappings(ua, store)) {
+    Dmsg0(200, "NdmpUpdateStorageMappings failed\n");
+    return drives;
+  }
 
   return store->runtime_storage_status->storage_mapping.dte_count;
 }