Fix crash logging non-UTF-8 narrow strings

Development/cmake/NmosCppLibraries.cmake

@@ -985,6 +985,7 @@ set(NMOS_CPP_BST_HEADERS
 
 set(NMOS_CPP_CPPREST_SOURCES
     cpprest/api_router.cpp
+    cpprest/basic_utils.cpp
     cpprest/host_utils.cpp
     cpprest/http_utils.cpp
     cpprest/json_escape.cpp

Development/cpprest/basic_utils.cpp

@@ -0,0 +1,46 @@
+#include "cpprest/basic_utils.h"
+
+#ifdef _WIN32
+#include <climits> // for INT_MAX
+#include <windows.h>
+#endif
+
+namespace utility
+{
+    namespace details
+    {
+        string_t system_narrow_to_us(const std::string& s)
+        {
+            if (s.empty()) return{};
+
+#ifdef _WIN32
+            // narrow platform strings, e.g. std::system_error::what(), are in the ANSI code page,
+            // so try that first, unless the ANSI code page is itself UTF-8, which Windows 10 and
+            // later allow - in that case it would just repeat the decode that has already failed,
+            // and would substitute U+FFFD for each bad byte, losing the very characters at issue
+            // MB_ERR_INVALID_CHARS is deliberately not set, since it would reject the bytes we are
+            // here for, and a best-effort transliteration beats losing the message
+            if (CP_UTF8 != ::GetACP() && s.size() <= (size_t)INT_MAX)
+            {
+                const int size = ::MultiByteToWideChar(CP_ACP, 0, s.data(), (int)s.size(), NULL, 0);
+                if (0 < size)
+                {
+                    // utf16string is std::wstring on Windows, so this is the native conversion target
+                    utf16string ws(size, L'\0');
+                    if (0 < ::MultiByteToWideChar(CP_ACP, 0, s.data(), (int)s.size(), &ws[0], size))
+                    {
+                        return conversions::to_string_t(std::move(ws));
+                    }
+                }
+            }
+            // otherwise fall through to Latin-1
+#endif
+
+            // Latin-1 maps each byte to the code point of the same value, so it cannot fail and
+            // cannot discard anything, which keeps the conversion lossless and reversible
+            // it also agrees with the Windows Western code page (1252) over 0xA0-0xFF,
+            // i.e. for the accented letters, so the common case matches on every platform
+            return conversions::to_string_t(conversions::latin1_to_utf16(s));
+        }
+    }
+}

Development/cpprest/basic_utils.h

@@ -1,6 +1,7 @@
 #ifndef CPPREST_BASIC_UTILS_H
 #define CPPREST_BASIC_UTILS_H
 
+#include <stdexcept> // for std::range_error
 #include "cpprest/asyncrt_utils.h" // for cpprest/details/basic_types.h and utility::conversions
 
 namespace utility
@@ -83,6 +84,40 @@ namespace utility
         return conversions::to_string_t(s);
     }
 
+    namespace details
+    {
+        // Decode a narrow string that is not valid UTF-8, using the system narrow encoding
+        // (the Windows ANSI code page) where there is one, and Latin-1 otherwise
+        // Latin-1 cannot fail, so neither can this; no input is rejected and nothing is discarded
+        string_t system_narrow_to_us(const std::string& s);
+    }
+
+    // Convert a narrow string of uncertain encoding to string_t
+    // s2us requires valid UTF-8 and throws std::range_error otherwise; use this instead at
+    // boundaries where the narrow string comes from the platform rather than from this codebase,
+    // e.g. std::exception::what(), system error messages, or __FILE__, none of which are
+    // guaranteed to be UTF-8 - on Windows they are typically in the ANSI code page
+    // Never throws, and never discards a message
+    inline string_t s2us_lenient(const std::string& s)
+    {
+        if (s.empty()) return{};
+        try
+        {
+            // conversions::to_utf16string is the same decoder that s2us itself uses on a wide
+            // build, on every platform, so this accepts exactly what s2us accepts and the
+            // fallback handles exactly what it would have rejected
+            // note this deliberately discards the result and converts s below, rather than
+            // converting the decoded value, so that whenever s2us would have succeeded this
+            // returns precisely what s2us returns, on a narrow build as well as a wide one
+            (void)conversions::to_utf16string(s);
+        }
+        catch (const std::range_error&)
+        {
+            return details::system_narrow_to_us(s);
+        }
+        return conversions::to_string_t(s);
+    }
+
     template <typename T>
     inline string_t ostringstreamed(const T& value)
     {

Development/cpprest/test/basic_utils_test.cpp

@@ -26,3 +26,87 @@ BST_TEST_CASE(testBase64Url)
         BST_REQUIRE_EQUAL(data, utility::conversions::from_base64url(str));
     }
 }
