clean up logging #792

rgknox · 2021-10-06T17:45:51Z

Description:

This set of changes seeks to ensure that all write statements to logs, that are intended to "warn", are either:

encapsulated in some type of debug clause, where the user has to set the debug level to verbose, or
is followed by an endrun
uses the FatesWarn() wrapper

FatesWarn() has a feature where each warning message is associated with an index. Once the specific warning has been written 100 times (or other desired value), it will stop reporting the warning. It will continue to count how many times the warning trips. It maintains these counts at the node level.

In some situations, such as the interface, we had also been requiring verbose output prior to an endrun. If the model hits an endrun prematurely, it is a failure, and thus all logging information is welcomed. So the verbose requirement was removed.

In a few situations we had been reporting errors that were fairly catastrophic without failing (such as encountering negative patch areas). So, endrun() was added to a few locations.

Fixes: #772
Fixes: #236
Fixes: #191
Fixes: #793

Collaborators:

@jkshuman

Expectation of Answer Changes:

This should not change answers

Checklist:

My change requires a change to the documentation.
I have updated the in-code documentation .AND. (the technical note .OR. the wiki) accordingly.
I have read the CONTRIBUTING document.
FATES PASS/FAIL regression tests were run
If answers were expected to change, evaluation was performed and provided

Test Results:

CTSM (or) E3SM (specify which) test hash-tag:

CTSM (or) E3SM (specify which) baseline hash-tag:

FATES baseline hash-tag:

Test Output:

… clause, or ensuring there is an endrun following.

rgknox · 2021-10-06T18:22:54Z

Updated the metadata of the decompmicc parameter in the parameter file. See: ef9126a

…n function

glemieux

This is a good amount of cleanup; really nice work.

I couldn't tag this directly to the line in github, but was the following overlooked or intentionally left without a debug flag check since it's only writing to the lead node?

fates/biogeochem/EDLoggingMortalityMod.F90

Lines 181 to 184 in 4acc184

    
           if(logging_time .and. (is_master.eq.itrue) ) then 
        
              write(fates_log(),fmt) 'Logging Event Enacted on date: ', & 
        
                    hlm_current_month,'-',hlm_current_day,'-',hlm_current_year 
        
           end if

biogeochem/EDCohortDynamicsMod.F90

rgknox · 2021-10-07T15:58:03Z

I did intentionally leave the logging event print-outs. They should be fairly sparse, and I figure it is useful for people using the logging module to have that verification of their events. Again, don't feel strongly here, I can also ecapsulate this in a debug.

jkshuman · 2021-10-13T03:30:25Z

@rgknox this looks good and will certainly help reduce the logging event print-outs. After I went through this I looked at my logs to confirm a reduction, and this will capture some things. But there is one that is not addressed. In the CESM.log and LND.log I get a consistent "BalanceCheck, solar radiation balance error" , but from what I can tell this is outside of FATES here:
src/biogeophys/BalanceCheckMod.F90: write(iulog,*)'WARNING:: BalanceCheck, solar radiation balance error (W/m2)'

So, I guess this BalanceCheck solar radiation error warning is a separate issue then, and I can approve this PR? Should I open a separate issue for that, or would this be on the HLM side?

Example from recent LND.log:
clm: completed timestep 4397444
(shr_dmodel_readstrm) file ub: /glade/p/cesmdata/cseg/inputdata/atm/datm7/NASA_LIS/clmforc.Li_2016_climo1995-2013.360x720.lnfm_Total_c160825.nc 4363
clm: completed timestep 4397445
WARNING:: BalanceCheck, solar radiation balance error (W/m2)
nstep = 4397446
errsol = -1.125070525631600E-007
clm: completed timestep 4397446
WARNING:: BalanceCheck, solar radiation balance error (W/m2)
nstep = 4397447
errsol = -1.602288648427930E-007
clm: completed timestep 4397447
WARNING:: BalanceCheck, solar radiation balance error (W/m2)
nstep = 4397448
errsol = -1.805403826438123E-007
clm: completed timestep 4397448
(shr_dmodel_readstrm) file ub: /glade/p/cesmdata/cseg/inputdata/atm/datm7/NASA_LIS/clmforc.Li_2016_climo1995-2013.360x720.lnfm_Total_c160825.nc 4364
WARNING:: BalanceCheck, solar radiation balance error (W/m2)
nstep = 4397449
errsol = -1.813866674638120E-007
clm: completed timestep 4397449
WARNING:: BalanceCheck, solar radiation balance error (W/m2)
nstep = 4397450
errsol = -2.600071979941276E-007
clm: completed timestep 4397450

