search

pytroll / pytroll-aapp-runner

Pytroll runner for AAPP
http://pytroll-aapp-runner.readthedocs.io/en/develop/
GNU General Public License v3.0
1 stars 8 forks source link

TLE archiving raises ValueError and copies to wrong directories #10

Closed gerritholl closed 3 years ago

gerritholl commented 3 years ago

Describe the bug

The AAPP runner on my system is failing to archive TLE files correctly. Subsequently, probably as a consequence, SATPOSTLE fails and processing stops. There are two issues:

To reproduce

It's a bit difficult to produce a MCVE for this case. On my system, this reproduces it:

import datetime
from satpy.utils import debug_on; debug_on()
import sys
from aapp_runner.tle_satpos_prepare import do_tleing
sys.path.insert(0, "/opt/pytroll/pytroll_inst/miniconda3/envs/pytroll-py38/bin/")
from aapp_dr_runner import AappL1Config

config = AappL1Config({'logging': {'log_rotation_days': 1, 'log_rotation_backup': 30, 'logging_mode': 'DEBUG'}, 'aapp_static_configuration': {'decommutation_files': {'avhrr_file': 'hrpt.l1b'}, 'supported_noaa_satellites': ['NOAA-18', 'NOAA-19'], 'supported_metop_satellites': ['Metop-C', 'Metop-B', 'Metop-A'], 'platform_name_aliases': {'NOAA-19': 'noaa19', 'NOAA-18': 'noaa18', 'Metop-A': 'metop02', 'Metop-B': 'metop01', 'Metop-C': 'metop03', 'METOP-A': 'metop02', 'METOP-B': 'metop01', 'METOP-C': 'metop03', 'METOP A': 'metop02', 'METOP B': 'metop01', 'METOP C': 'metop03', 'M01': 'metop01', 'M02': 'metop02', 'M03': 'metop03'}, 'satellite_sensor_name_aliases': {'avhrr': 'avhrr/3'}, 'tle_platform_name_aliases': {'NOAA-19': 'NOAA 19', 'noaa19': 'NOAA 19', 'NOAA-18': 'NOAA 18', 'Metop-A': 'METOP-A', 'Metop-B': 'METOP-B', 'Metop-C': 'METOP-C'}, 'sensor_name_converter': {'avhrr': 'avhrr/3', 'avhrr/3': 'avhrr'}}, 'aapp_processes': {'test': {'description': 'Test processing environment', 'name': 'test', 'subscribe_topics': ['/file/noaa/avhrr', '/cat/metop/avhrr'], 'tle_indir': '/data/pytroll/IN/TLE', 'tle_archive_dir': '{tle_indir:s}/archive/tle-{timestamp:%Y%m%d}', 'tle_infile_format': 'weather{timestamp:%Y%m%d%H%M}.tle', 'download_tle_files': False, 'tle_download': [{'url': 'http://www.celestrak.com/NORAD/elements/weather.txt'}, {'url': 'http://oiswww.eumetsat.org/metopTLEs/html/data_out/latest_m01_tle.txt'}], 'tle_file_to_data_diff_limit_days': 3, 'locktime_before_rerun': 10, 'publish_sift_format': '/aapp/avhrr', 'keep_orbit_number_from_message': True, 'aapp_prefix': '/opt/pytroll/AAPP', 'aapp_environment_file': 'ATOVS_ENV8', 'aapp_workdir': '/data/pytroll/TMP', 'working_dir': '/data/pytroll/TMP', 'use_dyn_work_dir': True, 'aapp_outdir_base': '/data/pytroll/OUTBOXES', 'aapp_outdir_format': '{satellite_name:s}_{start_time:%Y%m%d_%H%M}_{orbit_number:05d}', 'passlength_threshold': 5, 'aapp_log_files_archive_dir': '/opt/pytroll/pytroll_inst/log', 'aapp_log_outdir_format': '{satellite_name:s}_{start_time:%Y%m%d}_{start_time:%H%M}_{orbit_number:05d}', 'aapp_log_files_archive_length': 10, 'do_ana_correction': True, 'do_atovpp': False, 'do_avh2hirs': False, 'rename_aapp_compose': '{data_type:s}_{satellite_name:s}_{start_time:%Y%m%d}_{start_time:%H%M}_{orbit_number:5d}.{data_level:s}', 'rename_aapp_files': [{'avhrr': {'aapp_file': 'hrpt.l1b', 'data_type': 'hrpt', 'data_level': 'l1b'}}]}}, 'environment': 'test', 'station': 'unknown'}, "test")
do_tleing(config, datetime.datetime(2021, 1, 19, 14, 8, 26), "noaa19")