+
+////////////////////////////////////////////////////////////////////////////////////////////
+BST_TEST_CASE(testS2usLenientValidUtf8)
+{
+    // valid UTF-8 must take the fast path, i.e. give exactly what s2us gives, and round-trip
+    const std::string tests[] = {
+        "",
+        "hello",
+        "\xC3\xBC",             // U+00FC latin small letter u with diaeresis
+        "M\xC3\xBCller",
+        "\xE2\x82\xAC",         // U+20AC euro sign
+        "\xF0\x9F\x8E\xA5"      // U+1F3A5 movie camera
+    };
+
+    for (const auto& test : tests)
+    {
+        BST_REQUIRE_EQUAL(utility::s2us(test), utility::s2us_lenient(test));
+        BST_REQUIRE_EQUAL(test, utility::us2s(utility::s2us_lenient(test)));
+    }
+}
+
+////////////////////////////////////////////////////////////////////////////////////////////
+BST_TEST_CASE(testS2usLenientInvalidUtf8)
+{
+    // these are the byte sequences that make s2us throw std::range_error on a wide build,
+    // e.g. on Windows, where they would escape the async logging worker thread
+    const std::string tests[] = {
+        "\xFC",                 // u with diaeresis in the Windows Western code page, or Latin-1
+        "M\xFCller",
+        "\x80",                 // continuation byte with no leading byte
+        "\xC3",                 // truncated two byte sequence
+        "\xFF\xFE"
+    };
+
+    for (const auto& test : tests)
+    {
+        // to_utf16string is the strict decoder that s2us uses on a wide build, on every
+        // platform, so this asserts the Windows failure mode without needing a wide build
+        BST_REQUIRE_THROW(utility::conversions::to_utf16string(test), std::range_error);
+
+        utility::string_t converted;
+        BST_REQUIRE_NO_THROW(converted = utility::s2us_lenient(test));
+
+        // the message must be preserved, not dropped
+        BST_REQUIRE(!converted.empty());
+
+        // and whatever it decoded to must be well-formed, so that it can go into a JSON
+        // log event and be converted back without throwing
+        BST_REQUIRE_NO_THROW(utility::conversions::to_utf16string(utility::us2s(converted)));
+    }
+
+    // empty input is not an error
+    BST_REQUIRE(utility::s2us_lenient("").empty());
+
+    // note that the decoder is not a strict UTF-8 validator - it accepts UTF-16 surrogates,
+    // code points above U+10FFFF and overlong encodings - so these do not take the fallback
+    // that is deliberate: s2us_lenient differs from s2us only where s2us would have thrown,
+    // and passes everything else through unchanged
+    const std::string tolerated[] = {
+        "\xED\xA0\x80",         // a UTF-16 surrogate
+        "\xF5\x80\x80\x80",     // above U+10FFFF
+        "\xC0\xAF"              // overlong encoding of '/'
+    };
+
+    for (const auto& test : tolerated)
+    {
+        BST_REQUIRE_NO_THROW(utility::conversions::to_utf16string(test));
+        BST_REQUIRE_EQUAL(utility::s2us(test), utility::s2us_lenient(test));
+    }
+}
+
+////////////////////////////////////////////////////////////////////////////////////////////
+BST_TEST_CASE(testS2usLenientLatin1Fallback)
+{
+#ifndef _WIN32
+    // where there is no ANSI code page, the fallback is Latin-1, which maps each byte to the
+    // code point of the same value; the Windows Western code page (1252) agrees over 0xA0-0xFF,
+    // so the accented letters come out the same on either
+    // this is not asserted on Windows, where the ANSI code page is a machine setting and a
+    // double byte code page, e.g. 932, treats 0xFC as a leading byte instead
+    BST_REQUIRE_EQUAL(utility::s2us("\xC3\xBC"), utility::s2us_lenient("\xFC"));
+    BST_REQUIRE_EQUAL(utility::s2us("M\xC3\xBCller"), utility::s2us_lenient("M\xFCller"));
+#endif
+}

