[#4282] Added logs error responses

diff --git a/src/hooks/dhcp/radius/radius_messages.cc b/src/hooks/dhcp/radius/radius_messages.cc
index e89e9d9dc0bb9598f394698ddaae49fb2e4ed9c5..2cc22567e531abb7877827d8f8c0e4e670b27361 100644 (file)
--- a/src/hooks/dhcp/radius/radius_messages.cc
+++ b/src/hooks/dhcp/radius/radius_messages.cc
@@ -29,6 +29,7 @@ extern const isc::log::MessageID RADIUS_ACCOUNTING_ERROR = "RADIUS_ACCOUNTING_ER
 extern const isc::log::MessageID RADIUS_ACCOUNTING_HISTORY_UPDATE_FAILED = "RADIUS_ACCOUNTING_HISTORY_UPDATE_FAILED";
 extern const isc::log::MessageID RADIUS_ACCOUNTING_NO_HISTORY = "RADIUS_ACCOUNTING_NO_HISTORY";
 extern const isc::log::MessageID RADIUS_ACCOUNTING_STATUS = "RADIUS_ACCOUNTING_STATUS";
+extern const isc::log::MessageID RADIUS_ACCOUNTING_STATUS_ERROR = "RADIUS_ACCOUNTING_STATUS_ERROR";
 extern const isc::log::MessageID RADIUS_ACCOUNTING_STATUS_FAILED = "RADIUS_ACCOUNTING_STATUS_FAILED";
 extern const isc::log::MessageID RADIUS_ACCOUNTING_STATUS_SUCCEED = "RADIUS_ACCOUNTING_STATUS_SUCCEED";
 extern const isc::log::MessageID RADIUS_ACCOUNTING_SYNC = "RADIUS_ACCOUNTING_SYNC";
@@ -39,6 +40,7 @@ extern const isc::log::MessageID RADIUS_AUTHENTICATION_ASYNC_ACCEPTED = "RADIUS_
 extern const isc::log::MessageID RADIUS_AUTHENTICATION_ASYNC_FAILED = "RADIUS_AUTHENTICATION_ASYNC_FAILED";
 extern const isc::log::MessageID RADIUS_AUTHENTICATION_ASYNC_REJECTED = "RADIUS_AUTHENTICATION_ASYNC_REJECTED";
 extern const isc::log::MessageID RADIUS_AUTHENTICATION_STATUS = "RADIUS_AUTHENTICATION_STATUS";
+extern const isc::log::MessageID RADIUS_AUTHENTICATION_STATUS_ERROR = "RADIUS_AUTHENTICATION_STATUS_ERROR";
 extern const isc::log::MessageID RADIUS_AUTHENTICATION_STATUS_FAILED = "RADIUS_AUTHENTICATION_STATUS_FAILED";
 extern const isc::log::MessageID RADIUS_AUTHENTICATION_STATUS_SUCCEED = "RADIUS_AUTHENTICATION_STATUS_SUCCEED";
 extern const isc::log::MessageID RADIUS_AUTHENTICATION_SYNC = "RADIUS_AUTHENTICATION_SYNC";
@@ -124,6 +126,7 @@ const char* values[] = {
     "RADIUS_ACCOUNTING_HISTORY_UPDATE_FAILED", "failed to insert a record for %1 in the history container",
     "RADIUS_ACCOUNTING_NO_HISTORY", "failed to find the date the lease for %1 was created",
     "RADIUS_ACCOUNTING_STATUS", "send Status-Server with %1",
+    "RADIUS_ACCOUNTING_STATUS_ERROR", "received error response to Status-Server: %1 (%2) with %3",
     "RADIUS_ACCOUNTING_STATUS_FAILED", "Status-Server failed: return code %1 (%2)",
     "RADIUS_ACCOUNTING_STATUS_SUCCEED", "received valid response to Status-Server",
     "RADIUS_ACCOUNTING_SYNC", "Synchronous send Accounting-Request for NAS port %1 with %2",
@@ -134,6 +137,7 @@ const char* values[] = {
     "RADIUS_AUTHENTICATION_ASYNC_FAILED", "Access-Request failed: return code %1 (%2)",
     "RADIUS_AUTHENTICATION_ASYNC_REJECTED", "received valid Access-Reject with %1",
     "RADIUS_AUTHENTICATION_STATUS", "send Status-Server with %1",
+    "RADIUS_AUTHENTICATION_STATUS_ERROR", "received error response to Status-Server: %1 (%2) with %3",
     "RADIUS_AUTHENTICATION_STATUS_FAILED", "Status-Server failed: return code %1 (%2)",
     "RADIUS_AUTHENTICATION_STATUS_SUCCEED", "received valid response to Status-Server",
     "RADIUS_AUTHENTICATION_SYNC", "send Access-Request for NAS port %1 with %2",

diff --git a/src/hooks/dhcp/radius/radius_messages.h b/src/hooks/dhcp/radius/radius_messages.h
index c520fc2b61ef11606c8e0d894e35aecf3f4335e1..98c66422a37e81949f02c3c855585545c3bb25aa 100644 (file)
--- a/src/hooks/dhcp/radius/radius_messages.h
+++ b/src/hooks/dhcp/radius/radius_messages.h
@@ -30,6 +30,7 @@ extern const isc::log::MessageID RADIUS_ACCOUNTING_ERROR;
 extern const isc::log::MessageID RADIUS_ACCOUNTING_HISTORY_UPDATE_FAILED;
 extern const isc::log::MessageID RADIUS_ACCOUNTING_NO_HISTORY;
 extern const isc::log::MessageID RADIUS_ACCOUNTING_STATUS;
+extern const isc::log::MessageID RADIUS_ACCOUNTING_STATUS_ERROR;
 extern const isc::log::MessageID RADIUS_ACCOUNTING_STATUS_FAILED;
 extern const isc::log::MessageID RADIUS_ACCOUNTING_STATUS_SUCCEED;
 extern const isc::log::MessageID RADIUS_ACCOUNTING_SYNC;
@@ -40,6 +41,7 @@ extern const isc::log::MessageID RADIUS_AUTHENTICATION_ASYNC_ACCEPTED;
 extern const isc::log::MessageID RADIUS_AUTHENTICATION_ASYNC_FAILED;
 extern const isc::log::MessageID RADIUS_AUTHENTICATION_ASYNC_REJECTED;
 extern const isc::log::MessageID RADIUS_AUTHENTICATION_STATUS;
+extern const isc::log::MessageID RADIUS_AUTHENTICATION_STATUS_ERROR;
 extern const isc::log::MessageID RADIUS_AUTHENTICATION_STATUS_FAILED;
 extern const isc::log::MessageID RADIUS_AUTHENTICATION_STATUS_SUCCEED;
 extern const isc::log::MessageID RADIUS_AUTHENTICATION_SYNC;

diff --git a/src/hooks/dhcp/radius/radius_messages.mes b/src/hooks/dhcp/radius/radius_messages.mes
index d99c3442d58e6037cb2e7f69e14a9ff23d86bf95..42874cb52955fcd7d6a7c7d4af01e83e0f9e3d44 100644 (file)
--- a/src/hooks/dhcp/radius/radius_messages.mes
+++ b/src/hooks/dhcp/radius/radius_messages.mes
@@ -110,6 +110,11 @@ Logged at debug log level 40.
 This debug message is issued when starting to send a Status-Server message
 to accounting servers. The message attributes are logged.
 
+% RADIUS_ACCOUNTING_STATUS_ERROR received error response to Status-Server: %1 (%2) with %3
+This error message indicates that a valid response to Status-Server message
+was received from accounting servers but with an unexpected code or
+an Error-Cause attribute. The response details are logged.
+
 % RADIUS_ACCOUNTING_STATUS_FAILED Status-Server failed: return code %1 (%2)
 Logged at debug log level 40.
 This debug message is issued when no valid response to Status-Server message
@@ -161,6 +166,11 @@ Logged at debug log level 40.
 This debug message is issued when starting to send a Status-Server message
 to access servers. The message attributes are logged.
 
+% RADIUS_AUTHENTICATION_STATUS_ERROR received error response to Status-Server: %1 (%2) with %3
+This error message indicates that a valid response to Status-Server message
+was received from access servers but with an unexpected code or an
+Error-Cause attribute. The response details are logged.
+
 % RADIUS_AUTHENTICATION_STATUS_FAILED Status-Server failed: return code %1 (%2)
 Logged at debug log level 40.
 This debug message is issued when no valid response to Status-Server message

diff --git a/src/hooks/dhcp/radius/radius_status.cc b/src/hooks/dhcp/radius/radius_status.cc
index fa295948379d7158197e52a377f91822e3799e33..adaa1c6c394fe4821fe329d258cd6917c599f59d 100644 (file)
--- a/src/hooks/dhcp/radius/radius_status.cc
+++ b/src/hooks/dhcp/radius/radius_status.cc
@@ -65,6 +65,21 @@ RadiusAuthStatus::invokeCallback(const CallbackAcct& callback,
         LOG_DEBUG(radius_logger, RADIUS_DBG_TRACE,
                   RADIUS_AUTHENTICATION_STATUS_SUCCEED);
         RadiusImpl::instance().auth_->setIdleTimer();
+
+        MessagePtr response = exchange->getResponse();
+        AttributesPtr resp_attrs;
+        uint8_t code = 0;
+        if (response) {
+            resp_attrs = response->getAttributes();
+            code = response->getCode();
+        }
+        if (((code != 0) && (code != PW_ACCESS_ACCEPT)) ||
+            (resp_attrs && (resp_attrs->count(PW_ERROR_CAUSE) > 0))) {
+            LOG_ERROR(radius_logger, RADIUS_AUTHENTICATION_STATUS_ERROR)
+                .arg(msgCodeToText(code))
+                .arg(static_cast<unsigned>(code))
+                .arg(resp_attrs ? resp_attrs->toText() : "no attributes");
+        }
     } else {
         LOG_DEBUG(radius_logger, RADIUS_DBG_TRACE,
                   RADIUS_AUTHENTICATION_STATUS_FAILED)
@@ -126,6 +141,21 @@ RadiusAcctStatus::invokeCallback(const CallbackAcct& callback,
         LOG_DEBUG(radius_logger, RADIUS_DBG_TRACE,
                   RADIUS_ACCOUNTING_STATUS_SUCCEED);
         RadiusImpl::instance().acct_->setIdleTimer();
+
+        MessagePtr response = exchange->getResponse();
+        AttributesPtr resp_attrs;
+        uint8_t code = 0;
+        if (response) {
+            resp_attrs = response->getAttributes();
+            code = response->getCode();
+        }
+        if (((code != 0) && (code != PW_ACCOUNTING_RESPONSE)) ||
+            (resp_attrs && (resp_attrs->count(PW_ERROR_CAUSE) > 0))) {
+            LOG_ERROR(radius_logger, RADIUS_ACCOUNTING_STATUS_ERROR)
+                .arg(msgCodeToText(code))
+                .arg(static_cast<unsigned>(code))
+                .arg(resp_attrs ? resp_attrs->toText() : "no attributes");
+        }
     } else {
         LOG_DEBUG(radius_logger, RADIUS_DBG_TRACE,
                   RADIUS_ACCOUNTING_STATUS_FAILED)

diff --git a/src/hooks/dhcp/radius/tests/status_unittests.cc b/src/hooks/dhcp/radius/tests/status_unittests.cc
index 789ed8721cdfce80959e1e75469f5e773954005c..d2351459e2b999a4f4e28d335115e746ccfa647c 100644 (file)
--- a/src/hooks/dhcp/radius/tests/status_unittests.cc
+++ b/src/hooks/dhcp/radius/tests/status_unittests.cc
@@ -751,6 +751,99 @@ TEST_F(StatusTest, response) {
     EXPECT_EQ(OK_RC, result_);
 }
 
+/// Verify what happens with error Accounting-Response response.
+/// Should log a RADIUS_ACCOUNTING_STATUS_ERROR with
+/// Accounting-Response (5) with Error-Cause=Unsupported-Extension
+TEST_F(StatusTest, errorResponse) {
+    // Use CONFIGS[0].
+    ElementPtr json;
+    ASSERT_NO_THROW(json = Element::fromJSON(CONFIGS[0]));
+    ASSERT_NO_THROW(impl_.init(json));
+
+    // Build request parameters.
+    which_ = "accounting";
+
+    // Open server socket.
+    open(SERVER_ACCT_PORT);
+
+    // Push a receiver on it.
+    boost::asio::ip::udp::endpoint client;
+    size_t size = 0;
+    Callback receive_callback(receive_error_code_, size, received_);
+    server_socket_.async_receive_from(
+        boost::asio::buffer(&receive_buffer_[0], receive_buffer_.size()),
+        client, receive_callback);
+
+    // Launch request handler i.e. the client code to test.
+    run();
+
+    // Start timer for 1.5s timeout.
+    start(1500);
+
+    // Busy loop.
+    while (!received_ && !timeout_) {
+        poll();
+    }
+
+    ASSERT_TRUE(received_);
+    ASSERT_FALSE(timeout_);
+
+    // Sanity checks on the request.
+    receive_buffer_.resize(size);
+    ASSERT_LE(20, size);
+
+    // Build the response.
+    size = AUTH_HDR_LEN + 2 + 4;               // header + Error-Cause attribute.
+    send_buffer_.resize(size);
+    send_buffer_[0] = PW_ACCOUNTING_RESPONSE;  // Access-Accept.
+    send_buffer_[1] = receive_buffer_[1];      // Copy id.
+    send_buffer_[2] = size >> 8;               // Length.
+    send_buffer_[3] = size & 0xff;
+    // Copy the authenticator.
+    memmove(&send_buffer_[4], &receive_buffer_[4], AUTH_VECTOR_LEN);
+    // Error-Cause attribute.
+    send_buffer_[AUTH_HDR_LEN] = 0x65;         // Error-Cause (101)
+    send_buffer_[AUTH_HDR_LEN + 1] = 0x06;     // Length.
+    send_buffer_[AUTH_HDR_LEN + 2] = 0x00;
+    send_buffer_[AUTH_HDR_LEN + 3] = 0x00;
+    send_buffer_[AUTH_HDR_LEN + 4] = 0x01;
+    send_buffer_[AUTH_HDR_LEN + 5] = 0x96;     // Unsupported Extension (406).
+
+    // Compute the authenticator.
+    vector<unsigned char> auth_input(size + 3);
+    memmove(&auth_input[0], &send_buffer_[0], size);
+    auth_input[size] = 'b';
+    auth_input[size + 1] = 'a';
+    auth_input[size + 2] = 'r';
+    OutputBuffer auth_output(AUTH_VECTOR_LEN);
+    digest(&auth_input[0], size + 3, isc::cryptolink::MD5,
+           auth_output, AUTH_VECTOR_LEN);
+    memmove(&send_buffer_[4], auth_output.getData(), AUTH_VECTOR_LEN);
+
+    // Push a sender on the socket.
+    size_t sent_size = 0;
+    Callback send_callback(send_error_code_, sent_size, sent_);
+    server_socket_.async_send_to(boost::asio::buffer(&send_buffer_[0], size),
+                                 client, send_callback);
+
+    // Second busy loop.
+    while ((!sent_ || !finished_) && !timeout_) {
+        poll();
+    }
+
+    EXPECT_TRUE(finished_);
+    EXPECT_TRUE(sent_);
+    EXPECT_FALSE(timeout_);
+    EXPECT_EQ(size, sent_size);
+
+    // Done.
+    stop();
+    service_->stopWork();
+
+    // Check result.
+    EXPECT_EQ(OK_RC, result_);
+}
+
 /// Verify what happens with bad Access-Accept response.
 TEST_F(StatusTest, badAccept) {
     // Use CONFIGS[0].