Bugfix: METplus GridStat can't find OBS file using template and time range

[MarcelCaron-NOAA]

Replace italics below with details for this issue.

Describe the Problem

A METplus error occurs when this EVS/cam job is run on NCEP's WCOSS2 system in one environment (named "test_ecflow_env" for testing here). However, the same job is successful when run in a different environment ("test_parallel_env"). In the first case, METplus is unable to find a file that exists when checked manually. Could you help us debug?

Attached are copies of (1) the stdout log for the EVS job that failed (2) the METplus log file of the failed METplus run, and (3) two test scripts, described below and in the "To Reproduce" section.
EVS_fail_job.txt
METplus_fail_log.txt
test_ecflow_env.txt
test_parallel_env.txt

Here is an excerpt from the stdout log for the EVS job that included that METplus run:

5996 0 + '[' -s /lfs/h2/emc/vpppg/noscrub/emc.vpppg/com/evs/v1.0/prep/cam/mrms.20231107/conus/EchoTop18_00.50_20231107-150000.G227.nc ']'
...
 6008 0 + obs_found=1

The above excerpt is a section of our code that checks for the presence of an observation file that will be used in METplus, a check which was successful in this case. To confirm, a list command for the file showed that the file does exist on the system (WCOSS2/Dogwood).

However, the METplus run that followed the excerpted code outputs an error. The associated METplus log is attached, but here is an excerpt:

  32 11/08 18:36:50.387 metplus (command_builder.py:694) DEBUG: Looking for OBS_INPUT files under /lfs/h2/emc/vpppg/noscrub/emc.vpppg/com/evs/v1.0/prep/cam within range [-300,300] using template mrms.{valid?fmt=%Y%m%d}/conus/EchoTop18_00.50_{valid?fmt=%Y%m%d}-{valid?fmt=%H}0000.G227.nc
  33 11/08 18:36:50.792 metplus (command_builder.py:257) ERROR: (command_builder.py:741) Could not find OBS_INPUT files under /lfs/h2/emc/vpppg/noscrub/emc.vpppg/com/evs/v1.0/prep/cam within range [-300,300] using template mrms.{valid?fmt=%Y%m%d}/conus/EchoTop18_00.50_{valid?fmt=%Y%m%d}-{valid?fmt=%H}0000.G227.nc
  34 11/08 18:36:50.793 metplus (command_builder.py:257) ERROR: (command_builder.py:490) Could not find observation file

The valid time in this case is 2023110715, so METplus should have been able to find the file.

We also confirmed that (1) the observation file was already available before METplus was run, at about 11/08 18:15Z and (2) the valid time stored in the observation file is 11/07/2023 15:00:38Z, which should have satisfied the matching condition in METplus.

I've set up two test cases ("test_ecflow_env" and "test_parallel_env") with slightly different environments, one in which the error described here can be replicated, the other in which the same METplus run is successful.

I'm wondering if any part of our configuration jumps out to you as a possible cause of the issue?

Expected Behavior

The observation file should satisfy the METplus check for files that match the template within the valid hour range (11/07/2023 15Z +/- 5 mins). That observation file should be used to complete the METplus run successfully (the forecast file having been already found successfully). In other words, the "test_parallel_env" test results represent the expected behavior.

Environment

Describe your runtime environment:

1. Machine: WCOSS2, Dogwood
2. OS: Linux
3. Here are the modules loaded into the environment from which METplus was run in both test cases:

1) craype-x86-rome     (H)  11) ve/evs/1.0         21) hdf5/1.10.6
2) libfabric/1.11.0.0. (H)  12) cray-mpich/8.1.19  22) netcdf/4.7.4
3) craype-network-ofi  (H)  13) cray-pals/1.2.2    23) nco/4.9.7
4) envvar/1.0               14) cfp/2.0.4          24) prod_util/2.0.13
5) prod_envir/2.0.6         15) libjpeg/9c         25) cdo/1.9.8
6) intel/19.1.3.304         16) libpng/1.6.37      26) grib_util/1.2.4
7) PrgEnv-intel/8.3.3       17) zlib/1.2.11        27) wgrib2/2.0.8
8) craype/2.7.17            18) jasper/2.0.25      28) met/11.0.2
9) geos/3.8.1               19) udunits/2.2.28     29) metplus/5.0.1
10) proj/7.1.0               20) gsl/2.7

