Improve unit conversion error logging (NGWPC-7604)

extern/test_bmi_c/src/bmi_test_bmi_c.c

@@ -21,7 +21,7 @@ static const char *output_var_locations[OUTPUT_VAR_NAME_COUNT] = { "node", "node
 // Don't forget to update Get_value/Get_value_at_indices (and setter) implementation if these are adjusted
 static const char *input_var_names[INPUT_VAR_NAME_COUNT] = { "INPUT_VAR_1", "INPUT_VAR_2" };
 static const char *input_var_types[INPUT_VAR_NAME_COUNT] = { "double", "double" };
-static const char *input_var_units[INPUT_VAR_NAME_COUNT] = {  "m", "m/s" };
+static const char *input_var_units[INPUT_VAR_NAME_COUNT] = {  "m", "Pa" };
 static const int input_var_item_count[INPUT_VAR_NAME_COUNT] = { 1, 1 };
 static const char *input_var_grids[INPUT_VAR_NAME_COUNT] = { 0, 0 };
 static const char *input_var_locations[INPUT_VAR_NAME_COUNT] = { "node", "node" };

extern/test_bmi_cpp/include/test_bmi_cpp.hpp

@@ -172,8 +172,8 @@ class TestBmiCpp : public bmi::Bmi {
         std::vector<std::string> input_var_types = { "double", "double" };
         std::vector<std::string> output_var_types = { "double", "double" };
         std::vector<std::string> model_var_types = {};
-        std::vector<std::string> input_var_units = { "m", "m" };
-        std::vector<std::string> output_var_units = { "m", "m/s", "m", "m" };
+        std::vector<std::string> input_var_units = { "mm/s", "Pa" };
+        std::vector<std::string> output_var_units = { "mm/s", "m/s", "m", "m" };
         std::vector<std::string> model_var_units = {};
         std::vector<std::string> input_var_locations = { "node", "node" };
         std::vector<std::string> output_var_locations = { "node", "node" };

extern/test_bmi_fortran/src/bmi_test_bmi_fortran.f90

@@ -123,10 +123,10 @@ module bmitestbmi
   integer :: input_grid(4) = [0, 0, 0, 1]
 
   character (len=BMI_MAX_UNITS_NAME) :: &
-    output_units(6) = [character(BMI_MAX_UNITS_NAME):: 'm', 'm', 's', 'm', 'm', 'm']
+    output_units(6) = [character(BMI_MAX_UNITS_NAME):: 'mm s^-1', 'm', 's', 'm', 'm', 'm']
 
   character (len=BMI_MAX_UNITS_NAME) :: &
-    input_units(4) = [character(BMI_MAX_UNITS_NAME):: 'm', 'm', 's', 'm']
+    input_units(4) = [character(BMI_MAX_UNITS_NAME):: 'mm s^-1', 'Pa', 'K', 'mm s^-1']
 
   character (len=BMI_MAX_LOCATION_NAME) :: &
     output_location(6) = [character(BMI_MAX_LOCATION_NAME):: 'node', 'node', 'node', 'node', 'node', 'node']

extern/test_bmi_py/bmi_model.py

@@ -73,12 +73,12 @@ def __init__(self):
     #     since the input variable names could come from any forcing...
     #------------------------------------------------------
     #_var_name_map_long_first = {
-    _var_name_units_map = {'INPUT_VAR_1':['INPUT_VAR_1','-'],
-                           'INPUT_VAR_2':['INPUT_VAR_2','-'],
-                           'OUTPUT_VAR_1':['OUTPUT_VAR_1','-'],
-                           'OUTPUT_VAR_2':['OUTPUT_VAR_2','-'],
+    _var_name_units_map = {'INPUT_VAR_1':['INPUT_VAR_1','mm/s'],
+                           'INPUT_VAR_2':['INPUT_VAR_2','Pa'],
+                           'OUTPUT_VAR_1':['OUTPUT_VAR_1','m'],
+                           'OUTPUT_VAR_2':['OUTPUT_VAR_2','mm/s'],
                            'OUTPUT_VAR_3':['OUTPUT_VAR_3','-'],
-                           'GRID_VAR_1':['OUTPUT_VAR_1','-'],
+                           'GRID_VAR_1':['OUTPUT_VAR_1','mm/s'],
                            'GRID_VAR_2':['GRID_VAR_2','-'],
                             }
 
@@ -609,4 +609,4 @@ def _parse_config(self, cfg):
                 pass
 
         # Add more config parsing if necessary
-        return cfg
+        return cfg

include/forcing/CsvPerFeatureForcingProvider.hpp

@@ -170,13 +170,13 @@ class CsvPerFeatureForcingProvider : public data_access::GenericDataProvider
         try {
             return UnitsHelper::get_converted_value(available_forcings_units[output_name], value, output_units);
         }
-        catch (const std::runtime_error& e){
-            #ifndef UDUNITS_QUIET
-            std::stringstream ss;
-            ss <<"WARN: Unit conversion unsuccessful - Returning unconverted value! (\""<<e.what()<<"\")"<<std::endl;
-            LOG(ss.str(), LogLevel::SEVERE); ss.str("");
-            #endif
-            return value;
+        catch (const std::runtime_error& e) {
+            data_access::unit_conversion_exception uce(e.what());
+            uce.provider_model_name = "CsvPerFeatureProvider " + std::to_string(catchment_id);
+            uce.provider_bmi_var_name = output_name;
+            uce.provider_units = available_forcings_units[output_name];
+            uce.unconverted_values.push_back(value);
+            throw uce;
         }
     }
 
@@ -341,12 +341,16 @@ class CsvPerFeatureForcingProvider : public data_access::GenericDataProvider
                     }
                 }
 
+                LOG("CsvProvider has variable '" + var_name + "' with units '" + units + "'", LogLevel::DEBUG);
+
                 auto wkf = data_access::WellKnownFields.find(var_name);
                 if(wkf != data_access::WellKnownFields.end()){
                     units = units.empty() ? std::get<1>(wkf->second) : units;
+                    auto wkf_name = std::get<0>(wkf->second);
+                    LOG("CsvProvider has well-known name '" + wkf_name + "' for variable '" + var_name + "' with units '" + units + "'", LogLevel::DEBUG);
                     available_forcings.push_back(var_name); // Allow lookup by non-canonical name
                     available_forcings_units[var_name] = units; // Allow lookup of units by non-canonical name
-                    var_name = std::get<0>(wkf->second); // Use the CSDMS name from here on
+                    var_name = wkf_name; // Use the CSDMS name from here on
                 }
 
                 forcing_vectors[var_name] = {};

include/forcing/DataProvider.hpp

@@ -3,6 +3,8 @@
 
 #include <string>
 #include <vector>
+#include <set>
+#include <tuple>
 #include <boost/core/span.hpp>
 
 namespace data_access
@@ -101,6 +103,33 @@ namespace data_access
         private:
     };
 