Example of some of that reporting from a recent CESM.log:
107: WARNING:: BalanceCheck, solar radiation balance error (W/m2)
107: nstep = 4397517
107: errsol = -2.104200120811583E-007
265: WARNING:: BalanceCheck, solar radiation balance error (W/m2)
265: nstep = 4397517
265: errsol = -1.050174205374788E-007
14: WARNING:: BalanceCheck, solar radiation balance error (W/m2)
14: nstep = 4397517
14: errsol = -1.005038257062552E-007
119: WARNING:: BalanceCheck, solar radiation balance error (W/m2)
119: nstep = 4397517
119: errsol = -1.116209489282483E-007
280: WARNING:: BalanceCheck, solar radiation balance error (W/m2)
280: nstep = 4397517
280: errsol = -1.113486405301956E-007

jkshuman · 2021-10-13T03:41:05Z

updated this previous comment to reflect that the BalanceCheck solar radiation warning happens in CESM.log and LND.log

rgknox · 2021-10-13T15:53:23Z

I see that this messaging is like you say, on the CTSM side of the code. Those logging messages may be outside the scope of this PR, but this sounds like a potential discussion topic to bring up at the CTSM software meeting?
@ekluzek @billsacks @glemieux

glemieux · 2021-10-13T16:43:55Z

That sounds like a good idea @rgknox. I added it to the agenda of tomorrow's ctsm software meeting.

jkshuman · 2021-10-13T16:57:06Z

@rgknox and @glemieux sounds good. It is worth noting that this radiation imbalance is being ignored on the FATES side, so perhaps we should discuss the validity of this error tolerance on the FATES side as well. (Though I am not totally sure these are the same balance checks...)

fates/biogeophys/EDSurfaceAlbedoMod.F90

Lines 968 to 988 in 2fa452a

    
           !here we are adding a within-ED radiation scheme tolerance, and then adding the diffrence onto the albedo 
        
           !it is important that the lower boundary for this is ~1000 times smaller than the tolerance in surface albedo.  
        
           if (abs(error)  >  1.e-9_r8 .and. abs(error) < 0.15_r8)then 
        
              albd_parb_out(ib) = albd_parb_out(ib) + error 
        
              !this terms adds the error back on to the albedo. While this is partly inexcusable, it is  
        
              ! in the medium term a solution that 
        
              ! prevents the model from crashing with small and occasional energy balances issues. 
        
              ! These are extremely difficult to debug, many have been solved already, leading 
        
              ! to the complexity of this code, but where the system generates occasional errors, we 
        
              ! will deal with them for now. 
        
           end if 
        
           if (abs(error)  >  0.15_r8)then 
        
              write(fates_log(),*) 'Large Dir Radn consvn error',error ,ib 
        
              write(fates_log(),*) 'diags', albd_parb_out(ib), ftdd_parb_out(ib), & 
        
                   ftid_parb_out(ib), fabd_parb_out(ib) 
        
              write(fates_log(),*) 'lai_change',lai_change(currentpatch%ncl_p,1:numpft,1:diag_nlevleaf) 
        
              write(fates_log(),*) 'elai',currentpatch%elai_profile(currentpatch%ncl_p,1:numpft,1:diag_nlevleaf) 
        
              write(fates_log(),*) 'esai',currentpatch%esai_profile(currentpatch%ncl_p,1:numpft,1:diag_nlevleaf) 
        
              write(fates_log(),*) 'ftweight',ftweight(1,1:numpft,1:diag_nlevleaf) 
        
              write(fates_log(),*) 'cp',currentPatch%area, currentPatch%patchno 
        
              write(fates_log(),*) 'ground albedo diffuse (ib)', currentPatch%gnd_alb_dir(ib)

glemieux

Looks good. I have one suggested change and two questions.

I also noticed that there are three current FatesWarn calls and the first index used is 2 and not 1. I'm assuming the FatesWarn call that used index=1 was removed?

main/FatesGlobals.F90

main/FatesInterfaceMod.F90

glemieux · 2022-04-21T22:52:46Z

main/FatesInterfaceMod.F90

-               end if
-               ! end_run
+               write(fates_log(), *) 'fates NL tag not recognized:',trim(tag)
+               !! call endrun(msg=errMsg(sourcefile, __LINE__))


We don't want to end the run if the tag isn't recognized?

We are currently passing in a tag that is not recognized! I don't know where this came from, but

https://github.com/ESCOMP/CTSM/blob/ctsm5.1.dev090/src/utils/clmfates_interfaceMod.F90#L323

I don't see this passed in E3SM:

https://github.com/E3SM-Project/E3SM/blob/master/components/elm/src/main/elmfates_interfaceMod.F90#L375-L379

I'm guessing 'sf_anthro_suppression_def' was added at one point with the expectation it would be used, but the usage was never implemented. Lets remove this argument pass in the next API change on ctsm

@rgknox I am guessing this is a tag associated with anthropogenic fire suppression. You are correct that it is not yet in use. I think @glemieux or @slevisconsulting implemented this?

Yup that was me 🤦. As Jackie noted its part of ESCOMP/CTSM#1536. Since this was a ctsm-side only update to prep for future work I guess should have commented out those lines and the lines later on down the file to avoid this issue?