To Reproduce

Describe the steps to reproduce the behavior:
Two very similar tests may help isolate the problem. The first fails and the second succeeds. To test:

1. Log onto WCOSS2 Dogwood (prod) and cd into your work space (a test directory on ptmp or stmp will work)
2. Transfer the following files (attached here) from your local computer to your work space on WCOSS2 (Dogwood):
   test_ecflow_env.txt
   test_parallel_env.txt
3. Convert the files to bash scripts:
   cp test_ecflow_env.txt test_ecflow_env.sh
   cp test_parallel_env.txt test_parallel_env.sh
4. Make sure the files are user-executable:
   chmod u+x test_ecflow_env.sh
   chmod u+x test_parallel_env.sh
5. Open each test file (vi test_*_env.sh) and edit the section below #### EDIT BELOW FOR TESTING #### as needed
6. Run each test script, redirecting the output
   test_ecflow_env.sh &> test1.out
   test_parallel_env.sh &> test2.out
   (Note: these will write two data directories for METplus to use
7. test_ecflow_env should output errors, failing to find the output file. test_parallel_env should succeed.

If testing this on WCOSS2/Dogwood (currently the production machine) is not possible, or if you'd prefer the test data is provided here, please let me know and I can ask someone to copy it over. Thanks

Relevant Deadlines

The relevant EVS code will be delivered at COB 11/17/2023.

Funding Source

NOAA/NCEP/EMC/VPPPG

Define the Metadata

Assignee

• Select engineer(s) or no engineer required
• Select scientist(s) or no scientist required

Labels

• Select component(s)
• Select priority
• Select requestor(s)

Projects and Milestone

• Select Organization level Project for support of the current coordinated release
• Select Repository level Project for development toward the next official release or add alert: NEED CYCLE ASSIGNMENT label
• Select Milestone as the next bugfix version

Define Related Issue(s)

Consider the impact to the other METplus components.

• METplus, MET, METdataio, METviewer, METexpress, METcalcpy, METplotpy

Bugfix Checklist

See the METplus Workflow for details.

• Complete the issue definition above, including the Time Estimate and Funding Source.
• Fork this repository or create a branch of main_<Version>.
  Branch name: bugfix_<Issue Number>_main_<Version>_<Description>
• Fix the bug and test your changes.
• Add/update log messages for easier debugging.
• Add/update unit tests.
• Add/update documentation.
• Add any new Python packages to the METplus Components Python Requirements table.
• Push local changes to GitHub.
• Submit a pull request to merge into main_<Version>.
  Pull request: bugfix <Issue Number> main_<Version> <Description>
• Define the pull request metadata, as permissions allow.
  Select: Reviewer(s) and Development issues
  Select: Organization level software support Project for the current coordinated release
  Select: Milestone as the next bugfix version
• Iterate until the reviewer(s) accept and merge your changes.
• Delete your fork or branch.
• Complete the steps above to fix the bug on the develop branch.
  Branch name: bugfix_<Issue Number>_develop_<Description>
  Pull request: bugfix <Issue Number> develop <Description>
  Select: Reviewer(s) and Development issues
  Select: Repository level development cycle Project for the next official release
  Select: Milestone as the next official version
• Close this issue.

[CPKalb]

Hi:

Could you include a log file for a successful run, as this will help track down the differences.

Thanks,
Christina

[georgemccabe]

Hi @MarcelCaron-NOAA,

After reviewing the files you provided and your notes, I don't see anything obviously incorrect with your configuration. I don't have access to Dogwood and the only developer on our team that currently has access is not available to help with this until tomorrow afternoon. I have scheduled a meeting with them to take a closer look. If you are able to send over the log file for a successful run and the metplus_final.conf (defined by METPLUS_CONF) for both a successful and failed run, I could try to review the differences before then.

There are a few things I noticed that I don't think are the cause of the failure but may point you in the right direction.

The +/-5 minute window you have set only considers the filenames, not the actual time stored inside the files. In your example, the filename exactly matches the valid time, so a window is not necessary to find the mrms.20231107/conus/EchoTop18_00.50_20231107-150000.G227.nc file using mrms.{valid?fmt=%Y%m%d}/conus/EchoTop18_00.50_{valid?fmt=%Y%m%d}-{valid?fmt=%H}0000.G227.nc. If the filenames may vary to include minutes and seconds other than 0000, then the file window is needed. However, your template has hard-coded 0000 instead of including %M and %S in the valid tag, so it would not find files that are named with seconds, e.g. EchoTop18_00.50_20231107-150038.G227.nc. If the names of the files do include minutes and seconds other than 0, then you will need to set your input template to:

mrms.{valid?fmt=%Y%m%d}/conus/EchoTop18_00.50_{valid?fmt=%Y%m%d-%H%M%S}.G227.nc

Your example has 0000 for the minutes/seconds, so this shouldn't be the reason that the file was not found.

[MarcelCaron-NOAA]

Thanks for moving this discussion to the appropriate channel. I'm attaching two metplus_final config files--one for a failed run and the other for a successful run--and the log file for a successful run:
metplus_final_test1_fail.job2.GridStat_RETOP_conus.txt
metplus_final_test2_success.job2.GridStat_RETOP_conus.txt
METplus_success_log.txt

Ah okay, I wasn't sure whether or not the window considered the filenames. I'm not sure why we have both the minutes window and the hard-coded 0000 instead of %M and %S in the valid tag. I'll review our timing configuration, there may be a reason we developed this way. If we can get around using the window that would be great.

However, yes, given the provided template, the file should have been found.

[georgemccabe]

Hi @MarcelCaron-NOAA,

I worked with a few other METplus developers for an hour trying to investigate this error. We were able to replicate the error using the scripts you provided, so thank you for providing those easy-to-use scripts. We had to process files from 20231105, as there were no files in the com directory past that date. We were not able to figure out why the use case was failing to find the files within the time we had available. However, we were able to get it to work properly by removing the file window so the exact file name is searched. To remove the file window, change these values in your METplus configuration file:

OBS_GRID_STAT_FILE_WINDOW_BEGIN = 0
OBS_GRID_STAT_FILE_WINDOW_END = 0

We may be able to continue debugging the cause of the issue on Tuesday of next week if you'd like, but I hope that changing the configuration settings will get you a successful run. Please let me know if that change fixes the issue and if you'd like us to continue investigating the failure next week.

[MarcelCaron-NOAA]

Hi @georgemccabe:

Thank you so much for looking into this error in depth yesterday. Apologies that the full test dataset wasn't available, but we found that this error was occurring every cycle and every day, so 20231105 I think was appropriate to use for testing.

Your suggested solution will be enough to resolve the issue I think, as it does not seem the window is necessary for any variation of this job. I will implement and test this solution, and update this thread again this coming week if it is successful. I've marked this as the answer but will change with the update if needed.

Best,
Marcel

[georgemccabe]

Sounds good, @MarcelCaron-NOAA. I look forward to hearing if this solution works.

I would still like to understand why the error was occurring for one directory and not the other in case there is some way to make the error message more accurate. I suspect that it has something to do with file/directory permissions but it is hard to say without more testing.

[georgemccabe]

Hi @MarcelCaron-NOAA,

We discovered the source of the problem. The directories under /lfs/h2/emc/vpppg/noscrub/emc.vpppg/com/evs/v1.0/prep/cam are symbolic links to directories. The METplus wrappers logic to traverse through the directories to find files that fall within the file window does not follow symbolic links. This is a simple fix that I will include in the METplus 6.0.0-beta2 release. I created issue #2423 to track the work.

If you can confirm that your use case works as expected when you remove the file window time range, then I don't think a bugfix release is needed, but please let me know if you do need one.

[MarcelCaron-NOAA]

Hi @georgemccabe:

The fix works. We tested it in the ecflow environment on Dogwood and the job ran to completion. So I think we'll continue with this original solution, no bugfix release needed.

I'm glad you were able to solve the issue, and that it is a simple fix. I suspected it had to do with the files in that directory. However, since the use case works by removing the file window time range, having the fix in the METplus 6.0.0-beta2 release is fine with me.

Thanks again for all of the help with this issue.

[georgemccabe]

Thanks for confirming. I'm going to lock this discussion to prevent future posts. Please feel free to create a new discussion thread if you have any other issues or questions.