Troubleshooting Empty run log

[rburghol]

Sometime a model will return an empty log file, or a log file will have gaps in it. The most common cause is bad SQL table column definition, either, trying to log a string to a numeric column, or trying to log a number to a column that was guess as "varchar(1)" due to a null value at first time step. 9 out of 10 times this is due to a problem with dataMatrix variables, since they are the only entity that can have multiple evaluation types, that is, the column values could be a string, or a variable reference, or a numeric value, and the default value type is "auto", which means the system guesses... which is a design flaw that has only recently come to light as such (and will be eliminated in the new python version of the model).

Finding it

• Watch the database log
  • sudo su - postgres
  • tail -f logfile.model_scratch
• find the element id (in the table name) that is broken in the log (this will be recurring if there are large gaps in your model data, or the model data is missing altogether)
  • Ex: ERROR: value too long for type character varying(1) \n 2023-05-11 18:04:02.253 UTC [3374197] STATEMENT: insert into "tmp339146_047_datalog"
• Check more detail def to see which column it is:
  • cd om
  • php test_sqldef.php 245105 401 339146
  • SQL Def for Greensville County Raw Water Reservoir and Intake:Nottoway River = create TEMP table "tmp339146_058_datalog" ( "local_impoundment_Qin" float8 , "local_impoundment_evap_mgd" float8 ...
  • Look for varchar(1) in there (I just copy and paste the def table into notepad++ and search)
  • Once you find it, it is pretty clear. See Re-Creating the Error in psql CMD line
  • Alternate method to find the table definition from the last model run is stored in a separate log file:
    • /var/www/html/data/proj3/out/def.[elementid].-1.sql
    • Ex: cat /var/www/html/data/proj3/out/def.219133.-1.sql

Common Causes

• DataMatrix lookup tables without a specific DB Value Type -- can be set in the interface

Re-Creating the Error in psql CMD line

• Find an erroneous line (use one from the tail -f above, or fgrep for a specific one
  • fgrep for a specific line: fgrep 219133 logfile.model_scratch |grep '2008-12-30'
  • Note: in this example the error is value too long for type character varying(1)
• Get the recent definition log; cat /var/www/html/data/proj3/out/def.219133.-1.sql
• Find the varchar(1) -- in this example there are 6 columns with varchar(1):
  • "description", "historic_annual", "Send to Parent", "Listen on Parent", "current_monthly_discharge", and "local_impoundment"
  • Of these, only "historic_annual" and "current_monthly_discharge" can have any time varying data (broadcast variables don't actually log any specific data, nor do impoundment and channel type, or rather, impoundment and channel types log null under their own name, and store specific sub data, like local_impoundment_Qout
• This ends up being easy, current_monthly_discharge can be deleted, and historic_annual can be set to have type float8 and default value of 0.

SQL 1: Logfile for SQL definition of element 219133

create TEMP table "tmp219133_047_datalog" ( "local_impoundment_Qin" float8 , "local_impoundment_evap_mgd" float8 , "local_impoundment_Qout" float8 , "local_impoundment_lake_elev" float8 , "local_impoundment_Storage" float8 , "local_impoundment_refill_full_mgd" float8 , "local_impoundment_demand" float8 , "local_impoundment_use_remain_mg" float8 , "local_impoundment_days_remaining" float8 , "local_impoundment_max_usable" float8 , "local_impoundment_riser_stage" float8 , "local_impoundment_riser_head" float8 , "local_impoundment_riser_mode" varchar(32) , "local_impoundment_riser_flow" float8 , "local_impoundment_riser_diameter" float8 , "local_impoundment_demand_met_mgd" float8 , "local_impoundment_its" float8 , "local_impoundment_spill" float8 , "local_impoundment_release" float8 , "local_impoundment_area" float8 , "local_impoundment_refill" float8 , "run_mode" float8 , "Qriver" float8 , "wd_last_mgd" float8 , "ps_last_mgd" float8 , "lake_elev" float8 , "drought_status" float8 , "pct_full" float8 , "rejected_demand_pct" float8 , "impoundment_use_remain_mg" float8 , "Qreach" float8 , "Qriver_up" float8 , "Runit" float8 , "precip_in" float8 , "et_in" float8 , "reach_area_sqmi" float8 , "flowby_current" float8 , "release_proposed" float8 , "name" varchar(85) , "description" varchar(1) , "componentid" varchar(128) , "subshedid" varchar(128) , "dt" float8 , "month" float8 , "day" float8 , "year" float8 , "jday" float8 , "thisdate" date , "time" timestamp , "timestamp" bigint , "modays" bigint , "flow_mode" float8 , "season" varchar(8) , "wd_mgd" float8 , "discharge_mgd" float8 , "consumption" float8 , "current_mgy" float8 , "future_mgd" float8 , "safe_yield_mgy" float8 , "safe_yield" float8 , "current_mgd" float8 , "unaccounted_losses" float8 , "fac_demand_mgd" float8 , "fac_current_mgy" float8 , "riverseg_frac" float8 , "wsp2020_2040_mgy" float8 , "wsp2020_2020_mgy" float8 , "vwp_exempt_mgd" float8 , "wsp2020_2030_mgy" float8 , "available_mgd" float8 , "max_mgd" float8 , "adj_demand_mgd" float8 , "drought_response_enabled" float8 , "unmet_demand_mgd" float8 , "Qintake" float8 , "gw_frac" float8 , "sw_frac" float8 , "gw_sw_factor" float8 , "gw_demand_mgd" float8 , "discharge_from_gw_mgd" float8 , "ustabe_future_mgd" float8 , "safeyield_mgd" float8 , "vwp_prop_max_mgy" float8 , "vwp_prop_max_mgd" float8 , "vwp_prop_base_mgd" float8 , "vwp_prop_demand_mgd" float8 , "vwp_max_mgy" float8 , "vwp_max_mgd" float8 , "vwp_base_mgd" float8 , "vwp_demand_mgd" float8 , "permit_status" varchar(64) , "flowby_proposed" float8 , "flowby_historic" float8 , "mif_monthly" float8 , "refill_max_mgd" float8 , "scenario" varchar(64) , "reports" varchar(64) , "local_area_sqmi" float8 , "local_flow_cfs" float8 , "refill_available_mgd" float8 , "refill_pump_mgd" float8 , "refill_plus_demand" float8 , "zero" float8 , "imp_enabled" float8 , "wd_net_mgd" float8 , "release_current" float8 , "release_historic" float8 , "week" float8 , "historic_annual" varchar(1) , "Send to Parent" varchar(1) , "Listen on Parent" varchar(1) , "flowby" float8 , "historic_monthly_pct" float8 , "current_monthly_discharge" varchar(1) , "ps_enabled" float8 , "fac_demand_mgy" float8 , "base_demand_mgd" float8 , "drought_pct" float8 , "base_demand_pstatus_mgd" float8 , "local_impoundment" varchar(1) , "mif_monthly_gage" float8 , "release" float8 )

SQL 2: Find a specific data error using fgrep, ex: fgrep 219133 logfile.model_scratch |grep '2008-12-30'.

2023-05-19 00:52:32.289 UTC [279764] STATEMENT: insert into "tmp219133_047_datalog" ( "local_impoundment_evap_mgd" , "local_impoundment_Qout" , "local_impoundment_lake_elev" , "local_impoundment_Storage" , "local_impoundment_refill_full_mgd" , "local_impoundment_demand" , "local_impoundment_use_remain_mg" , "local_impoundment_days_remaining" , "local_impoundment_max_usable" , "local_impoundment_riser_stage" , "local_impoundment_riser_head" , "local_impoundment_riser_mode" , "local_impoundment_riser_flow" , "local_impoundment_riser_diameter" , "local_impoundment_demand_met_mgd" , "local_impoundment_its" , "local_impoundment_spill" , "local_impoundment_release" , "local_impoundment_area" , "local_impoundment_refill" , "local_impoundment_Qin" , "run_mode" , "Qriver" , "wd_last_mgd" , "ps_last_mgd" , "lake_elev" , "drought_status" , "pct_full" , "rejected_demand_pct" , "impoundment_use_remain_mg" , "Qreach" , "Qriver_up" , "Runit" , "precip_in" , "et_in" , "reach_area_sqmi" , "flowby_current" , "release_proposed" , "thisdate" , "month" , "day" , "year" , "jday" , "week" , "timestamp" , "modays" , "flow_mode" , "historic_annual" , "wd_mgd" , "Send to Parent" , "Listen on Parent" , "discharge_mgd" , "flowby" , "historic_monthly_pct" , "consumption" , "current_monthly_discharge" , "current_mgy" , "future_mgd" , "safe_yield_mgy" , "safe_yield" , "current_mgd" , "ps_enabled" , "fac_demand_mgy" , "unaccounted_losses" , "fac_demand_mgd" , "fac_current_mgy" , "riverseg_frac" , "wsp2020_2040_mgy" , "wsp2020_2020_mgy" , "vwp_exempt_mgd" , "wsp2020_2030_mgy" , "available_mgd" , "base_demand_mgd" , "max_mgd" , "adj_demand_mgd" , "drought_pct" , "drought_response_enabled" , "unmet_demand_mgd" , "Qintake" , "gw_frac" , "sw_frac" , "gw_sw_factor" , "gw_demand_mgd" , "discharge_from_gw_mgd" , "ustabe_future_mgd" , "safeyield_mgd" , "base_demand_pstatus_mgd" , "vwp_prop_max_mgy" , "vwp_prop_max_mgd" , "vwp_prop_base_mgd" , "vwp_prop_demand_mgd" , "vwp_max_mgy" , "vwp_max_mgd" , "vwp_base_mgd" , "vwp_demand_mgd" , "permit_status" , "flowby_proposed" , "flowby_historic" , "local_impoundment" , "mif_monthly_gage" , "mif_monthly" , "refill_max_mgd" , "scenario" , "reports" , "local_area_sqmi" , "local_flow_cfs" , "refill_available_mgd" , "refill_pump_mgd" , "refill_plus_demand" , "zero" , "imp_enabled" , "wd_net_mgd" , "release" , "release_current" , "release_historic" ) values ( 0,0,'10','54',0,'0','12.99674267101',0,'39.9',NULL,NULL,'',NULL,NULL,'0',NULL,0,'0','5','0','0','4','78.201660174277',0,'3.4395084617573','10',0,'1',0,'293.15960912052','78.201660174277','13.848868314636',0,0,0,0,'10.321282798834','0','2008-12-30','12','30','2008','364','01','1230613200','31','3','13','0','','','0','10.321282798834','0.0000','1','','0','0.079999999999999','20.64','0','0','1','0','0','0','2.6666666666667','0','0','0','0.079999999999999','0','12.99674267101','0','0','0','0','1','0','23.054530051479','0','1','0','0','0','0','0.079999999999999','0','29.2','0.288','0','0','29.2','0.288','0','0','reissue','20.749077046331','10.321282798834','','6.2','10.321282798834','0.288','vahydro-1.0','Custom information for automated assembly of CIA reports.','0','0','8.2309290579476','0','0','0','1','0','0','0','0')