+    struct unit_error_log_key {
+        std::string requester_name;
+        std::string requester_variable;
+        std::string provider_name;
+        std::string provider_variable;
+        std::string failure_message;
+
+        bool operator<(unit_error_log_key const& rhs) const {
+            return std::tie(requester_name, requester_variable, provider_name, provider_variable, failure_message)
+                 < std::tie(rhs.requester_name, rhs.requester_variable, rhs.provider_name, rhs.provider_variable, rhs.failure_message);
+        }
+
+        bool operator==(unit_error_log_key const& rhs) const {
+            return std::tie(requester_name, requester_variable, provider_name, provider_variable, failure_message)
+                == std::tie(rhs.requester_name, rhs.requester_variable, rhs.provider_name, rhs.provider_variable, rhs.failure_message);
+        }
+    };
+
+    extern std::set<unit_error_log_key> unit_errors_reported;
+
+    struct unit_conversion_exception : public std::runtime_error {
+        unit_conversion_exception(std::string message) : std::runtime_error(message) {}
+        std::string provider_model_name;
+        std::string provider_bmi_var_name;
+        std::string provider_units;
+        std::vector<double> unconverted_values;
+    };
 }
 
 

include/realizations/catchment/Bmi_Module_Formulation.hpp

@@ -486,8 +486,6 @@ namespace realization {
         /** A configured mapping of BMI model variable names to standard names for use inside the framework. */
         std::map<std::string, std::string> bmi_var_names_map;
         bool model_initialized = false;
-        bool unitGetValueErrLogged = false;
-        bool unitGetValuesErrLogged = false;
 
         std::vector<std::string> OPTIONAL_PARAMETERS = {
                 BMI_REALIZATION_CFG_PARAM_OPT__USES_FORCINGS

include/realizations/catchment/Bmi_Multi_Formulation.hpp

@@ -583,6 +583,15 @@ namespace realization {
                 //TODO: After merge PR#405, try re-adding support for index
                 return nested_module->get_value(selector);
             }
+            catch (data_access::unit_conversion_exception &uce) {
+                // We asked for it as a dimensionless quantity, "1", just above
+                static bool no_conversion_message_logged = false;
+                if (!no_conversion_message_logged) {
+                    no_conversion_message_logged = true;
+                    LOG("Emitting output variables from Bmi_Multi_Formulation without unit conversion - see NGWPC-7604", LogLevel::WARNING);
+                }
+                return uce.unconverted_values[0];
+            }
             // If there was any problem with the cast and extraction of the value, throw runtime error
             catch (std::exception &e) {
                 std::string throw_msg; throw_msg.assign("Multi BMI formulation can't use associated data provider as a nested module"

src/forcing/NetCDFPerFeatureDataProvider.cpp

@@ -419,14 +419,12 @@ double NetCDFPerFeatureDataProvider::get_value(const CatchmentAggrDataSelector&
     }
     catch (const std::runtime_error& e)
     {
-        //minor change to aid debugging (log_stream is an output log stream for messages from the underlying library, therefore logging to both EWTS and library logger) 
-        netcdf_ss << "NetCDFPerFeatureDataProvider: get_converted_value Unit conversion unsuccessful - Returning unconverted value! (" << e.what() << ")" << std::endl;
-        log_stream << netcdf_ss.str();
-        LOG(netcdf_ss.str(), LogLevel::WARNING); netcdf_ss.str("");
-        netcdf_ss << "=== Exiting get_value function ===" << std::endl;
-        log_stream << netcdf_ss.str();
-        LOG(netcdf_ss.str(), LogLevel::WARNING); netcdf_ss.str("");
-        return rvalue;
+        data_access::unit_conversion_exception uce(e.what());
+        uce.provider_model_name = "NetCDFPerFeatureDataProvider " + catchment_id;
+        uce.provider_bmi_var_name = selector.get_variable_name();
+        uce.provider_units = native_units;
+        uce.unconverted_values.push_back(rvalue);
+        throw uce;
     }
 
     return rvalue;

src/realizations/catchment/Bmi_Formulation.cpp

@@ -18,3 +18,7 @@ namespace realization
                 BMI_REALIZATION_CFG_PARAM_REQ__MODEL_TYPE,
         };
 }
+
+namespace data_access {
+    std::set<unit_error_log_key> unit_errors_reported;
+}

src/realizations/catchment/Bmi_Module_Formulation.cpp

@@ -25,8 +25,14 @@ namespace realization {
             if (timestep != (next_time_step_index - 1)) {
                 throw std::invalid_argument("Only current time step valid when getting output for BMI C++ formulation");
             }
-            std::string output_str;
 
+            static bool no_conversion_message_logged = false;
+            if (!no_conversion_message_logged) {
+                no_conversion_message_logged = true;
+                LOG("Emitting output variables from Bmi_Module_Formulation without unit conversion - see NGWPC-7604", LogLevel::WARNING);
+            }
+
+            std::string output_str;
             for (const std::string& name : get_output_variable_names()) {
                 output_str += (output_str.empty() ? "" : ",") + std::to_string(get_var_value_as_double(0, name));
             }
@@ -175,19 +181,12 @@ namespace realization {
                     return values;
                 }
                 catch (const std::runtime_error& e) {
-                    // Log at least one error
-                    if (!unitGetValuesErrLogged) {
-                        bmiform_ss << "BMI Module Formulation: get_values Unit conversion unsuccessful - Returning unconverted value! (" << e.what() << ")" << std::endl;
-                        unitGetValuesErrLogged = true;
-                        LOG(bmiform_ss.str(), LogLevel::WARNING); bmiform_ss.str("");
-                    }
-                    else {
-                        #ifndef UDUNITS_QUIET
-                        bmiform_ss << "BMI Module Formulation: get_values Unit conversion unsuccessful - Returning unconverted value! (" << e.what() << ")" << std::endl;
-                        LOG(bmiform_ss.str(), LogLevel::WARNING); bmiform_ss.str("");
-                        #endif
-                    }
-                    return values;
+                    data_access::unit_conversion_exception uce(e.what());
+                    uce.provider_model_name = get_bmi_model()->get_model_name();
+                    uce.provider_bmi_var_name = bmi_var_name;
+                    uce.provider_units = native_units;
+                    uce.unconverted_values = std::move(values);
+                    throw uce;
                 }
             }
             //This is unlikely (impossible?) to throw since a pre-check on available names is done above. Assert instead?
@@ -230,19 +229,12 @@ namespace realization {
                     return UnitsHelper::get_converted_value(native_units, value, output_units);
                 }
                 catch (const std::runtime_error& e){
-                    // Log at least one error
-                    if (!unitGetValueErrLogged) {
-                        bmiform_ss << "BMI Module Formulation: get_value Unit conversion unsuccessful - Returning unconverted value! (" << e.what() << ")" << std::endl;
-                        unitGetValueErrLogged = true;
-                        LOG(bmiform_ss.str(), LogLevel::WARNING); bmiform_ss.str("");
-                    }
-                    else {
-                        #ifndef UDUNITS_QUIET
-                        bmiform_ss << "BMI Module Formulation: get_value Unit conversion unsuccessful - Returning unconverted value! (" << e.what() << ")" << std::endl;
-                        LOG(bmiform_ss.str(), LogLevel::WARNING); bmiform_ss.str("");
-                        #endif
-                    }
-                    return value;
+                    data_access::unit_conversion_exception uce(e.what());
+                    uce.provider_model_name = get_bmi_model()->get_model_name();
+                    uce.provider_bmi_var_name = bmi_var_name;
+                    uce.provider_units = native_units;
+                    uce.unconverted_values.push_back(value);
+                    throw uce;
                 }
             }
 
@@ -724,10 +716,28 @@ namespace realization {
                     value_ptr = get_values_as_type( type, values.begin(), values.end() );
 
                 } else {
-                    //scalar value
-                    double value = provider->get_value(CatchmentAggrDataSelector(this->get_catchment_id(),var_map_alias, model_epoch_time, t_delta,
-                                                   get_bmi_model()->GetVarUnits(var_name)));
-                    value_ptr = get_value_as_type(type, value);
+                    try {
+                        //scalar value
+                        double value = provider->get_value(CatchmentAggrDataSelector(this->get_catchment_id(),var_map_alias, model_epoch_time, t_delta,
+                                                                                     get_bmi_model()->GetVarUnits(var_name)));
+                        value_ptr = get_value_as_type(type, value);
+                    } catch (data_access::unit_conversion_exception &uce) {
+                        data_access::unit_error_log_key key{get_id(), var_map_alias, uce.provider_model_name, uce.provider_bmi_var_name, uce.what()};
+                        auto ret = data_access::unit_errors_reported.insert(key);
+                        bool new_error = ret.second;
+                        if (new_error) {
+                            std::stringstream ss;
+                            ss << "Unit conversion failure:"
+                               << " requester {'" << get_bmi_model()->get_model_name() << "' catchment '" << get_catchment_id()
+                               << "' variable '" << var_name << "'" << " (alias '" << var_map_alias << "')"
+                               << " units '" << get_bmi_model()->GetVarUnits(var_name) << "'}"
+                               << " provider {'" << uce.provider_model_name << "' source variable '" << uce.provider_bmi_var_name << "'"
+                               << " raw value " << uce.unconverted_values[0] << "}"
+                               << " message \"" << uce.what() << "\"";
+                            LOG(ss.str(), LogLevel::WARNING); ss.str("");
+                        }
+                        value_ptr = get_value_as_type(type, uce.unconverted_values[0]);
+                    }
                 }
                 get_bmi_model()->SetValue(var_name, value_ptr.get());
             }