After running this, I have:

$ find /data/pytroll/IN/TLE/
/data/pytroll/IN/TLE/
/data/pytroll/IN/TLE/tle_noaa19.index
/data/pytroll/IN/TLE/weather202101160000.tle-0
/data/pytroll/IN/TLE/weather202101170000.tle-0
/data/pytroll/IN/TLE/weather202101180008.tle
/data/pytroll/IN/TLE/weather202101180325.tle
/data/pytroll/IN/TLE/weather202101190000.tle-0
/data/pytroll/IN/TLE/weather202101190616.tle
/data/pytroll/IN/TLE/archive
/data/pytroll/IN/TLE/archive/tle-20210119
/data/pytroll/IN/TLE/archive/tle-20210119/weather202101190616.tle
/data/pytroll/IN/TLE/archive/tle-1190616
/data/pytroll/IN/TLE/archive/tle-1190616/weather202101190616.tle
/data/pytroll/IN/TLE/archive/tle-20190616
/data/pytroll/IN/TLE/archive/tle-20190616/weather202101190616.tle
/data/pytroll/IN/TLE/tle_noaa18.index

Expected behaviour

I would expect that the TLE for 2021-01-19 06:16 gets copied to the directory tle-20210119. I'm not sure if I should expect anything for the older TLEs. Although this copying does happen, I expect that either the other TLEs are also copied, or nothing further gets copied and processing stops here.

Actual results

In reality, the aforementioned script results in:

[WARNING: 2021-01-19 16:12:10 : aapp_runner.tle_satpos_prepare] Override the env variable set in AAPP_ENV DIR_DATA_TLE from /opt/pytroll/AAPP/AAPP/orbelems/tle_db to /data/pytroll/IN/TLE.
[DEBUG: 2021-01-19 16:12:10 : aapp_runner.tle_satpos_prepare] tle file name: weather202101191408.tle
[DEBUG: 2021-01-19 16:12:10 : aapp_runner.tle_satpos_prepare] tle_search_dir /data/pytroll/IN/TLE/2021_01 does not exists.
[DEBUG: 2021-01-19 16:12:10 : aapp_runner.tle_satpos_prepare] tle_search_dir /data/pytroll/IN/TLE
[WARNING: 2021-01-19 16:12:10 : aapp_runner.tle_satpos_prepare] Could not find tle file: weather202101191408.tle. Try find closest ...
[DEBUG: 2021-01-19 16:12:10 : aapp_runner.tle_satpos_prepare] tle file list: ['/data/pytroll/IN/TLE/tle_noaa19.index', '/data/pytroll/IN/TLE/weather202101160000.tle-0', '/data/pytroll/IN/TLE/weather202101170000.tle-0', '/data/pytroll/IN/TLE/weather202101180008.tle', '/data/pytroll/IN/TLE/weather202101180325.tle', '/data/pytroll/IN/TLE/weather202101190000.tle-0', '/data/pytroll/IN/TLE/weather202101190616.tle', '/data/pytroll/IN/TLE/archive', '/data/pytroll/IN/TLE/tle_noaa18.index']
[DEBUG: 2021-01-19 16:12:10 : aapp_runner.tle_satpos_prepare] ['/data/pytroll/IN/TLE/tle_noaa19.index', '/data/pytroll/IN/TLE/weather202101160000.tle-0', '/data/pytroll/IN/TLE/weather202101170000.tle-0', '/data/pytroll/IN/TLE/weather202101180008.tle', '/data/pytroll/IN/TLE/weather202101180325.tle', '/data/pytroll/IN/TLE/weather202101190000.tle-0', '/data/pytroll/IN/TLE/weather202101190616.tle', '/data/pytroll/IN/TLE/archive', '/data/pytroll/IN/TLE/tle_noaa18.index']
[DEBUG: 2021-01-19 16:12:10 : aapp_runner.tle_satpos_prepare] /data/pytroll/IN/TLE/weather202101160000.tle-0 2021-01-16 00:00:00
[DEBUG: 2021-01-19 16:12:10 : aapp_runner.tle_satpos_prepare] /data/pytroll/IN/TLE/weather202101170000.tle-0 2021-01-17 00:00:00
[DEBUG: 2021-01-19 16:12:10 : aapp_runner.tle_satpos_prepare] Closest tle infile so far: /data/pytroll/IN/TLE/weather202101170000.tle-0
[DEBUG: 2021-01-19 16:12:10 : aapp_runner.tle_satpos_prepare] /data/pytroll/IN/TLE/weather202101180008.tle 2021-01-18 00:08:00
[DEBUG: 2021-01-19 16:12:10 : aapp_runner.tle_satpos_prepare] Closest tle infile so far: /data/pytroll/IN/TLE/weather202101180008.tle
[DEBUG: 2021-01-19 16:12:10 : aapp_runner.tle_satpos_prepare] /data/pytroll/IN/TLE/weather202101180325.tle 2021-01-18 03:25:00
[DEBUG: 2021-01-19 16:12:10 : aapp_runner.tle_satpos_prepare] Closest tle infile so far: /data/pytroll/IN/TLE/weather202101180325.tle
[DEBUG: 2021-01-19 16:12:10 : aapp_runner.tle_satpos_prepare] /data/pytroll/IN/TLE/weather202101180325.tle 0118-03-25 00:00:00
[DEBUG: 2021-01-19 16:12:10 : aapp_runner.tle_satpos_prepare] /data/pytroll/IN/TLE/weather202101180325.tle 2018-03-25 00:00:00
[DEBUG: 2021-01-19 16:12:10 : aapp_runner.tle_satpos_prepare] /data/pytroll/IN/TLE/weather202101190000.tle-0 2021-01-19 00:00:00
[DEBUG: 2021-01-19 16:12:10 : aapp_runner.tle_satpos_prepare] Closest tle infile so far: /data/pytroll/IN/TLE/weather202101190000.tle-0
[DEBUG: 2021-01-19 16:12:10 : aapp_runner.tle_satpos_prepare] /data/pytroll/IN/TLE/weather202101190616.tle 2021-01-19 06:16:00
[DEBUG: 2021-01-19 16:12:10 : aapp_runner.tle_satpos_prepare] Closest tle infile so far: /data/pytroll/IN/TLE/weather202101190616.tle
[DEBUG: 2021-01-19 16:12:10 : aapp_runner.tle_satpos_prepare] /data/pytroll/IN/TLE/weather202101190616.tle 0119-06-16 00:00:00
[DEBUG: 2021-01-19 16:12:10 : aapp_runner.tle_satpos_prepare] /data/pytroll/IN/TLE/weather202101190616.tle 2019-06-16 00:00:00
[DEBUG: 2021-01-19 16:12:10 : aapp_runner.tle_satpos_prepare] Use this: ['/data/pytroll/IN/TLE/weather202101190616.tle'] offset 28346.0s
[DEBUG: 2021-01-19 16:12:10 : aapp_runner.tle_satpos_prepare] stdin arguments to command: /data/pytroll/IN/TLE
weather202101190616.tle
noaa19
/data/pytroll/IN/TLE/tle_noaa19.index

[DEBUG: 2021-01-19 16:12:10 : aapp_runner.helper_functions] Command sequence= ['tleing.exe']
[DEBUG: 2021-01-19 16:12:10 : aapp_runner.helper_functions] Process pid: 31972
[DEBUG: 2021-01-19 16:12:10 : aapp_runner.helper_functions] Before call to communicate:
[DEBUG: 2021-01-19 16:12:10 : aapp_runner.helper_functions] communicate complete
[DEBUG: 2021-01-19 16:12:10 : aapp_runner.helper_functions] > 2021/01/19 16:12:10 oflks333.dwd.de 31972 tleing.exe INFO : Ingests tle /data/pytroll/IN/TLE/weather202101190616.tle
[DEBUG: 2021-01-19 16:12:10 : aapp_runner.helper_functions] > 2021/01/19 16:12:10 oflks333.dwd.de 31972 tleing.exe INFO : Satellite noaa19
[DEBUG: 2021-01-19 16:12:10 : aapp_runner.helper_functions] > 2021/01/19 16:12:10 oflks333.dwd.de 31972 tleing.exe WARNING : No valid TLE before the current one
[DEBUG: 2021-01-19 16:12:10 : aapp_runner.tle_satpos_prepare] Running command: tleing.exe with return code: 0
[DEBUG: 2021-01-19 16:12:10 : aapp_runner.tle_satpos_prepare] stdout:
[DEBUG: 2021-01-19 16:12:10 : aapp_runner.tle_satpos_prepare] stderr: > 2021/01/19 16:12:10 oflks333.dwd.de 31972 tleing.exe INFO : Ingests tle /data/pytroll/IN/TLE/weather202101190616.tle
> 2021/01/19 16:12:10 oflks333.dwd.de 31972 tleing.exe INFO : Satellite noaa19
> 2021/01/19 16:12:10 oflks333.dwd.de 31972 tleing.exe WARNING : No valid TLE before the current one

