met workflow continues after logger.severe

[infotroph]

I'm not sure if this is actually a bug or working as intended. In the run below, I'm trying to download raw data to extend an existing input. The initial failure is pure user error -- I'm requesting data that doesn't exist -- but I was expecting the whole conversion workflow to exit after the logger.severe in the download stage. Instead, met2CF goes ahead and the workflow only stops at the second logger.severe, when met2CF discovers that it's attempting to convert a file that wasn't downloaded.

workflow output:

2017-05-23 10:22:12 DEBUG  [convert.input] : 
   Convert.Inputs download.Geostreams NA localhost 
   /home/a-m/black11/.pecan/dbfiles/Geostreams_site_8-4906 Geostreams 
   meteorology application/json 8000004906 2016-01-01 2016-12-31 
2017-05-23 10:22:12 INFO   [convert.input] : 
   start CHECK Convert.Inputs download.Geostreams NA localhost 
   /home/a-m/black11/.pecan/dbfiles/Geostreams_site_8-4906/ Geostreams 
   meteorology application/json 8000004906 2016-01-01 2016-12-31 
2017-05-23 10:22:12 WARN   [dbfile.input.check] : 
   Found possible matching input. Checking if its associate files are on 
   host machine 
     id    site_id notes          created_at          updated_at start_date
1 8e+09 8000004906       2017-05-23 10:19:34 2017-05-23 10:19:34 2016-02-16
    end_date                   name parent_id user_id access_level raw
1 2016-09-24 Geostreams_site_8-4906        NA      NA            4  NA
  format_id
1        46
2017-05-23 10:22:12 INFO   [convert.input] : 
   8000001414 Clowder.UIUC Energy Farm - SE.2016-02-16.2016-09-24 
   /home/a-m/black11/.pecan/dbfiles/Geostreams_site_8-4906 NA NA NA 18 
   1495552774 1495552774 Input 8000000053 
2017-05-23 10:22:12 INFO   [convert.input] : 
   end CHECK for existing input record. 
2017-05-23 10:22:12 INFO   [convert.input] : 
   Changed start/end dates to '2016-01-01'/'2016-12-31' so that existing 
   input can be updated while maintaining continuous time span. 
2017-05-23 10:22:12 DEBUG  [convert.input] : 
   convert.input executing the following function: 
   PEcAn.data.atmosphere::download.Geostreams(sitename='UIUC Energy Farm - 
   SE', username='pecan', overwrite=FALSE, 
   outfolder='/home/a-m/black11/.pecan/dbfiles/Geostreams_site_8-4906/', 
   start_date='2016-01-01', end_date='2016-12-31') 

R version 3.3.1 (2016-06-21) -- "Bug in Your Hair"
Copyright (C) 2016 The R Foundation for Statistical Computing
Platform: x86_64-redhat-linux-gnu (64-bit)

R is free software and comes with ABSOLUTELY NO WARRANTY.
You are welcome to redistribute it under certain conditions.
Type 'license()' or 'licence()' for distribution details.

  Natural language support but running in an English locale

R is a collaborative project with many contributors.
Type 'contributors()' for more information and
'citation()' on how to cite R or R packages in publications.

Type 'demo()' for some demos, 'help()' for on-line help, or
'help.start()' for an HTML browser interface to help.
Type 'q()' to quit R.

> remotefunc <- function() {PEcAn.data.atmosphere::download.Geostreams(sitename='UIUC Energy Farm - SE', username='pecan', overwrite=FALSE, outfolder='/home/a-m/black11/.pecan/dbfiles/Geostreams_site_8-4906/', start_date='2016-01-01', end_date='2016-12-31')}
> remoteout <- remotefunc()
2017-05-23 10:22:13 SEVERE [PEcAn.data.atmosphere::download.Geostreams] : 
   Requested start date 1451606400 is before data begin 1451630700 
