Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

TLE archiving raises ValueError and copies to wrong directories #10

Closed
gerritholl opened this issue Jan 19, 2021 · 2 comments · Fixed by #11
Closed

TLE archiving raises ValueError and copies to wrong directories #10

gerritholl opened this issue Jan 19, 2021 · 2 comments · Fixed by #11

Comments

@gerritholl
Copy link
Member

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:

  • The same TLE file gets copied to three different directories, only one which is correct, and
  • A ValueError is raised due to "unconverted data"

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
Copy link
Member Author

Related: #2

@gerritholl gerritholl mentioned this issue Jan 19, 2021
Open
gerritholl added a commit to gerritholl/pytroll-aapp-runner that referenced this issue Jan 19, 2021
@gerritholl
Added test reproducing TLE valueerror
95bc4aa 
Added a test case that reproduces the TLE ValueError as reported in pytroll#10.
Since this appears to be the first test case, also adapt .travis.yml to
run this test with pytest, and update the Python version to the modern
era.
@gerritholl gerritholl mentioned this issue Jan 19, 2021
Merged
3 tasks
@gerritholl
Copy link
Member Author

gerritholl commented Jan 20, 2021 •
edited
Loading

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:

pytroll-aapp-runner/aapp_runner/tle_satpos_prepare.py

Lines 446 to 470 in d806497

for tle_file_name in tle_file_list:
for regex, test in tle_match_tests:
m = re.match(regex, tle_file_name)
if m:
try:
archive_dict['timestamp'] = test(m)
tle_archive_dir = compose(
config['aapp_processes'][config.process_name]['tle_archive_dir'], archive_dict)
if not os.path.exists(tle_archive_dir):
try:
os.makedirs(tle_archive_dir)
except:
LOG.error("Failed to make archive dir: {}".format(tle_archive_dir))
except ValueError:
LOG.exception('Failed in archive step...')
pass
try:
copy(tle_file_name, tle_archive_dir)
LOG.debug("Copied {} to {}.".format(tle_file_name, tle_archive_dir))
archive = False
except IOError as ioe:
LOG.error("Failed to copy TLE file: {} to archive: {} because {}".format(
tle_file_name, tle_archive_dir, ioe))
LOG.error("CWD: {}".format(os.getcwd()))

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.

gerritholl added a commit to gerritholl/pytroll-aapp-runner that referenced this issue Jan 20, 2021
@gerritholl
Make sure we only copy TLE archive file once
253d3af 
Make sure we only copy a TLE file to a single archive directory.
Fixes pytroll#10.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

Copy TLE file to archive at most once gerritholl/pytroll-aapp-runner
1 participant
@gerritholl