Development/nmos/api_utils.cpp

@@ -616,7 +616,8 @@ namespace nmos
     // set up a standard NMOS error response, using the default reason phrase and the specified debug information
     void set_error_reply(web::http::http_response& res, web::http::status_code code, const std::exception& debug)
     {
-        set_error_reply(res, code, {}, utility::s2us(debug.what()));
+        // what() is a narrow platform string with no UTF-8 guarantee
+        set_error_reply(res, code, {}, utility::s2us_lenient(debug.what()));
     }
 
     // add handler to set appropriate response headers, and error response body if indicated - call this only after adding all others!
@@ -863,7 +864,8 @@ namespace nmos
                 if (error.value != nmos::experimental::authorization_error::without_authentication)
                 {
                     utility::string_t error_string = { (error.value == nmos::experimental::authorization_error::insufficient_scope) ? web::http::oauth2::experimental::resource_server_errors::insufficient_scope.name : web::http::oauth2::experimental::resource_server_errors::invalid_token.name };
-                    error_description = utility::s2us(error.message);
+                    // the message originates from std::exception::what(), so may not be UTF-8
+                    error_description = utility::s2us_lenient(error.message);
                     auth_params += U(",error=") + error_string + U(",error_description=") + error_description;
                 }
 
@@ -880,7 +882,7 @@ namespace nmos
                     res.headers().add(web::http::header_names::retry_after, retry_after);
                 }
 
-                nmos::set_error_reply(res, status_code, utility::s2us(error.message));
+                nmos::set_error_reply(res, status_code, utility::s2us_lenient(error.message));
             }
         }
     }

Development/nmos/authorization_redirect_api.cpp

@@ -44,7 +44,8 @@ namespace nmos
 
             inline authorization_flow_response make_authorization_flow_error_response(web::http::status_code code, const std::exception& debug)
             {
-                return make_authorization_flow_error_response(code, {}, utility::s2us(debug.what()));
+                // what() is a narrow platform string with no UTF-8 guarantee
+                return make_authorization_flow_error_response(code, {}, utility::s2us_lenient(debug.what()));
             }
 
             void process_error_response(const web::uri& redirected_uri, const utility::string_t& response_type, const utility::string_t& state)

Development/nmos/channelmapping_api.cpp

@@ -84,7 +84,8 @@ namespace nmos
 
         inline channelmapping_activation_post_response make_channelmapping_activation_post_error_response(web::http::status_code code, const std::exception& debug)
         {
-            return make_channelmapping_activation_post_error_response(code, {}, utility::s2us(debug.what()));
+            // what() is a narrow platform string with no UTF-8 guarantee
+            return make_channelmapping_activation_post_error_response(code, {}, utility::s2us_lenient(debug.what()));
         }
 
         inline utility::string_t make_channelmapping_input_error(const nmos::channelmapping_id& input_id)

Development/nmos/connection_api.cpp

@@ -447,7 +447,8 @@ namespace nmos
 
         inline connection_resource_patch_response make_connection_resource_patch_error_response(web::http::status_code code, const std::exception& debug)
         {
-            return make_connection_resource_patch_error_response(code, {}, utility::s2us(debug.what()));
+            // what() is a narrow platform string with no UTF-8 guarantee
+            return make_connection_resource_patch_error_response(code, {}, utility::s2us_lenient(debug.what()));
         }
 
         // Basic theory of implementation of PATCH /staged

Development/nmos/control_protocol_ws_api.cpp

@@ -369,7 +369,7 @@ namespace nmos
                             resources.modify(grain, [&](nmos::resource& grain)
                             {
                                 web::json::push_back(nmos::fields::message_grain_data(grain.data),
-                                    nc::make_error_message({ nc_method_status::bad_command_format }, utility::s2us(e.what())));
+                                    nc::make_error_message({ nc_method_status::bad_command_format }, utility::s2us_lenient(e.what())));
 
                                 grain.updated = strictly_increasing_update(resources);
                             });