Error in logger.severe("Requested start date", start_date, "is before data begin",  : 
  Requested start date 2016-01-01 is before data begin 2016-01-01 06:45:00
Calls: remotefunc -> <Anonymous> -> logger.severe
Execution halted
[1] 1
2017-05-23 10:22:13 INFO   [convert.input] : 
   RESULTS: Convert.Input 
2017-05-23 10:22:13 INFO   [convert.input] : 1 
2017-05-23 10:22:13 INFO   [convert.input] :  
2017-05-23 10:22:13 INFO   [.met2cf.module] : 
   Begin change to CF Standards 
2017-05-23 10:22:13 DEBUG  [convert.input] : 
   Convert.Inputs met2CF.Geostreams 8000000053 localhost 
   /home/a-m/black11/.pecan/dbfiles/Geostreams_CF_site_8-4906 CF 
   Meteorology application/x-netcdf 8000004906 2016-01-01 2016-12-31 
2017-05-23 10:22:13 INFO   [convert.input] : 
   start CHECK Convert.Inputs met2CF.Geostreams 8000000053 localhost 
   /home/a-m/black11/.pecan/dbfiles/Geostreams_CF_site_8-4906/ CF 
   Meteorology application/x-netcdf 8000004906 2016-01-01 2016-12-31 
2017-05-23 10:22:13 INFO   [convert.input] :  
2017-05-23 10:22:13 INFO   [convert.input] : 
   end CHECK for existing input record. 
2017-05-23 10:22:13 DEBUG  [convert.input] : 
   convert.input executing the following function: 
   PEcAn.data.atmosphere::met2CF.Geostreams(lat=40.05691, lon=-88.193573, 
   overwrite=FALSE, 
   in.path='/home/a-m/black11/.pecan/dbfiles/Geostreams_site_8-4906', 
   in.prefix='Clowder.UIUC Energy Farm - SE.2016-02-16.2016-09-24', 
   outfolder='/home/a-m/black11/.pecan/dbfiles/Geostreams_CF_site_8-4906/', 
   start_date='2016-01-01', end_date='2016-12-31') 

R version 3.3.1 (2016-06-21) -- "Bug in Your Hair"
Copyright (C) 2016 The R Foundation for Statistical Computing
Platform: x86_64-redhat-linux-gnu (64-bit)

R is free software and comes with ABSOLUTELY NO WARRANTY.
You are welcome to redistribute it under certain conditions.
Type 'license()' or 'licence()' for distribution details.

  Natural language support but running in an English locale

R is a collaborative project with many contributors.
Type 'contributors()' for more information and
'citation()' on how to cite R or R packages in publications.

Type 'demo()' for some demos, 'help()' for on-line help, or
'help.start()' for an HTML browser interface to help.
Type 'q()' to quit R.

> remotefunc <- function() {PEcAn.data.atmosphere::met2CF.Geostreams(lat=40.05691, lon=-88.193573, overwrite=FALSE, in.path='/home/a-m/black11/.pecan/dbfiles/Geostreams_site_8-4906', in.prefix='Clowder.UIUC Energy Farm - SE.2016-02-16.2016-09-24', outfolder='/home/a-m/black11/.pecan/dbfiles/Geostreams_CF_site_8-4906/', start_date='2016-01-01', end_date='2016-12-31')}
> remoteout <- remotefunc()
2017-05-23 10:22:17 SEVERE [PEcAn.data.atmosphere::met2CF.Geostreams] : 
   Requested start date is 1451606400 but 2016 data begin on 1455602400 
Error in logger.severe("Requested start date is", start_date, "but", year,  : 
  Requested start date is 2016-01-01 but 2016 data begin on 2016-02-16 06:00:00
Calls: remotefunc -> <Anonymous> -> logger.severe
Execution halted
[1] 1
Warning in file(tmpfile, "w") :
  cannot open file '/home/a-m/black11/.pecan/dbfiles/Geostreams_CF_site_8-4906//pecan-2c1014b10e96339b37af21799553f2': No such file or directory
Error in file(tmpfile, "w") : cannot open the connection
Calls: do.conversions ... .met2cf.module -> convert.input -> remote.execute.R -> file

[infotroph]

@mdietze I think you discussed this with me in Gitter shortly after I opened it, but now I can't grep up the conversation.

My memory is that we decided this is at least partly expected -- download.Geostreams is a remote call here and in general we don't always want a remote logger.severe to kill the workflow -- but I forget whether you thought this example was a bug. Close or fix?

[mdietze]

I think there's two separate bugs here to be fixed:

1) Both remote executions throw the same error -- that the requested data is before the start date. It seems like we should be catching that before calling the remote function (unless, in this case, the Input start date is coming from the remote source not from the database).

2) It's possible that some combination of convert.input or remote.execute.R is failing to detect that the remote workflow is throwing an error. Whether we decide that a given workflow should stop on severe or not, we need to at least make sure that remote error is detected and passed back to the part of the workflow that handles the "stop.on.error" flag. That flag should also be handled consistently -- if stop.on.error is FALSE then the workflow also needs to be tolerant to the 3rd error (the inability to open the file, which is what finally kills the workflow). Furthermore, it would be good to note that in the settings so that failure can be leveraged downstream -- there's no point in calling start.model.runs for a site or ensemble member whose input processing failed.

[robkooper]

I think the function download, should fail, and produce a zero byte file, which should trigger the main code to throw another sever to fail the call.

Thing I don't understand is that the call should not be remote, but should just call the function since the requested host, and current host both are the same.

[github-actions[bot]]

This issue is stale because it has been open 365 days with no activity.

[robkooper]

I believe there are some other issues related to this.

[infotroph]

My hunch is that the symptom in the title was fixed by #2489. Whether severe ought to have been thrown in the first place is probably still worth considering as part of a larger met robustness effort.

[github-actions[bot]]

This issue is stale because it has been open 365 days with no activity.