test/bmi/Bmi_Cpp_Adapter_Test.cpp

@@ -51,7 +51,7 @@ class Bmi_Cpp_Adapter_Test : public ::testing::Test {
     std::vector<std::string> expected_output_var_names = { "OUTPUT_VAR_1", "OUTPUT_VAR_2" };
     std::vector<std::string> expected_output_var_locations = { "node", "node" };
     std::vector<int> expected_output_var_grids = { 0, 0 };
-    std::vector<std::string> expected_output_var_units = { "m", "m" };
+    std::vector<std::string> expected_output_var_units = { "mm/s", "m" };
     std::vector<std::string> expected_output_var_types = { "double", "double" };
     int expected_grid_rank = 1;
     int expected_grid_size = 1;

test/bmi/Bmi_Fortran_Adapter_Test.cpp

@@ -52,7 +52,7 @@ class Bmi_Fortran_Adapter_Test : public ::testing::Test {
     std::vector<std::string> expected_output_var_locations = { "node", "node", "node", "node", "node"};
     std::vector<int> expected_output_var_grids = { 0, 0, 0, 1, 2, 2 };
     std::vector<int> expected_input_var_grids = { 0, 0, 0, 1 };
-    std::vector<std::string> expected_output_var_units = { "m", "m", "s", "m", "m", "m" };
+    std::vector<std::string> expected_output_var_units = { "mm s^-1", "m", "s", "m", "m", "m" };
     std::vector<std::string> expected_output_var_types = { "double precision", "real", "integer", "double precision", "double precision", "double precision" };
     std::vector<int> expected_output_var_item_sizes = { 8, 4, 4, 8, 8, 8};
     std::vector<std::string> expected_input_var_types = { "double precision", "real", "integer", "double precision" };