https://github.com/ESCOMP/CTSM/blob/449345ee9a534316cba0d6b4fd696b8d57e60428/src/utils/clmfates_interfaceMod.F90#L822-L829

and

https://github.com/ESCOMP/CTSM/blob/449345ee9a534316cba0d6b4fd696b8d57e60428/src/utils/clmfates_interfaceMod.F90#L846-L850

Co-authored-by: Gregory Lemieux <7565064+glemieux@users.noreply.github.com>

rgknox · 2022-04-22T15:57:45Z

Good point about the indexing @glemieux . I might had started using 2, assuming 1 would be a "universal" or "generic" code, but that is zero. I can change this to start with one. Also, I need to change the loop in the finalize routine where the totals are printed, to start with zero and not 1.

rgknox · 2022-04-26T22:28:25Z

I believe all tests pass as expected.

rgknox/tests_0426-152504ch> ./cs.status.fails
0426-152504ch_gnu: 2 tests

 
0426-152504ch_int: 27 tests
    FAIL ERS_Lm12.1x1_brazil.I2000Clm50FatesCruRsGs.cheyenne_intel.clm-FatesFireLightningPopDens COMPARE_base_rest

Encapsulating all write/print statements to logging in either a debug…

d4e35f0

… clause, or ensuring there is an endrun following.

rgknox requested review from glemieux, rosiealice and jkshuman October 6, 2021 18:14

Added metadata fix to the decompmicc parameter

ef9126a

Fixed some text describing parameters in microbial biomass attenuatio…

4acc184

…n function

glemieux reviewed Oct 6, 2021

View reviewed changes

biogeochem/EDCohortDynamicsMod.F90 Show resolved Hide resolved

jkshuman mentioned this pull request Oct 14, 2021

Solar radiation error handling #794

Closed

First pass at adding warning functions

75e37c6

rgknox added 6 commits April 18, 2022 14:12

Merge resolution

51f46f3

Merge branch 'default-off-logs' into default-off-logs-warnfunc

4133a05

small bug fix from merge

84a67fa

Removing endruns in the NL passing

0f65e91

Merge branch 'default-off-logs' into default-off-logs-warnfunc

961d7b9

Various updates to FatesWarn

9e90dde

glemieux requested changes Apr 21, 2022

View reviewed changes

Update main/FatesGlobals.F90

9457e94

Co-authored-by: Gregory Lemieux <7565064+glemieux@users.noreply.github.com>

Fixed some logging indices

d974364

rgknox added 2 commits April 26, 2022 14:30

Removed extra def of msgErr

b9c8831

Merge branch 'master' into default-off-logs

5ca52ce

rgknox merged commit 55d40f1 into NGEET:master Apr 26, 2022

rgknox mentioned this pull request Jan 27, 2023

anatomy of a cesm.log #858

Open

rgknox deleted the default-off-logs branch October 31, 2023 18:02

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

clean up logging #792

clean up logging #792

rgknox commented Oct 6, 2021 •

edited

Loading

rgknox commented Oct 6, 2021

glemieux left a comment

rgknox commented Oct 7, 2021

jkshuman commented Oct 13, 2021 •

edited

Loading

jkshuman commented Oct 13, 2021

rgknox commented Oct 13, 2021

glemieux commented Oct 13, 2021

jkshuman commented Oct 13, 2021

glemieux left a comment

glemieux Apr 21, 2022

rgknox Apr 22, 2022

rgknox Apr 22, 2022

jkshuman Apr 22, 2022

glemieux Apr 22, 2022

rgknox commented Apr 22, 2022

rgknox commented Apr 26, 2022

	if(logging_time .and. (is_master.eq.itrue) ) then
	write(fates_log(),fmt) 'Logging Event Enacted on date: ', &
	hlm_current_month,'-',hlm_current_day,'-',hlm_current_year
	end if

clean up logging #792

clean up logging #792

Conversation

rgknox commented Oct 6, 2021 • edited Loading

Description:

Collaborators:

Expectation of Answer Changes:

Checklist:

Test Results:

rgknox commented Oct 6, 2021

glemieux left a comment

Choose a reason for hiding this comment

rgknox commented Oct 7, 2021

jkshuman commented Oct 13, 2021 • edited Loading

jkshuman commented Oct 13, 2021

rgknox commented Oct 13, 2021

glemieux commented Oct 13, 2021

jkshuman commented Oct 13, 2021

glemieux left a comment

Choose a reason for hiding this comment

glemieux Apr 21, 2022

Choose a reason for hiding this comment

rgknox Apr 22, 2022

Choose a reason for hiding this comment

rgknox Apr 22, 2022

Choose a reason for hiding this comment

jkshuman Apr 22, 2022

Choose a reason for hiding this comment

glemieux Apr 22, 2022

Choose a reason for hiding this comment

rgknox commented Apr 22, 2022

rgknox commented Apr 26, 2022

rgknox commented Oct 6, 2021 •

edited

Loading

jkshuman commented Oct 13, 2021 •

edited

Loading