[DEBUG: 2021-01-19 16:12:10 : aapp_runner.tle_satpos_prepare] DIR_DATA_TLE : /data/pytroll/IN/TLE
[DEBUG: 2021-01-19 16:12:10 : aapp_runner.tle_satpos_prepare] tle_file : weather202101190616.tle
[DEBUG: 2021-01-19 16:12:10 : aapp_runner.tle_satpos_prepare] satellite : noaa19
[DEBUG: 2021-01-19 16:12:10 : aapp_runner.tle_satpos_prepare] TLE_INDEX : /data/pytroll/IN/TLE/tle_noaa19.index
[DEBUG: 2021-01-19 16:12:10 : aapp_runner.helper_functions] Command sequence= ['sort', '-u', '+0b', '-3b', '/data/pytroll/IN/TLE/tle_noaa19.index']
[DEBUG: 2021-01-19 16:12:10 : aapp_runner.helper_functions] Process pid: 31973
[DEBUG: 2021-01-19 16:12:10 : aapp_runner.helper_functions] Before call to communicate:
[DEBUG: 2021-01-19 16:12:10 : aapp_runner.helper_functions] communicate complete
[DEBUG: 2021-01-19 16:12:10 : aapp_runner.helper_functions] Command sequence= ['grep', '-v', 'NaN', '/data/pytroll/IN/TLE/tle_noaa19.index.sort1']
[DEBUG: 2021-01-19 16:12:10 : aapp_runner.helper_functions] Process pid: 31974
[DEBUG: 2021-01-19 16:12:10 : aapp_runner.helper_functions] Before call to communicate:
[DEBUG: 2021-01-19 16:12:10 : aapp_runner.helper_functions] communicate complete
[DEBUG: 2021-01-19 16:12:10 : aapp_runner.tle_satpos_prepare] Copied /data/pytroll/IN/TLE/weather202101190616.tle to /data/pytroll/IN/TLE/archive/tle-20210119.
[ERROR: 2021-01-19 16:12:10 : aapp_runner.tle_satpos_prepare] Failed in archive step...
Traceback (most recent call last):
  File "/opt/pytroll/pytroll_inst/miniconda3/envs/pytroll-py38/lib/python3.8/site-packages/aapp_runner/tle_satpos_prepare.py", line 451, in do_tleing
    archive_dict['timestamp'] = test(m)
  File "/opt/pytroll/pytroll_inst/miniconda3/envs/pytroll-py38/lib/python3.8/site-packages/aapp_runner/tle_satpos_prepare.py", line 56, in _do_4_matches
    return datetime.strptime(m.group(1) + m.group(2) + m.group(3) + m.group(4), "%Y%m%d%H")
  File "/opt/pytroll/pytroll_inst/miniconda3/envs/pytroll-py38/lib/python3.8/_strptime.py", line 568, in _strptime_datetime
    tt, fraction, gmtoff_fraction = _strptime(data_string, format)
  File "/opt/pytroll/pytroll_inst/miniconda3/envs/pytroll-py38/lib/python3.8/_strptime.py", line 352, in _strptime
    raise ValueError("unconverted data remains: %s" %
ValueError: unconverted data remains: 16
[DEBUG: 2021-01-19 16:12:10 : aapp_runner.tle_satpos_prepare] Copied /data/pytroll/IN/TLE/weather202101190616.tle to /data/pytroll/IN/TLE/archive/tle-20210119.
[DEBUG: 2021-01-19 16:12:10 : aapp_runner.tle_satpos_prepare] Copied /data/pytroll/IN/TLE/weather202101190616.tle to /data/pytroll/IN/TLE/archive/tle-1190616.
[DEBUG: 2021-01-19 16:12:10 : aapp_runner.tle_satpos_prepare] Copied /data/pytroll/IN/TLE/weather202101190616.tle to /data/pytroll/IN/TLE/archive/tle-20190616.

with files being copied to where I don't expect them.

Subsequently, further AAPP processing fails:

[INFO: 2021-01-19 16:01:19 : aapp_runner.tle_satpos_prepare] satpos files is stored under the dir_navigation/satpos
[DEBUG: 2021-01-19 16:01:19 : aapp_runner.helper_functions] Command sequence= ['satpostle', '-o', '-s', 'noaa19', '-d', '19/01/21', '-n', '1.2']
[DEBUG: 2021-01-19 16:01:19 : aapp_runner.helper_functions] Process pid: 13597
[DEBUG: 2021-01-19 16:01:19 : aapp_runner.helper_functions] Before call to communicate:
[DEBUG: 2021-01-19 16:01:19 : aapp_runner.helper_functions] communicate complete
[DEBUG: 2021-01-19 16:01:19 : aapp_runner.helper_functions] > 2021/01/19 16:01:19 oflks333.dwd.de 13600 satpostle.exe INFO : SATPOSTLE start
[DEBUG: 2021-01-19 16:01:19 : aapp_runner.helper_functions] > 2021/01/19 16:01:19 oflks333.dwd.de 13600 satpostle.exe INFO : SATPOSTLE for satellite noaa19
[DEBUG: 2021-01-19 16:01:19 : aapp_runner.helper_functions] > 2021/01/19 16:01:19 oflks333.dwd.de 13600 satpostle.exe ERROR : NO tle file available for the date19/01/21  00:00:00.000
[DEBUG: 2021-01-19 16:01:19 : aapp_runner.helper_functions] > 2021/01/19 16:01:19 oflks333.dwd.de 13600 satpostle.exe ERROR : return code of tle_gnv/tle_glpv :        1
[DEBUG: 2021-01-19 16:01:19 : aapp_runner.helper_functions] > 2021/01/19 16:01:19 oflks333.dwd.de 13600 satpostle.exe ERROR : SATPOSTLE aborted
[ERROR: 2021-01-19 16:01:19 : aapp_runner.tle_satpos_prepare] cmd: satpostle -o -s noaa19 -d 19/01/21 -n 1.2 failed with returncode: 1
[WARNING: 2021-01-19 16:01:19 : aapp_runner] Tle satpos failed for some reason. It might be that the processing can continue
[WARNING: 2021-01-19 16:01:19 : aapp_runner] Please check the previous log carefully to see if this is an error you can accept.
[ERROR: 2021-01-19 16:01:19 : aapp_runner] The satpos failed: 'Tle satpos failed for some reason'
Traceback (most recent call last):
  File "/opt/pytroll/pytroll_inst/miniconda3/envs/pytroll-py38/bin/aapp_dr_runner.py", line 892, in process_aapp
    raise SatposError("Tle satpos failed for some reason")
aapp_runner.exceptions.SatposError: 'Tle satpos failed for some reason'
[ERROR: 2021-01-19 16:01:19 : aapp_runner] AAPP processing failed.

Additional context

It's possible that there is something wrong in my configuration. The relevant part is probably:

    # Sift format of your TLE file archive
    tle_archive_dir: '{tle_indir:s}/archive/tle-{timestamp:%Y%m%d%H%M}'
    # Sift format of your TLE files
    tle_infile_format: 'weather{timestamp:%Y%m%d%H%M}.tle'

I don't understand why this leads to the observed behaviour, though.

gerritholl commented 3 years ago

Related: #2

gerritholl commented 3 years ago

The problem here appears to lie in the archival strategy. As currently implemented, for each matching regex it creates a copy and for each regex that matches but can't be decomposed as desired it logs an exception:

https://github.com/pytroll/pytroll-aapp-runner/blob/d8064976be9f4dd8ef0247ed86e62e9c5efa8125/aapp_runner/tle_satpos_prepare.py#L446-L470

that means that I'm not even sure anymore if the exception I'm seeing is the cause of the later AAPP problem I'm having, but it does explain why I get several spurious directories, which clutters up the archive and is confusing.

I'm not sure how I can safely fix this without risking breaking compatibility.