From: Eric Bollengier Date: Tue, 8 Nov 2022 10:30:59 +0000 (+0100) Subject: Improve the bsock network errors display X-Git-Tag: Beta-15.0.0~371 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=30c5a881eb17a75a3b0ad7bf8bb90d545fc84f18;p=thirdparty%2Fbacula.git Improve the bsock network errors display - Put [error] codes in many messages - Do not print error messages inside the BSOCK::connect/open calls - Print error messages after a connect() depending of the context (UA/jcr) - Network messages should not end up in JobId 0 - Fix incorrect socket usage after a console command error --- diff --git a/bacula/src/console/console.c b/bacula/src/console/console.c index 7d15a4822..ca70cc32b 100644 --- a/bacula/src/console/console.c +++ b/bacula/src/console/console.c @@ -1369,6 +1369,7 @@ int main(int argc, char *argv[]) } if (!UA_sock->connect(NULL, 5, 15, heart_beat, "Director daemon", dir->address, NULL, dir->DIRport, 0)) { + senditf("%s", UA_sock->errmsg); UA_sock->destroy(); UA_sock = NULL; terminate_console(0); diff --git a/bacula/src/dird/authenticate.c b/bacula/src/dird/authenticate.c index 6a53490be..5137633a1 100644 --- a/bacula/src/dird/authenticate.c +++ b/bacula/src/dird/authenticate.c @@ -71,9 +71,15 @@ public: bool authenticate_storage_daemon(STORE *store); }; -bool authenticate_storage_daemon(JCR *jcr, STORE *store) +bool authenticate_storage_daemon(JCR *jcr, STORE *store, int *status, POOLMEM **errmsg) { - return DIRAuthenticateSD(jcr).authenticate_storage_daemon(store); + DIRAuthenticateSD elt(jcr); + bool ret = elt.authenticate_storage_daemon(store); + if (!ret) { + pm_strcpy(errmsg, elt.errmsg); + *status = elt.status; + } + return ret; } bool DIRAuthenticateSD::authenticate_storage_daemon(STORE *store) @@ -95,10 +101,9 @@ bool DIRAuthenticateSD::authenticate_storage_daemon(STORE *store) StartAuthTimeout(); /* Sent Hello SD: Bacula Director calling */ if (!sd->fsend(hello, "SD: Bacula ", dirname, DIR_VERSION, tlspsk_local_need)) { - Dmsg3(dbglvl, _("Error sending Hello to Storage daemon at \"%s:%d\". ERR=%s\n"), - sd->host(), sd->port(), sd->bstrerror()); - Jmsg(jcr, M_FATAL, 0, _("Error sending Hello to Storage daemon at \"%s:%d\". ERR=%s\n"), - sd->host(), sd->port(), sd->bstrerror()); + status = M_FATAL; + MmsgD3(dbglvl, errmsg, _("[DE0011] Error sending Hello to Storage daemon at \"%s:%d\". ERR=%s\n"), + sd->host(), sd->port(), sd->bstrerror()); return false; } @@ -113,17 +118,19 @@ bool DIRAuthenticateSD::authenticate_storage_daemon(STORE *store) Dmsg1(116, ">stored: %s", sd->msg); if (sd->recv() <= 0) { - Jmsg3(jcr, M_FATAL, 0, _("bdirdwho(), sd->host(), sd->bstrerror()); + status = M_FATAL; + Mmsg(errmsg, _("[DE0011] bdirdwho(), sd->host(), sd->bstrerror()); return 0; } Dmsg1(110, "msg); jcr->SDVersion = 0; if (sscanf(sd->msg, SDOKnewHello, &jcr->SDVersion) != 1 && - strncmp(sd->msg, OKhello, sizeof(OKhello)) != 0) { - Dmsg0(dbglvl, _("Storage daemon rejected Hello command\n")); - Jmsg2(jcr, M_FATAL, 0, _("Storage daemon at \"%s:%d\" rejected Hello command\n"), - sd->host(), sd->port()); + strncmp(sd->msg, OKhello, sizeof(OKhello)) != 0) + { + status = M_FATAL; + MmsgD2(dbglvl, errmsg, _("[DE0011] Storage daemon at \"%s:%d\" rejected Hello command\n"), + sd->host(), sd->port()); return 0; } /* For newer SD turn on comm line compression */ @@ -134,8 +141,9 @@ bool DIRAuthenticateSD::authenticate_storage_daemon(STORE *store) Dmsg0(050, "*** No Dir compression to SD\n"); } if (jcr->SDVersion < SD_VERSION) { - Jmsg2(jcr, M_FATAL, 0, _("Older Storage daemon at \"%s:%d\" incompatible with this Director.\n"), - sd->host(), sd->port()); + status = M_FATAL; + Mmsg(errmsg, _("[DE0011] Older Storage daemon at \"%s:%d\" incompatible with this Director.\n"), + sd->host(), sd->port()); return 0; } return 1; @@ -152,9 +160,15 @@ public: int authenticate_file_daemon(); }; -int authenticate_file_daemon(JCR *jcr) +int authenticate_file_daemon(JCR *jcr, int *status, POOLMEM **errmsg) { - return DIRAuthenticateFD(jcr).authenticate_file_daemon(); + DIRAuthenticateFD auth(jcr); + int ret = auth.authenticate_file_daemon(); + if (!ret) { + *status = auth.status; + pm_strcpy(errmsg, auth.errmsg); + } + return ret; } int DIRAuthenticateFD::authenticate_file_daemon() @@ -176,9 +190,8 @@ int DIRAuthenticateFD::authenticate_file_daemon() /* Timeout Hello after 1 min */ StartAuthTimeout(); if (!fd->fsend(hello, "", dirname, DIR_VERSION, tlspsk_local_need)) { - Dmsg3(dbglvl, _("Error sending Hello to File daemon at \"%s:%d\". ERR=%s\n"), - fd->host(), fd->port(), fd->bstrerror()); - Jmsg(jcr, M_FATAL, 0, _("Error sending Hello to File daemon at \"%s:%d\". ERR=%s\n"), + status = M_FATAL; + MmsgD3(dbglvl, errmsg, _("[DE0011] Error sending Hello to File daemon at \"%s:%d\". ERR=%s\n"), fd->host(), fd->port(), fd->bstrerror()); return false; } @@ -194,20 +207,20 @@ int DIRAuthenticateFD::authenticate_file_daemon() Dmsg1(116, ">filed: %s", fd->msg); if (fd->recv() <= 0) { - Dmsg1(dbglvl, _("Bad response from File daemon to Hello command: ERR=%s\n"), - fd->bstrerror()); - Jmsg(jcr, M_FATAL, 0, _("Bad response from File daemon at \"%s:%d\" to Hello command: ERR=%s\n"), - fd->host(), fd->port(), fd->bstrerror()); + status = M_FATAL; + MmsgD3(dbglvl, errmsg, _("[DE0011] Bad response from File daemon at \"%s:%d\" to Hello command: ERR=%s\n"), + fd->host(), fd->port(), fd->bstrerror()); return 0; } Dmsg1(110, "msg); StopAuthTimeout(); jcr->FDVersion = 0; if (strncmp(fd->msg, FDOKhello, sizeof(FDOKhello)) != 0 && - sscanf(fd->msg, FDOKnewHello, &jcr->FDVersion) != 1) { - Dmsg0(dbglvl, _("File daemon rejected Hello command\n")); - Jmsg(jcr, M_FATAL, 0, _("File daemon at \"%s:%d\" rejected Hello command\n"), - fd->host(), fd->port()); + sscanf(fd->msg, FDOKnewHello, &jcr->FDVersion) != 1) + { + status = M_FATAL; + MmsgD2(dbglvl, errmsg, _("[DE0011] File daemon at \"%s:%d\" rejected Hello command\n"), + fd->host(), fd->port()); return 0; } /* For newer FD turn on comm line compression */ @@ -231,8 +244,9 @@ public: } virtual ~UAAuthenticate() {}; void TLSFailure() { - Jmsg(jcr, M_SECURITY, 0, _("TLS negotiation failed with %s at \"%s:%d\"\n"), - GetRemoteClassShortName(), bsock->host(), bsock->port()); + status = M_SECURITY; + MmsgD3(dbglvl, errmsg, _("TLS negotiation failed with %s at \"%s:%d\"\n"), + GetRemoteClassShortName(), bsock->host(), bsock->port()); } int authenticate_user_agent(); @@ -259,8 +273,9 @@ int UAAuthenticate::authenticate_user_agent() bool legacy_auth = true; if (ua->msglen < 16 || ua->msglen >= MAX_NAME_LENGTH + 15) { - Qmsg3(NULL, M_SECURITY, 0, _("UA Hello from %s:%s is invalid. Len=%d\n"), ua->who(), - ua->host(), ua->msglen); + status = M_SECURITY; + Mmsg(errmsg, _("[DE0011] UA Hello from %s:%s is invalid. Len=%d\n"), ua->who(), + ua->host(), ua->msglen); sleep(5); return 0; } @@ -273,8 +288,9 @@ int UAAuthenticate::authenticate_user_agent() scan_string(ua->msg, "Hello %127s calling", name) != 1) { ua->msg[100] = 0; /* terminate string */ - Qmsg3(NULL, M_SECURITY, 0, _("UA Hello from %s:%s is invalid. Got: %s\n"), ua->who(), - ua->host(), ua->msg); + status = M_SECURITY; + Mmsg(errmsg, _("[DE0011] UA Hello from %s:%s is invalid. Got: %s\n"), ua->who(), + ua->host(), ua->msg); sleep(5); return 0; } @@ -357,8 +373,9 @@ int UAAuthenticate::authenticate_user_agent() auth_done: if (!auth_success) { ua->fsend("%s", _(Dir_sorry)); - Jmsg4(NULL, M_SECURITY, 0, _("Unable to authenticate console \"%s\" at %s:%s:%d.\n"), - name, ua->who(), ua->host(), ua->port()); + status = M_SECURITY; + Mmsg(errmsg, _("[DE0015] Unable to authenticate console \"%s\" at %s:%s:%d.\n"), + name, ua->who(), ua->host(), ua->port()); sleep(5); return 0; } @@ -405,22 +422,26 @@ bool UAAuthenticate::authenticate_with_plugin(CONRES * cons) authData = (bDirAuthenticationRegister*) dir_authplugin_getauthenticationData(uac->jcr, cons->hdr.name, cons->authenticationplugin); if (authData == NULL) { + status = M_FATAL; + Mmsg(errmsg, "[DE0011] Incorrect authentication plugin initialization\n"); return false; } // do tls before real auth if (!ServerEarlyTLS()) - { + { // errmsg already edited return false; } // We require to have TLS setup to use authentication plugins if (!tls_started) { - Dmsg0(dbglvl, "Unable to use Plugin Authentication because TLS is not available\n"); + status = M_FATAL; + MmsgD0(dbglvl, errmsg, _("[DE0011] Unable to use Plugin Authentication because TLS is not available\n")); return false; } // send auth plugin start packet and optional welcome string to console if (!bsock->fsend("auth interactive %s\n", NPRTB(authData->welcome))) { - Dmsg1(dbglvl, "Send interactive start comm error. ERR=%s\n", bsock->bstrerror()); + status = M_FATAL; + MmsgD1(dbglvl, errmsg, "[DE0011] Send interactive start comm error. ERR=%s\n", bsock->bstrerror()); return false; } @@ -430,11 +451,15 @@ bool UAAuthenticate::authenticate_with_plugin(CONRES * cons) for (uint i = 0; i < authData->num; i++){ Dmsg1(dbglvl, "bDirAuthenticationData step %d\n", i); if (dir_authplugin_do_interaction(uac->jcr, bsock, authData->name, (void *)&data[i]) != bRC_OK){ + status = M_FATAL; + Mmsg(errmsg, "[DE0011] Invalid authentication protocol\n"); return false; } } if (dir_authplugin_authenticate(uac->jcr, bsock, authData->name) != bRC_OK){ + status = M_FATAL; + Mmsg(errmsg, "[DE0015] Authorization failed\n"); bsock->fsend(_("1999 Authorization failed !!!.\n")); bmicrosleep(5, 0); return false; diff --git a/bacula/src/dird/backup.c b/bacula/src/dird/backup.c index 377cbc906..0590f2b52 100644 --- a/bacula/src/dird/backup.c +++ b/bacula/src/dird/backup.c @@ -466,7 +466,7 @@ bool do_backup(JCR *jcr) char ed1[100]; db_int64_ctx job, first, last; int64_t val=0; - POOL_MEM buf; + POOL_MEM buf, tmp; if (jcr->is_JobLevel(L_VIRTUAL_FULL)) { return do_vbackup(jcr); @@ -581,6 +581,13 @@ bool do_backup(JCR *jcr) Dmsg1(100, "Connected to the storage: %s\n", jcr->store_mngr->get_wstore()->name()); } + /* Print connection info only for real jobs */ + build_connecting_info_log(_("Storage"), jcr->store_mngr->get_wstore()->name(), + get_storage_address(jcr->client, jcr->store_mngr->get_wstore()), + jcr->store_mngr->get_wstore()->SDport, + jcr->store_bsock->tls ? true : false, buf.addr()); + Jmsg(jcr, M_INFO, 0, "%s", buf.c_str()); + alist wlist; wlist.init(10, not_owned_by_alist); wlist.append(store); @@ -638,12 +645,19 @@ bool do_backup(JCR *jcr) } jcr->setJobStatus(JS_WaitFD); if (!connect_to_file_daemon(jcr, 10, FDConnectTimeout, 1)) { + Jmsg(jcr, M_FATAL, 0, "%s", jcr->errmsg); goto bail_out; } jcr->setJobStatus(JS_Running); fd = jcr->file_bsock; + /* Print connection info only for real jobs */ + build_connecting_info_log(_("Client"), jcr->client->name(), + get_client_address(jcr, jcr->client, tmp.addr()), jcr->client->FDport, + fd->tls ? true : false, buf.addr()); + Jmsg(jcr, M_INFO, 0, "%s", buf.c_str()); + if (!send_level_command(jcr)) { goto bail_out; } @@ -868,8 +882,8 @@ int wait_for_job_termination(JCR *jcr, int timeout) jcr->CommCompressedBytes = CommCompressedBytes; jcr->Snapshot = VSS; jcr->Encrypt = Encrypt; - } else if (jcr->getJobStatus() != JS_Canceled) { - Jmsg(jcr, M_FATAL, 0, _("No Job status returned from FD.\n")); + } else if (!jcr->is_canceled()) { + Jmsg(jcr, M_FATAL, 0, _("No Job status returned from FD. %c\n"), jcr->getJobStatus()); } /* Return the first error status we find Dir, FD, or SD */ diff --git a/bacula/src/dird/fd_cmds.c b/bacula/src/dird/fd_cmds.c index db07ae9f6..c2f150819 100644 --- a/bacula/src/dird/fd_cmds.c +++ b/bacula/src/dird/fd_cmds.c @@ -76,6 +76,8 @@ static void delete_bsock_end_cb(JCR *jcr, void *ctx) * Open connection with File daemon. * Try connecting every retry_interval (default 10 sec), and * give up after max_retry_time (default 30 mins). + * If the return code is 0, the error is stored inside jcr->errmsg + * Need to call free_bsock() if an error occurs outside of a job */ int connect_to_file_daemon(JCR *jcr, int retry_interval, int max_retry_time, @@ -84,9 +86,10 @@ int connect_to_file_daemon(JCR *jcr, int retry_interval, int max_retry_time, BSOCK *fd = jcr->file_bsock; char ed1[30]; utime_t heart_beat; + int status; if (!jcr->client) { - Jmsg(jcr, M_FATAL, 0, _("File daemon not defined for current Job\n")); + Mmsg(jcr->errmsg, _("[DE0017] File daemon not defined for current Job\n")); Dmsg0(10, "No Client defined for the job.\n"); return 0; } @@ -96,7 +99,6 @@ int connect_to_file_daemon(JCR *jcr, int retry_interval, int max_retry_time, } else { heart_beat = director->heartbeat_interval; } - if (!is_bsock_open(jcr->file_bsock)) { char name[MAX_NAME_LENGTH + 100]; POOL_MEM buf, tmp; @@ -114,11 +116,8 @@ int connect_to_file_daemon(JCR *jcr, int retry_interval, int max_retry_time, Dmsg0(DT_NETWORK, "Found a socket, keep it!\n"); job_end_push(jcr, delete_bsock_end_cb, (void *)jcr->file_bsock); } - - /* if address == NULL forget it */ if (!fd) { - Dmsg0(DT_NETWORK, "No socket in client \n"); - jcr->setJobStatus(JS_ErrorTerminated); + Mmsg(jcr->errmsg, "[DE0010] No socket found of the client\n"); return 0; } jcr->file_bsock = fd; @@ -142,7 +141,7 @@ int connect_to_file_daemon(JCR *jcr, int retry_interval, int max_retry_time, jcr->client->FDport, verbose)) { fd->close(); - jcr->setJobStatus(JS_ErrorTerminated); + pm_strcpy(jcr->errmsg, fd->errmsg); return 0; } Dmsg0(10, "Opened connection with File daemon\n"); @@ -151,23 +150,11 @@ int connect_to_file_daemon(JCR *jcr, int retry_interval, int max_retry_time, fd->res = (RES *)jcr->client; /* save resource in BSOCK */ jcr->setJobStatus(JS_Running); - if (!authenticate_file_daemon(jcr)) { - jcr->setJobStatus(JS_ErrorTerminated); - Dmsg0(10, "Authentication error with FD.\n"); + if (!authenticate_file_daemon(jcr, &status, &jcr->errmsg)) { + Dmsg1(10, "Authentication error with FD. %s\n", jcr->errmsg); 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 */ @@ -183,10 +170,10 @@ int connect_to_file_daemon(JCR *jcr, int retry_interval, int max_retry_time, if (bget_dirmsg(jcr, fd, BSOCK_TYPE_FD) > 0) { Dmsg1(110, "msg); if (strncmp(fd->msg, OKjob, strlen(OKjob)) != 0) { - Jmsg(jcr, M_FATAL, 0, _("File daemon \"%s\" rejected Job command: %s\n"), + Mmsg(jcr->errmsg, _("[DE0011] File daemon \"%s\" rejected Job command: %s\n"), jcr->client->hdr.name, fd->msg); - jcr->setJobStatus(JS_ErrorTerminated); return 0; + } else if (jcr->db) { CLIENT_DBR cr; memset(&cr, 0, sizeof(cr)); @@ -204,14 +191,13 @@ int connect_to_file_daemon(JCR *jcr, int retry_interval, int max_retry_time, bstrncpy(cr.Uname, fd->msg+strlen(OKjob)+1, sizeof(cr.Uname)); if (!db_update_client_record(jcr, jcr->db, &cr)) { - Jmsg(jcr, M_WARNING, 0, _("Error updating Client record. ERR=%s\n"), - db_strerror(jcr->db)); + Jmsg(jcr, M_WARNING, 0, _("[DE0008] Error updating Client record. ERR=%s\n"), + db_strerror(jcr->db)); } } } else { - Jmsg(jcr, M_FATAL, 0, _("FD gave bad response to JobId command: %s\n"), + Mmsg(jcr->errmsg, _("[DE0011] FD gave bad response to JobId command: %s\n"), fd->bstrerror()); - jcr->setJobStatus(JS_ErrorTerminated); return 0; } return 1; diff --git a/bacula/src/dird/job.c b/bacula/src/dird/job.c index b59400833..ff674386a 100644 --- a/bacula/src/dird/job.c +++ b/bacula/src/dird/job.c @@ -557,7 +557,7 @@ static bool cancel_file_daemon_job(UAContext *ua, const char *cmd, JCR *jcr) old_client = ua->jcr->client; ua->jcr->client = jcr->client; if (!connect_to_file_daemon(ua->jcr, 10, FDConnectTimeout, 1)) { - ua->error_msg(_("Failed to connect to File daemon.\n")); + ua->error_msg("%s", ua->jcr->errmsg); goto bail_out; } Dmsg3(10, "Connected to file daemon %s for cancel ua.jcr=%p jcr=%p\n", diff --git a/bacula/src/dird/msgchan.c b/bacula/src/dird/msgchan.c index f6dbbda17..60603f362 100644 --- a/bacula/src/dird/msgchan.c +++ b/bacula/src/dird/msgchan.c @@ -97,6 +97,7 @@ bool connect_to_storage_daemon(JCR *jcr, int retry_interval, utime_t heart_beat; STORE *wstore = jcr->store_mngr->get_wstore(); POOL_MEM buf; + int status; if (is_bsock_open(sd)) { return true; /* already connected */ @@ -113,7 +114,7 @@ bool connect_to_storage_daemon(JCR *jcr, int retry_interval, } if (!store) { - Dmsg1(100, "No storage resource found in jcr for JobId: %d!\n", jcr->JobId); + MmsgD1(100, jcr->errmsg, "[DE0017] No storage resource found in jcr for JobId: %d!\n", jcr->JobId); return false; } @@ -131,8 +132,9 @@ bool connect_to_storage_daemon(JCR *jcr, int retry_interval, sd->set_source_address(director->DIRsrc_addr); 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)) { - + store->address, NULL, store->SDport, verbose)) + { + pm_strcpy(jcr->errmsg, sd->errmsg); if (!jcr->store_bsock) { /* The bsock was locally created, so we free it here */ free_bsock(sd); } @@ -140,24 +142,16 @@ bool connect_to_storage_daemon(JCR *jcr, int retry_interval, } if (sd == NULL) { + /* Not able to connect the SD, error message in jcr->errmsg */ return false; } sd->res = (RES *)store; /* save pointer to other end */ jcr->store_bsock = sd; - if (!authenticate_storage_daemon(jcr, store)) { + if (!authenticate_storage_daemon(jcr, store, &status, &jcr->errmsg)) { 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/dird/protos.h b/bacula/src/dird/protos.h index acf2c5a3f..5714651b6 100644 --- a/bacula/src/dird/protos.h +++ b/bacula/src/dird/protos.h @@ -27,8 +27,8 @@ extern void admin_cleanup(JCR *jcr, int TermCode); /* authenticate.c */ -extern bool authenticate_storage_daemon(JCR *jcr, STORE *store); -extern int authenticate_file_daemon(JCR *jcr); +extern bool authenticate_storage_daemon(JCR *jcr, STORE *store, int *status, POOLMEM **errmsg); +extern int authenticate_file_daemon(JCR *jcr, int *status, POOLMEM **errmsg); extern int authenticate_user_agent(UAContext *ua); /* autoprune.c */ diff --git a/bacula/src/dird/restore.c b/bacula/src/dird/restore.c index 1927eef21..f83f1dcca 100644 --- a/bacula/src/dird/restore.c +++ b/bacula/src/dird/restore.c @@ -305,7 +305,7 @@ bool restore_bootstrap(JCR *jcr) uint32_t store_port; bool first_time = true; bootstrap_info info; - POOL_MEM restore_cmd(PM_MESSAGE); + POOL_MEM restore_cmd(PM_MESSAGE), buf(PM_FNAME); bool ret = false; /* Open the bootstrap file */ @@ -339,6 +339,13 @@ bool restore_bootstrap(JCR *jcr) goto bail_out; } sd = jcr->store_bsock; + + build_connecting_info_log(_("Storage"), jcr->store_mngr->get_rstore()->name(), + get_storage_address(jcr->client, jcr->store_mngr->get_rstore()), + jcr->store_mngr->get_rstore()->SDport, + sd->tls ? true : false, buf.addr()); + Jmsg(jcr, M_INFO, 0, "%s", buf.c_str()); + /* * Now start a job with the Storage daemon */ @@ -347,16 +354,23 @@ bool restore_bootstrap(JCR *jcr) } if (first_time) { + POOL_MEM tmp, buf; /* * Start conversation with File daemon */ jcr->setJobStatus(JS_WaitFD); jcr->keep_sd_auth_key = true; /* don't clear the sd_auth_key now */ if (!connect_to_file_daemon(jcr, 10, FDConnectTimeout, 1)) { + Jmsg(jcr, M_FATAL, 0, "%s", jcr->errmsg); goto bail_out; } fd = jcr->file_bsock; build_restore_command(jcr, restore_cmd); + + build_connecting_info_log(_("Client"), jcr->client->name(), + get_client_address(jcr, jcr->client, tmp.addr()), jcr->client->FDport, + fd->tls ? true : false, buf.addr()); + Jmsg(jcr, M_INFO, 0, "%s", buf.c_str()); } jcr->setJobStatus(JS_Running); diff --git a/bacula/src/dird/snapshot.c b/bacula/src/dird/snapshot.c index 5d2cfb6e0..c9ea2f827 100644 --- a/bacula/src/dird/snapshot.c +++ b/bacula/src/dird/snapshot.c @@ -182,7 +182,7 @@ int delete_snapshot(UAContext *ua) ua->send_msg(_("Connecting to Client %s at %s:%d\n"), client->name(), get_client_address(ua->jcr, client, buf.addr()), client->FDport); if (!connect_to_file_daemon(ua->jcr, 1, 15, 0)) { - ua->error_msg(_("Failed to connect to Client.\n")); + ua->error_msg("%s", ua->jcr->errmsg); free_bsock(ua->jcr->file_bsock); ua->jcr->client = old_client; return 0; @@ -233,7 +233,7 @@ int list_snapshot(UAContext *ua, alist *snap_list) client->name(), get_client_address(ua->jcr, client, tmp.addr()), client->FDport); if (!connect_to_file_daemon(ua->jcr, 1, 15, 0)) { - ua->error_msg(_("Failed to connect to Client.\n")); + ua->error_msg("%s", ua->jcr->errmsg); goto bail_out; } @@ -332,7 +332,7 @@ int prune_snapshot(UAContext *ua) ua->send_msg(_("Connecting to Client %s at %s:%d\n"), client->name(), get_client_address(ua->jcr, client, tmp.addr()), client->FDport); if (!connect_to_file_daemon(ua->jcr, 1, 15, 0)) { - ua->error_msg(_("Failed to connect to Client.\n")); + ua->error_msg("%s", ua->jcr->errmsg); free_bsock(ua->jcr->file_bsock); ua->jcr->client = NULL; client = NULL; diff --git a/bacula/src/dird/ua_cmds.c b/bacula/src/dird/ua_cmds.c index 140a31e71..9d2775a26 100644 --- a/bacula/src/dird/ua_cmds.c +++ b/bacula/src/dird/ua_cmds.c @@ -763,7 +763,7 @@ static int setbwlimit_client(UAContext *ua, CLIENT *client, char *Job, int64_t l ua->send_msg(_("Connecting to Client %s at %s:%d\n"), client->name(), get_client_address(ua->jcr, client, buf.addr()), client->FDport); if (!connect_to_file_daemon(ua->jcr, 1, 15, 0)) { - ua->error_msg(_("Failed to connect to Client.\n")); + ua->error_msg("%s", ua->jcr->errmsg); goto bail_out; } Dmsg0(120, "Connected to file daemon\n"); @@ -1106,7 +1106,7 @@ static void do_client_setdebug(UAContext *ua, CLIENT *client, client->name(), get_client_address(ua->jcr, client, buf.addr()), client->FDport); if (!connect_to_file_daemon(ua->jcr, 1, 15, 0)) { - ua->error_msg(_("Failed to connect to Client.\n")); + ua->error_msg("%s", ua->jcr->errmsg); goto bail_out; } Dmsg0(120, "Connected to file daemon\n"); @@ -1562,7 +1562,7 @@ static int estimate_cmd(UAContext *ua, const char *cmd) ua->send_msg(_("Connecting to Client %s at %s:%d\n"), jcr->client->name(), get_client_address(jcr, jcr->client, buf.addr()), jcr->client->FDport); if (!connect_to_file_daemon(jcr, 1, 15, 0)) { - ua->error_msg(_("Failed to connect to Client.\n")); + ua->error_msg("%s", jcr->errmsg); goto bail_out; } diff --git a/bacula/src/dird/ua_collect.c b/bacula/src/dird/ua_collect.c index 2aac98703..bcc198e9d 100644 --- a/bacula/src/dird/ua_collect.c +++ b/bacula/src/dird/ua_collect.c @@ -354,7 +354,7 @@ void do_collect_client(UAContext *ua, CLIENT *client, bool doall, display_format POOL_MEM buf; if (!acl_access_client_ok(ua, client->name(), JT_BACKUP_RESTORE)) { - ua->error_msg(_("No authorization for Client \"%s\"\n"), client->name()); + ua->error_msg(_("[DE0016] No authorization for Client \"%s\"\n"), client->name()); return; } /* Connect to File daemon */ @@ -370,8 +370,7 @@ void do_collect_client(UAContext *ua, CLIENT *client, bool doall, display_format if (!ua->api) ua->send_msg(_("Connecting to Client %s at %s:%d\n"), client->name(), get_client_address(ua->jcr, client, buf.addr()), client->FDport); if (!connect_to_file_daemon(ua->jcr, 1, 15, 0)) { - ua->send_msg(_("Failed to connect to Client %s.\n====\n"), - client->name()); + ua->error_msg("%s", ua->jcr->errmsg); free_bsock(ua->jcr->file_bsock); return; } @@ -426,7 +425,7 @@ void do_collect_storage(UAContext *ua, STORE *store, bool doall, display_format_ */ if (have_restricted_acl(ua, Client_ACL) || have_restricted_acl(ua, Job_ACL)) { - ua->error_msg(_("Restricted Client or Job does not permit access to Storage daemons\n")); + ua->error_msg(_("[DE0016] Restricted Client or Job does not permit access to Storage daemons\n")); return; } diff --git a/bacula/src/dird/ua_dotcmds.c b/bacula/src/dird/ua_dotcmds.c index 99d261290..b21340f4d 100644 --- a/bacula/src/dird/ua_dotcmds.c +++ b/bacula/src/dird/ua_dotcmds.c @@ -244,6 +244,7 @@ static bool dot_ls_cmd(UAContext *ua, const char *cmd) char *plugin = NULL; JCR *jcr = ua->jcr; int i; + bool ret = false; jcr->setJobLevel(L_FULL); i = find_arg_with_value(ua, NT_("client")); @@ -289,8 +290,8 @@ static bool dot_ls_cmd(UAContext *ua, const char *cmd) jcr->client->FDport); if (!connect_to_file_daemon(jcr, 1, 15, 0)) { - ua->error_msg(_("Failed to connect to Client.\n")); - return false; + ua->error_msg("%s", jcr->errmsg); + goto bail_out; } /* when .ls plugin prepare a special ls_plugin_fileset */ @@ -311,12 +312,15 @@ static bool dot_ls_cmd(UAContext *ua, const char *cmd) ua->send_msg("%s", jcr->file_bsock->msg); } + ret = true; + bail_out: if (jcr->file_bsock) { jcr->file_bsock->signal(BNET_TERMINATE); free_bsock(ua->jcr->file_bsock); } - return true; + jcr->client = NULL; + return ret; } #ifdef COMMUNITY @@ -1750,7 +1754,7 @@ static void do_storage_cmd(UAContext *ua, STORE *store, const char *cmd) store->name(), store->address, store->SDport); if (!connect_to_storage_daemon(jcr, 1, 15, 0)) { ua->error_msg(_("Failed to connect to Storage daemon.\n")); - return; + goto bail_out; } Dmsg0(120, _("Connected to storage daemon\n")); sd = jcr->store_bsock; @@ -1759,6 +1763,8 @@ static void do_storage_cmd(UAContext *ua, STORE *store, const char *cmd) ua->send_msg("%s", sd->msg); } sd->signal(BNET_TERMINATE); + +bail_out: free_bsock(ua->jcr->store_bsock); return; } @@ -1774,7 +1780,7 @@ static void do_client_cmd(UAContext *ua, CLIENT *client, const char *cmd) ua->send_msg(_("Connecting to Client %s at %s:%d\n"), client->name(), get_client_address(ua->jcr, client, buf.addr()), client->FDport); if (!connect_to_file_daemon(ua->jcr, 1, 15, 0)) { - ua->error_msg(_("Failed to connect to Client.\n")); + ua->error_msg("%s", ua->jcr->errmsg); goto bail_out; } Dmsg0(120, "Connected to file daemon\n"); @@ -1787,6 +1793,7 @@ static void do_client_cmd(UAContext *ua, CLIENT *client, const char *cmd) bail_out: free_bsock(ua->jcr->file_bsock); + ua->jcr->client = NULL; return; } @@ -2390,7 +2397,7 @@ static bool dot_querycmd(UAContext *ua, const char *cmd) init_jcr_job_record(jcr); // need job if (!connect_to_file_daemon(jcr, 1, 15, 0)) { - ua->error_msg(_("error=Failed to connect to Client.\n")); + ua->error_msg("%s", jcr->errmsg); goto bail_out; } @@ -2405,6 +2412,7 @@ static bool dot_querycmd(UAContext *ua, const char *cmd) while (jcr->file_bsock->recv() >= 0) { ua->send_msg("%s", jcr->file_bsock->msg); } + ret = true; ret = true; diff --git a/bacula/src/dird/ua_status.c b/bacula/src/dird/ua_status.c index 596c11012..526d0f425 100644 --- a/bacula/src/dird/ua_status.c +++ b/bacula/src/dird/ua_status.c @@ -186,7 +186,7 @@ static int do_network_status(UAContext *ua) } if (!connect_to_file_daemon(jcr, 1, 15, 0)) { - ua->error_msg(_("Failed to connect to Client.\n")); + ua->error_msg("%s", jcr->errmsg); goto bail_out; } @@ -645,7 +645,7 @@ static void do_client_status(UAContext *ua, CLIENT *client, char *cmd) int i; if (!acl_access_client_ok(ua, client->name(), JT_BACKUP_RESTORE)) { - ua->error_msg(_("No authorization for Client \"%s\"\n"), client->name()); + ua->error_msg(_("[DE0016] No authorization for Client \"%s\"\n"), client->name()); return; } @@ -667,8 +667,7 @@ static void do_client_status(UAContext *ua, CLIENT *client, char *cmd) if (!ua->api) ua->send_msg(_("Connecting to Client %s at %s:%d\n"), client->name(), get_client_address(ua->jcr, client, buf.addr()), client->FDport); if (!connect_to_file_daemon(ua->jcr, 1, 15, 0)) { - ua->send_msg(_("Failed to connect to Client %s.\n====\n"), - client->name()); + ua->error_msg("%s", ua->jcr->errmsg); free_bsock(ua->jcr->file_bsock); return; } diff --git a/bacula/src/dird/verify.c b/bacula/src/dird/verify.c index 6a7280eef..10fe85cd9 100644 --- a/bacula/src/dird/verify.c +++ b/bacula/src/dird/verify.c @@ -303,12 +303,21 @@ bool do_verify(JCR *jcr) */ jcr->setJobStatus(JS_Blocked); if (!connect_to_file_daemon(jcr, 10, FDConnectTimeout, 1)) { + Jmsg(jcr, M_FATAL, 0, "%s", jcr->errmsg); goto bail_out; } jcr->setJobStatus(JS_Running); fd = jcr->file_bsock; + { + POOL_MEM buf, tmp; + /* Print connection info only for real jobs */ + build_connecting_info_log(_("Client"), jcr->client->name(), + get_client_address(jcr, jcr->client, tmp.addr()), jcr->client->FDport, + fd->tls ? true : false, buf.addr()); + Jmsg(jcr, M_INFO, 0, "%s", buf.c_str()); + } Dmsg0(30, ">filed: Send include list\n"); if (!send_include_list(jcr)) { diff --git a/bacula/src/filed/authenticate.c b/bacula/src/filed/authenticate.c index c1bbd2d67..9f6cbbc37 100644 --- a/bacula/src/filed/authenticate.c +++ b/bacula/src/filed/authenticate.c @@ -97,7 +97,7 @@ bool FDAuthenticateDIR::validate_dir_hello() if (!director) { char addr[64]; char *who = dir->get_peer(addr, sizeof(addr)) ? dir->who() : addr; - Jmsg2(jcr, M_FATAL, 0, _("Connection from unknown Director %s at %s rejected.\n"), + Jmsg2(jcr, M_FATAL, 0, _("[FE0016] Connection from unknown Director %s at %s rejected.\n"), dirname, who); goto auth_fatal; } diff --git a/bacula/src/filed/hello.c b/bacula/src/filed/hello.c index 47d3abcd7..e03bcaa38 100644 --- a/bacula/src/filed/hello.c +++ b/bacula/src/filed/hello.c @@ -180,7 +180,7 @@ bool recv_sdcaps(JCR *jcr) stat = sd->recv(); if (stat <= 0) { berrno be; - Jmsg1(jcr, M_FATAL, 0, _("Recv caps from SD failed. ERR=%s\n"), + Jmsg1(jcr, M_FATAL, 0, _("[FE0011] Recv caps from SD failed. ERR=%s\n"), be.bstrerror()); Dmsg1(050, _("Recv caps from SD failed. ERR=%s\n"), be.bstrerror()); return false; @@ -266,8 +266,8 @@ bool FDUAAuthenticateDir::authenticate_director(const char *name, DIRINFO *dir, */ Dmsg1(dbglvl, ">dird: %s", UA_sock->msg); if (UA_sock->recv() <= 0) { - Mmsg(jcr->errmsg, _("Bad response to Hello command: ERR=%s\n"), - UA_sock->bstrerror()); + Mmsg(errmsg, _("[FE0011] Bad response to Hello command: ERR=%s\n"), + UA_sock->bstrerror()); return false; } @@ -275,7 +275,7 @@ bool FDUAAuthenticateDir::authenticate_director(const char *name, DIRINFO *dir, if (strncmp(UA_sock->msg, DirOKhello, sizeof(DirOKhello)-3) == 0) { sscanf(UA_sock->msg, DirOKhello, &dir_version); } else { - Mmsg(jcr->errmsg, _("Director rejected Hello command\n")); + Mmsg(errmsg, _("[FE0011] Director rejected Hello command\n")); return false; } /* Turn on compression for newer Directors */ @@ -305,19 +305,21 @@ BSOCK *connect_director(JCR *jcr, const char *name, DIRINFO *dir, connect_dir_mo UA_sock = new_bsock(); if (!UA_sock->connect(NULL, 5, 15, heart_beat, "Director daemon", dir->address, NULL, dir->DIRport, 0)) { + pm_strcpy(jcr->errmsg, UA_sock->errmsg); free_bsock(UA_sock); return NULL; } - if (FDUAAuthenticateDir(jcr, UA_sock).authenticate_director(name, dir, mode)) { + FDUAAuthenticateDir auth(jcr, UA_sock); + if (auth.authenticate_director(name, dir, mode)) { return UA_sock; } free_bsock(UA_sock); Mmsg(jcr->errmsg, - ( _("Director authorization problem.\n" - "Most likely the passwords do not agree.\n" - "If you are using TLS, there may have been a certificate validation error during the TLS handshake.\n" - "For help, please see " MANUAL_AUTH_URL "\n"))); + _("Director authorization problem.\n" + "Most likely the passwords do not agree.\n" + "If you are using TLS, there may have been a certificate validation error during the TLS handshake.\n" + "For help, please see " MANUAL_AUTH_URL "\n%s"), auth.errmsg); return NULL; } diff --git a/bacula/src/lib/authenticatebase.cc b/bacula/src/lib/authenticatebase.cc index 4342af677..1e0118a8a 100644 --- a/bacula/src/lib/authenticatebase.cc +++ b/bacula/src/lib/authenticatebase.cc @@ -55,15 +55,19 @@ tlspsk_local_need(0), tid(NULL), auth_success(false), check_early_tls(false), -tls_started(false) +tls_started(false), +errmsg(get_pool_memory(PM_FNAME)), +status(0) { local_name[0]='\0'; remote_name[0]='\0'; + errmsg[0]='\0'; } AuthenticateBase::~AuthenticateBase() { StopAuthTimeout(); + free_pool_memory(errmsg); } /* @@ -343,13 +347,15 @@ bool AuthenticateBase::CheckTLSRequirement() /* Verify that the connection is willing to meet our TLS requirements */ switch (TestTLSRequirement()) { case TLS_REQ_ERR_LOCAL: - Jmsg(jcr, msg_type, 0, _("Authorization problem: %s \"%s:%s\" did not advertise required TLS support.\n"), - GetRemoteClassShortName(), bsock->who(), bsock->host()); + status = msg_type; + Mmsg(errmsg, _("[%cE0017] Authorization problem: %s \"%s:%s\" did not advertise required TLS support.\n"), + component_code, GetLocalClassShortName(), bsock->who(), bsock->host()); return false; case TLS_REQ_ERR_REMOTE: - Jmsg(jcr, msg_type, 0, _("Authorization problem: %s \"%s:%s\" did not advertise required TLS support.\n"), - GetRemoteClassShortName(), bsock->who(), bsock->host()); + status = msg_type; + Mmsg(errmsg, _("[%cE0017] Authorization problem: %s \"%s:%s\" did not advertise required TLS support.\n"), + component_code, GetRemoteClassShortName(), bsock->who(), bsock->host()); return false; case TLS_REQ_OK: break; @@ -372,6 +378,8 @@ bool AuthenticateBase::ClientEarlyTLS() check_early_tls=true; if (bsock->recv() <= 0) { bmicrosleep(5, 0); // original cram_md5_respond() wait for 5s here + status = M_FATAL; + Mmsg(errmsg, "[%cE0011] Unable to get starttls protocol\n", component_code); return false; } if (scan_string(bsock->msg, "starttls tlspsk=%d\n", &tlspsk_remote) != EOF) { @@ -403,6 +411,8 @@ bool AuthenticateBase::ClientCramMD5AuthenticateBase(const char *password) (local_class == dcFD && remote_class == dcSD))) { if (jcr && job_canceled(jcr)) { auth_success = false; + status = M_FATAL; + Mmsg(errmsg, "[DE0019] Job is canceled\n"); return false; /* quick exit */ } } @@ -412,6 +422,8 @@ bool AuthenticateBase::ClientCramMD5AuthenticateBase(const char *password) if (local_class == dcSD && remote_class == dcSD) { if (jcr && job_canceled(jcr)) { auth_success = false; + status = M_FATAL; + Mmsg(errmsg, "[DE0019] Job is canceled\n"); return false; /* quick exit */ } } @@ -432,18 +444,22 @@ bool AuthenticateBase::ClientCramMD5AuthenticateBase(const char *password) (local_class == dcSD && remote_class == dcFD) ) { Dmsg2(authdl, "Authorization key rejected by %s at %s.\n", GetRemoteClassShortName(), bsock->who()); - Jmsg(jcr, M_FATAL, 0, _("Authorization key rejected by %s at %s rejected.\n" - "For help, please see: " MANUAL_AUTH_URL "\n"), - GetRemoteClassLongName(), bsock->who()); + status = M_FATAL; + Mmsg(errmsg, _("[%cE0015] Authorization key rejected by %s at %s rejected.\n" + "For help, please see: " MANUAL_AUTH_URL "\n"), + component_code, + GetRemoteClassLongName(), bsock->who()); } else if ((local_class == dcDIR && (remote_class == dcSD || remote_class == dcFD))) { Dmsg2(authdl, _("%s and %s passwords or names not the same.\n"), GetLocalClassLongName(), GetRemoteClassLongName()); - Jmsg6(jcr, M_FATAL, 0, - _("%s unable to authenticate with %s at \"%s:%d\". Possible causes:\n" + status = M_FATAL; + Mmsg(errmsg, + _("[%cE0015] %s unable to authenticate with %s at \"%s:%d\". Possible causes:\n" "Passwords or names not the same or\n" "Maximum Concurrent Jobs exceeded on the %s or\n" "%s networking messed up (restart daemon).\n" "For help, please see: " MANUAL_AUTH_URL "\n"), + component_code, GetLocalClassLongName(), GetRemoteClassLongName(), bsock->host(), bsock->port(), GetRemoteClassShortName(), GetRemoteClassShortName()); @@ -470,8 +486,9 @@ bool AuthenticateBase::ServerEarlyTLS() */ if (!bsock->fsend("starttls tlspsk=%d\n", tlspsk_local_need)) { // TODO tweak the error message - Qmsg3(NULL, M_SECURITY, 0, _("Connection with %s:%s starttls comm error. ERR=%s\n"), bsock->who(), - bsock->host(), bsock->bstrerror()); + status = M_SECURITY; + Mmsg(errmsg, _("[%cE0011] Connection with %s:%s starttls comm error. ERR=%s\n"), + component_code, bsock->who(), bsock->host(), bsock->bstrerror()); sleep(5); return false; } @@ -523,12 +540,15 @@ bool AuthenticateBase::ServerCramMD5Authenticate(const char *password) bsock->who()); } else if ((local_class == dcFD && remote_class == dcSD) || (local_class == dcSD && remote_class == dcFD) ) { - Jmsg(jcr, M_FATAL, 0, _("Incorrect authorization key from %s at %s rejected.\n" - "For help, please see: " MANUAL_AUTH_URL "\n"), - GetRemoteClassLongName(), bsock->who()); + status = M_FATAL; + Mmsg(errmsg, _("Incorrect authorization key from %s at %s rejected.\n" + "For help, please see: " MANUAL_AUTH_URL "\n"), + GetRemoteClassLongName(), bsock->who()); } else { - Jmsg1(jcr, M_FATAL, 0, _("Incorrect password given by %s.\n" - "For help, please see: " MANUAL_AUTH_URL "\n"), GetRemoteClassLongName()); + status = M_FATAL; + Mmsg(errmsg, _("Incorrect password given by %s.\n" + "For help, please see: " MANUAL_AUTH_URL "\n"), + GetRemoteClassLongName()); } } if (tls_authenticate) { /* authentication only? */ @@ -540,8 +560,9 @@ bool AuthenticateBase::ServerCramMD5Authenticate(const char *password) void AuthenticateBase::TLSFailure() { - Jmsg(jcr, M_FATAL, 0, _("TLS negotiation failed with %s at \"%s:%d\"\n"), - GetRemoteClassShortName(), bsock->host(), bsock->port()); + status = M_FATAL; + Mmsg(errmsg, _("TLS negotiation failed with %s at \"%s:%d\"\n"), + GetRemoteClassShortName(), bsock->host(), bsock->port()); } bool AuthenticateBase::HandleTLS() @@ -550,6 +571,7 @@ bool AuthenticateBase::HandleTLS() return true; } if (!CheckTLSRequirement()) { + status = M_FATAL; return false; } @@ -568,8 +590,11 @@ bool AuthenticateBase::HandleTLS() } if (ctx != NULL) { if ((local_type==dtCli && !bnet_tls_client(ctx, bsock, verify_list, password)) || - (local_type==dtSrv && !bnet_tls_server(ctx, bsock, verify_list, password))) { - TLSFailure(); + (local_type==dtSrv && !bnet_tls_server(ctx, bsock, verify_list, password))) + { + // errmsg set by bnet_tls_server/bnet_tls_client + pm_strcpy(errmsg, bsock->errmsg); + status = M_FATAL; return false; } tls_started = true; diff --git a/bacula/src/lib/authenticatebase.h b/bacula/src/lib/authenticatebase.h index bea031d6a..9394f7660 100644 --- a/bacula/src/lib/authenticatebase.h +++ b/bacula/src/lib/authenticatebase.h @@ -71,7 +71,8 @@ protected: bool tls_started; public: - + POOLMEM *errmsg; + int status; enum DaemonClass { dcUnknown=0, dcCON, dcFD, dcSD, dcDIR, dcGUI }; enum DaemonType { dtUnknown=0, dtCli, dtSrv }; diff --git a/bacula/src/lib/bnet.c b/bacula/src/lib/bnet.c index d3a132bfb..96379a0cd 100644 --- a/bacula/src/lib/bnet.c +++ b/bacula/src/lib/bnet.c @@ -58,21 +58,21 @@ static pthread_mutex_t ip_mutex = PTHREAD_MUTEX_INITIALIZER; */ #ifdef HAVE_TLS bool bnet_tls_server(TLS_CONTEXT *ctx, BSOCK * bsock, alist *verify_list, - const char *psk_shared_key) + const char *psk_shared_key) { TLS_CONNECTION *tls; JCR *jcr = bsock->jcr(); tls = new_tls_connection(ctx, bsock->m_fd); if (!tls) { - Qmsg0(bsock->jcr(), M_FATAL, 0, _("TLS connection initialization failed.\n")); + Mmsg(bsock->errmsg, _("[%cE0016] TLS connection initialization failed.\n"), component_code); return false; } if (get_tls_psk_context(ctx)) { if (!psk_shared_key || !psk_set_shared_key(tls, psk_shared_key)) { - Dmsg0(0, "Cannot setup TLS-PSK shared key\n"); - return false; + Dmsg0(10, "Cannot setup TLS-PSK shared key\n"); + goto err; } } @@ -80,15 +80,15 @@ bool bnet_tls_server(TLS_CONTEXT *ctx, BSOCK * bsock, alist *verify_list, /* Initiate TLS Negotiation */ if (!tls_bsock_accept(bsock)) { - Qmsg0(bsock->jcr(), M_FATAL, 0, _("TLS Negotiation failed.\n")); + Mmsg(bsock->errmsg, _("[%cE0017] TLS Negotiation failed.\n"), component_code); goto err; } if (!get_tls_psk_context(ctx)) { if (verify_list) { if (!tls_postconnect_verify_cn(jcr, tls, verify_list)) { - Qmsg1(bsock->jcr(), M_FATAL, 0, _("TLS certificate verification failed." - " Peer certificate did not match a required commonName\n"), - bsock->host()); + Mmsg(bsock->errmsg, _("[%cE0018] TLS certificate verification failed." + " Peer certificate did not match a required commonName\n"), + component_code); goto err; } } @@ -115,14 +115,14 @@ bool bnet_tls_client(TLS_CONTEXT *ctx, BSOCK *bsock, alist *verify_list, tls = new_tls_connection(ctx, bsock->m_fd); if (!tls) { - Qmsg0(bsock->jcr(), M_FATAL, 0, _("TLS connection initialization failed.\n")); + Mmsg(bsock->errmsg, _("[%cE0016] TLS connection initialization failed.\n"), component_code); return false; } if (get_tls_psk_context(ctx)) { if (!psk_shared_key || !psk_set_shared_key(tls, psk_shared_key)) { - Dmsg0(0, "Cannot setup TLS-PSK shared key\n"); - return false; + MmsgD1(10, bsock->errmsg, "[%cE0017] Cannot setup TLS-PSK Password\n", component_code); + goto err; } } @@ -137,17 +137,15 @@ bool bnet_tls_client(TLS_CONTEXT *ctx, BSOCK *bsock, alist *verify_list, * certificate's CN. Otherwise, we use standard host/CN matching. */ if (verify_list) { if (!tls_postconnect_verify_cn(jcr, tls, verify_list)) { - Qmsg1(bsock->jcr(), M_FATAL, 0, _("TLS certificate verification failed." - " Peer certificate did not match a required commonName\n"), - bsock->host()); + Mmsg(bsock->errmsg, _("[%cE0018] TLS certificate verification failed." + " Peer certificate did not match a required commonName\n"), component_code); goto err; } } else if (!tls_postconnect_verify_host(jcr, tls, bsock->host())) { /* If host is 127.0.0.1, try localhost */ if (strcmp(bsock->host(), "127.0.0.1") != 0 || !tls_postconnect_verify_host(jcr, tls, "localhost")) { - Qmsg1(bsock->jcr(), M_FATAL, 0, _("TLS host certificate verification failed. Host name \"%s\" did not match presented certificate\n"), - bsock->host()); + Mmsg(bsock->errmsg, _("[%cE0018] TLS host certificate verification failed. Host name \"%s\" did not match presented certificate\n"), component_code, bsock->host()); goto err; } } @@ -165,14 +163,14 @@ err: bool bnet_tls_server(TLS_CONTEXT *ctx, BSOCK * bsock, alist *verify_list, const char *psk_shared_key) { - Jmsg(bsock->jcr(), M_ABORT, 0, _("TLS enabled but not configured.\n")); + Mmsg(bsock->errmsg, _("[%cE0019] TLS enabled but not configured.\n"), component_code); return false; } bool bnet_tls_client(TLS_CONTEXT *ctx, BSOCK * bsock, alist *verify_list, const char *psk_shared_key) { - Jmsg(bsock->jcr(), M_ABORT, 0, _("TLS enable but not configured.\n")); + Mmsg(bsock->errmsg, _("[%cE0019] TLS enabled but not configured.\n"), component_code); return false; } diff --git a/bacula/src/lib/bsockcore.c b/bacula/src/lib/bsockcore.c index 9b5559107..611a3daf9 100644 --- a/bacula/src/lib/bsockcore.c +++ b/bacula/src/lib/bsockcore.c @@ -251,7 +251,7 @@ bool BSOCKCORE::connect(JCR * jcr, int retry_interval, utime_t max_retry_time, if (fatal || (jcr && job_canceled(jcr))) { goto bail_out; } - Dmsg4(50, "Unable to connect to %s on %s:%d. ERR=%s\n", + Dmsg4(50, _("Unable to connect to %s on %s:%d. ERR=%s\n"), name, host, port, be.bstrerror()); if (i < 0) { i = 60 * 5; /* complain again in 5 minutes */ @@ -263,8 +263,8 @@ bool BSOCKCORE::connect(JCR * jcr, int retry_interval, utime_t max_retry_time, bmicrosleep(retry_interval, 0); now = time(NULL); if (begin_time + max_retry_time <= now) { - Qmsg4(jcr, M_WARNING, 0, _("Unable to connect to %s on %s:%d. ERR=%s\n"), - name, host, port, be.bstrerror()); + Mmsg(errmsg, _("[%cE0009] Unable to connect to %s on %s:%d. ERR=%s\n"), + component_code, name, host, port, be.bstrerror()); goto bail_out; } } @@ -339,10 +339,8 @@ bool BSOCKCORE::open(JCR *jcr, const char *name, char *host, char *service, */ if ((addr_list = bnet_host2ipaddrs(host, 0, &errstr)) == NULL) { /* Note errstr is not malloc'ed */ - Qmsg2(jcr, M_ERROR, 0, _("gethostbyname() for host \"%s\" failed: ERR=%s\n"), - host, errstr); - Dmsg2(100, "bnet_host2ipaddrs() for host %s failed: ERR=%s\n", - host, errstr); + MmsgD3(100, errmsg, _("[%cE0012] gethostbyname() for host \"%s\" failed: ERR=%s\n"), + component_code, host, errstr); *fatal = 1; return false; } @@ -380,10 +378,9 @@ bool BSOCKCORE::open(JCR *jcr, const char *name, char *host, char *service, #endif default: *fatal = 1; - Qmsg3(jcr, M_ERROR, 0, _("Socket open error. proto=%d port=%d. ERR=%s\n"), - ipaddr->get_family(), ipaddr->get_port_host_order(), be.bstrerror()); - Pmsg3(300, _("Socket open error. proto=%d port=%d. ERR=%s\n"), - ipaddr->get_family(), ipaddr->get_port_host_order(), be.bstrerror()); + MmsgD4(300, errmsg, _("[%cE0012] Socket open error. proto=%d port=%d. ERR=%s\n"), + component_code, ipaddr->get_family(), ipaddr->get_port_host_order(), + be.bstrerror()); break; } continue; @@ -398,11 +395,11 @@ bool BSOCKCORE::open(JCR *jcr, const char *name, char *host, char *service, berrno be; save_errno = errno; *fatal = 1; - Qmsg2(jcr, M_ERROR, 0, _("Source address bind error. proto=%d. ERR=%s\n"), - src_addr->get_family(), be.bstrerror() ); - Pmsg2(000, _("Source address bind error. proto=%d. ERR=%s\n"), - src_addr->get_family(), be.bstrerror() ); - if (sockfd >= 0) socketClose(sockfd); + MmsgD3(300, errmsg, _("[%cE0013] Source address bind error. proto=%d. ERR=%s\n"), + component_code, src_addr->get_family(), be.bstrerror() ); + if (sockfd >= 0) { + socketClose(sockfd); + } continue; } } @@ -412,16 +409,16 @@ bool BSOCKCORE::open(JCR *jcr, const char *name, char *host, char *service, */ if (setsockopt(sockfd, SOL_SOCKET, SO_KEEPALIVE, (sockopt_val_t)&turnon, sizeof(turnon)) < 0) { berrno be; - Qmsg1(jcr, M_WARNING, 0, _("Cannot set SO_KEEPALIVE on socket: %s\n"), - be.bstrerror()); + Qmsg2(jcr, M_WARNING, 0, _("[%cW0014] Cannot set SO_KEEPALIVE on socket: %s\n"), + component_code, be.bstrerror()); } #if defined(TCP_KEEPIDLE) if (heart_beat) { int opt = heart_beat; if (setsockopt(sockfd, SOL_TCP, TCP_KEEPIDLE, (sockopt_val_t)&opt, sizeof(opt)) < 0) { berrno be; - Qmsg1(jcr, M_WARNING, 0, _("Cannot set TCP_KEEPIDLE on socket: %s\n"), - be.bstrerror()); + Qmsg2(jcr, M_WARNING, 0, _("[%cW0014] Cannot set TCP_KEEPIDLE on socket: %s\n"), + component_code, be.bstrerror()); } } #endif @@ -429,7 +426,9 @@ bool BSOCKCORE::open(JCR *jcr, const char *name, char *host, char *service, /* connect to server */ if (::connect(sockfd, ipaddr->get_sockaddr(), ipaddr->get_sockaddr_len()) < 0) { save_errno = errno; - if (sockfd >= 0) socketClose(sockfd); + if (sockfd >= 0) { + socketClose(sockfd); + } continue; } *fatal = 0; @@ -451,8 +450,8 @@ bool BSOCKCORE::open(JCR *jcr, const char *name, char *host, char *service, */ if (setsockopt(sockfd, SOL_SOCKET, SO_KEEPALIVE, (sockopt_val_t)&turnon, sizeof(turnon)) < 0) { berrno be; - Qmsg1(jcr, M_WARNING, 0, _("Cannot set SO_KEEPALIVE on socket: %s\n"), - be.bstrerror()); + Qmsg2(jcr, M_WARNING, 0, _("[%cW0014] Cannot set SO_KEEPALIVE on socket: %s\n"), + component_code, be.bstrerror()); } fin_init(jcr, sockfd, name, host, port, ipaddr->get_sockaddr()); free_addresses(addr_list); @@ -1058,7 +1057,9 @@ void BSOCKCORE::close() if (!bsock->m_duped) { /* Shutdown tls cleanly. */ if (bsock->tls) { - tls_bsock_shutdown(bsock); + if (tls_bsock_shutdown(bsock) < 0) { + Dmsg1(DT_NETWORK, "%s", bsock->errmsg); + } free_tls_connection(bsock->tls); bsock->tls = NULL; } diff --git a/bacula/src/lib/message.c b/bacula/src/lib/message.c index 71e339975..4b88147e5 100644 --- a/bacula/src/lib/message.c +++ b/bacula/src/lib/message.c @@ -31,6 +31,7 @@ #include "bacula.h" #include "jcr.h" +char component_code = 'X'; sql_insert_log p_sql_log = NULL; sql_insert_event p_sql_event = NULL; @@ -258,6 +259,15 @@ void my_name_is(int argc, char *argv[], const char *name) if (argc>0 && argv && argv[0]) { get_path_and_fname(argv[0], &exepath, &exename); } + if (strcmp(name, "bacula-dir") == 0) { + component_code = 'D'; + } else if (strcmp(name, "bacula-sd") == 0) { + component_code = 'S'; + } else if (strcmp(name, "bacula-fd") == 0) { + component_code = 'F'; + } else if (strcmp(name, "bconsole") == 0) { + component_code = 'C'; + } } void set_sysconfig_path(const char *file) diff --git a/bacula/src/lib/message.h b/bacula/src/lib/message.h index b04e56921..2f6be2257 100644 --- a/bacula/src/lib/message.h +++ b/bacula/src/lib/message.h @@ -205,6 +205,7 @@ class BDB; /* define forward refere typedef bool (*sql_insert_log)(JCR *jcr, JobId_t jobid, utime_t mtime, char *msg); typedef bool (*sql_insert_event)(JCR *jcr, utime_t mtime, const char *line); +extern DLL_IMP_EXP char component_code; extern DLL_IMP_EXP sql_insert_log p_sql_log; extern DLL_IMP_EXP sql_insert_event p_sql_event; diff --git a/bacula/src/lib/openssl.c b/bacula/src/lib/openssl.c index ee035bd8d..e16ff7172 100644 --- a/bacula/src/lib/openssl.c +++ b/bacula/src/lib/openssl.c @@ -55,6 +55,34 @@ void openssl_post_errors(int code, const char *errstring) /* * Post all per-thread openssl errors */ +void openssl_post_errors(POOLMEM **errmsg) +{ + char buf[512]; + unsigned long sslerr; + + /* Pop errors off of the per-thread queue */ + while((sslerr = ERR_get_error()) != 0) { + /* Acquire the human readable string */ + ERR_error_string_n(sslerr, buf, sizeof(buf)); +#if (OPENSSL_VERSION_NUMBER > 0x10101000L) && defined(SSL_R_APPLICATION_DATA_AFTER_CLOSE_NOTIFY) + if (ERR_GET_REASON(sslerr) == SSL_R_APPLICATION_DATA_AFTER_CLOSE_NOTIFY) { + /* Ignore this error that is SSL_shutdown() specific and is new to TLS 1.3 + * error:14094123:SSL routines:ssl3_read_bytes:application data after close notify + * + * This happens when there is still something to read in the socket + * while we are doing the TLS shutdown. This can happens at multiple + * place but the message appears only on the DIR because at that time + * the connection with the DIR is often "terminated" + */ + continue; + } +#endif + pm_strcat(errmsg, buf); + pm_strcat(errmsg, " "); + } + pm_strcat(errmsg, "\n"); +} + void openssl_post_errors(JCR *jcr, int code, const char *errstring) { char buf[512]; @@ -64,7 +92,6 @@ void openssl_post_errors(JCR *jcr, int code, const char *errstring) while((sslerr = ERR_get_error()) != 0) { /* Acquire the human readable string */ ERR_error_string_n(sslerr, buf, sizeof(buf)); - Dmsg3(50, "jcr=%p %s: ERR=%s\n", jcr, errstring, buf); #if (OPENSSL_VERSION_NUMBER > 0x10101000L) && defined(SSL_R_APPLICATION_DATA_AFTER_CLOSE_NOTIFY) if (ERR_GET_REASON(sslerr) == SSL_R_APPLICATION_DATA_AFTER_CLOSE_NOTIFY) { /* Ignore this error that is SSL_shutdown() specific and is new to TLS 1.3 diff --git a/bacula/src/lib/openssl.h b/bacula/src/lib/openssl.h index 790d75787..4b8769729 100644 --- a/bacula/src/lib/openssl.h +++ b/bacula/src/lib/openssl.h @@ -38,6 +38,7 @@ #ifdef HAVE_OPENSSL void openssl_post_errors (int code, const char *errstring); +void openssl_post_errors (POOLMEM **errmsg); void openssl_post_errors (JCR *jcr, int code, const char *errstring); #endif /* HAVE_OPENSSL */ diff --git a/bacula/src/lib/protos.h b/bacula/src/lib/protos.h index c94a7c8d9..da8e07453 100644 --- a/bacula/src/lib/protos.h +++ b/bacula/src/lib/protos.h @@ -404,7 +404,7 @@ int tls_bsock_readn (BSOCK *bsock, char *ptr, int32_t nbyte bool tls_bsock_probe (BSOCKCORE *bsock); #endif /* HAVE_TLS */ bool tls_bsock_connect (BSOCK *bsock); -void tls_bsock_shutdown (BSOCKCORE *bsock); +int tls_bsock_shutdown (BSOCKCORE *bsock); void free_tls_connection (TLS_CONNECTION *tls); bool get_tls_require (TLS_CONTEXT *ctx); bool get_tls_enable (TLS_CONTEXT *ctx); diff --git a/bacula/src/lib/tls.c b/bacula/src/lib/tls.c index bfdcbc77f..ce6d1d2b2 100644 --- a/bacula/src/lib/tls.c +++ b/bacula/src/lib/tls.c @@ -744,7 +744,8 @@ static inline bool openssl_bsock_session_start(BSOCK *bsock, bool server) goto cleanup; case SSL_ERROR_ZERO_RETURN: /* TLS connection was cleanly shut down */ - openssl_post_errors(bsock->get_jcr(), M_FATAL, _("Connect failure")); + Mmsg(bsock->errmsg, _("[%cE0018] TLS Connect failure ERR="), component_code); + openssl_post_errors(&bsock->errmsg); stat = false; goto cleanup; case SSL_ERROR_WANT_READ: @@ -757,7 +758,8 @@ static inline bool openssl_bsock_session_start(BSOCK *bsock, bool server) break; default: /* Socket Error Occurred */ - openssl_post_errors(bsock->get_jcr(), M_FATAL, _("Connect failure")); + Mmsg(bsock->errmsg, _("[%cE0018] TLS Connect failure. Check the passwords. ERR="), component_code); + openssl_post_errors(&bsock->errmsg); stat = false; goto cleanup; } @@ -804,7 +806,7 @@ bool tls_bsock_accept(BSOCK *bsock) /* * Shutdown TLS_CONNECTION instance */ -void tls_bsock_shutdown(BSOCKCORE *bsock) +int tls_bsock_shutdown(BSOCKCORE *bsock) { /* * SSL_shutdown must be called twice to fully complete the process - @@ -837,14 +839,19 @@ void tls_bsock_shutdown(BSOCKCORE *bsock) break; case SSL_ERROR_ZERO_RETURN: /* TLS connection was shut down on us via a TLS protocol-level closure */ - openssl_post_errors(bsock->get_jcr(), M_ERROR, _("TLS shutdown failure.")); + Mmsg(bsock->errmsg, _("[%cW0019] TLS shutdown failure ERR="), component_code); + openssl_post_errors(&bsock->errmsg); + err = -1; break; default: /* Socket Error Occurred */ - openssl_post_errors(bsock->get_jcr(), M_ERROR, _("TLS shutdown failure.")); + Mmsg(bsock->errmsg, _("[%cW0019] TLS shutdown failure ERR="), component_code); + openssl_post_errors(&bsock->errmsg); + err = -1; break; } } + return err; } /* Does all the manual labor for tls_bsock_readn() and tls_bsock_writen() */ diff --git a/bacula/src/stored/dircmd.c b/bacula/src/stored/dircmd.c index 66991ed62..89c258898 100644 --- a/bacula/src/stored/dircmd.c +++ b/bacula/src/stored/dircmd.c @@ -325,7 +325,7 @@ static bool client_cmd(JCR *jcr) /* destroy() OK because cl is local */ cl->destroy(); pm_strcpy(jcr->errmsg, dir->msg); - Jmsg(jcr, M_FATAL, 0, _("Bad client command: %s"), jcr->errmsg); + Jmsg(jcr, M_FATAL, 0, _("[SE0011] Bad client command: %s"), jcr->errmsg); Dmsg1(050, "Bad client command: %s", jcr->errmsg); goto bail_out; } @@ -337,11 +337,10 @@ static bool client_cmd(JCR *jcr) if (!cl->connect(jcr, 10, (int)me->ClientConnectTimeout, me->heartbeat_interval, _("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, jcr->client_port); + Jmsg(jcr, M_FATAL, 0, "%s", cl->errmsg); Dmsg2(100, "Failed to connect to Client daemon: %s:%d\n", jcr->client_addr, jcr->client_port); + cl->destroy(); goto bail_out; }