@@ -381,7 +381,7 @@ namespace nmos
                             resources.modify(grain, [&](nmos::resource& grain)
                             {
                                 web::json::push_back(nmos::fields::message_grain_data(grain.data),
-                                    nc::make_error_message({ nc_method_status::bad_command_format }, utility::s2us(std::string("Unexpected exception while handing control protocol command : ") + e.what())));
+                                    nc::make_error_message({ nc_method_status::bad_command_format }, utility::s2us_lenient(std::string("Unexpected exception while handing control protocol command : ") + e.what())));
 
                                 grain.updated = strictly_increasing_update(resources);
                             });

Development/nmos/log_gate.h

@@ -133,19 +133,38 @@ namespace nmos
             {
                 auto lock = model.write_lock();
 
-                auto categories = nmos::get_categories_stash(message.stream());
+                // this runs on the async logging worker thread, and slog's message_service::run only
+                // catches its own stopped_exception, so anything else escaping here would propagate out
+                // of the thread function and terminate the process - a last resort, since a failure to
+                // log must never take down the application; the encoding boundaries that could
+                // realistically throw are handled in json_from_message with utility::s2us_lenient
+                try
+                {
+                    auto categories = nmos::get_categories_stash(message.stream());
+
+                    if (pertinent(message.level()) && pertinent(categories))
+                    {
+                        error_log << details::error_log_format(message);
+                    }
+
+                    if (categories.end() != boost::range::find(categories, nmos::categories::access))
+                    {
+                        access_log << nmos::common_log_format(message);
+                    }
 
-                if (pertinent(message.level()) && pertinent(categories))
+                    nmos::experimental::insert_log_event(model.events, message, generate_id(), nmos::experimental::fields::logging_limit(model.settings));
+                }
+                catch (const std::exception& e)
                 {
-                    error_log << details::error_log_format(message);
+                    // report on the error log directly rather than via the gate, which would re-enter here
+                    // and guard that too, since the error log is itself a plausible source of the error,
+                    // and throwing from a handler here would defeat the point of catching at all
+                    try { error_log << "Error while logging: " << e.what() << std::endl; } catch (...) {}
                 }
-
-                if (categories.end() != boost::range::find(categories, nmos::categories::access))
+                catch (...)
                 {
-                    access_log << nmos::common_log_format(message);
+                    try { error_log << "Unexpected error while logging" << std::endl; } catch (...) {}
                 }
-
-                nmos::experimental::insert_log_event(model.events, message, generate_id(), nmos::experimental::fields::logging_limit(model.settings));
             }
 
             mutable slog::async_log_service<service_function> async_service;

Development/nmos/log_model.cpp

@@ -27,11 +27,15 @@ namespace nmos
                     // hmm, could be good to provide a log/settings option to redact thread_id and/or source_location?
                     { U("thread_id"), ostringstreamed(message.thread_id()) },
                     { U("source_location"), web::json::value_of({
-                        { U("file"), utility::s2us(message.file()) },
+                        // __FILE__ and __FUNCTION__ are narrow platform strings, so may not be UTF-8
+                        { U("file"), utility::s2us_lenient(message.file()) },
                         { U("line"), message.line() },
-                        { U("function"), utility::s2us(message.function()) }
+                        { U("function"), utility::s2us_lenient(message.function()) }
                     }, true) },
-                    { U("message"), utility::s2us(message.str()) },
+                    // log messages may contain arbitrary narrow text, e.g. from std::exception::what(),
+                    // which carries no UTF-8 guarantee; s2us would throw std::range_error on such bytes,
+                    // and this runs on the async logging worker thread where that would terminate the app
+                    { U("message"), utility::s2us_lenient(message.str()) },
                     { U("id"), id }
                 }, true);
 
@@ -43,7 +47,7 @@ namespace nmos
                 const auto route_parameters = nmos::get_route_parameters_stash(message.stream());
                 if (!route_parameters.empty()) json_message[U("route_parameters")] = web::json::value_from_fields(route_parameters);
                 const auto categories = nmos::get_categories_stash(message.stream());
-                if (!categories.empty()) json_message[U("tags")][U("category")] = web::json::value_from_elements(categories | boost::adaptors::transformed(utility::s2us));
+                if (!categories.empty()) json_message[U("tags")][U("category")] = web::json::value_from_elements(categories | boost::adaptors::transformed(utility::s2us_lenient));
 
                 return json_message;
             }