search

Open-EO / openeo-geopyspark-driver

OpenEO driver for GeoPySpark (Geotrellis)
Apache License 2.0
26 stars 4 forks source link

check if shub caching system is effectively used on openeo-dev #149

Closed jdries closed 2 years ago

bossie commented 2 years ago

Found this typo in the baremetal entrypoint.sh script:

export CACHE_SHUB_BATCH_RESULSTS=$cache_shub_batch_results
bossie commented 2 years ago

Correcting the typo enabled the caching but missing AWS environment variables prevent it from working:

[2022-04-22 12:26:35,373] ERROR in openeo_driver.views: An error occurred while calling o1598.start_batch_process_cached.
: software.amazon.awssdk.core.exception.SdkClientException: Unable to load region from any of the providers in the chain software.amazon.awssdk.regions.providers.DefaultAwsRegionProviderChain@3d793d27: [software
.amazon.awssdk.regions.providers.SystemSettingsRegionProvider@600c3623: Unable to load region from system settings. Region must be specified either via environment variable (AWS_REGION) or  system property (aws.
region)., software.amazon.awssdk.regions.providers.AwsProfileRegionProvider@7eaf41ee: No region provided in profile: default, software.amazon.awssdk.regions.providers.InstanceProfileRegionProvider@7602b838: Unab
le to contact EC2 metadata service.]
        at software.amazon.awssdk.core.exception.SdkClientException$BuilderImpl.build(SdkClientException.java:98)
        at software.amazon.awssdk.regions.providers.AwsRegionProviderChain.getRegion(AwsRegionProviderChain.java:70)
        at software.amazon.awssdk.awscore.client.builder.AwsDefaultClientBuilder.regionFromDefaultProvider(AwsDefaultClientBuilder.java:202)
        at software.amazon.awssdk.awscore.client.builder.AwsDefaultClientBuilder.resolveRegion(AwsDefaultClientBuilder.java:184)
        at software.amazon.awssdk.awscore.client.builder.AwsDefaultClientBuilder.finalizeChildConfiguration(AwsDefaultClientBuilder.java:135)
        at software.amazon.awssdk.core.client.builder.SdkDefaultClientBuilder.syncClientConfiguration(SdkDefaultClientBuilder.java:154)
        at software.amazon.awssdk.services.s3.DefaultS3ClientBuilder.buildClient(DefaultS3ClientBuilder.java:27)
        at software.amazon.awssdk.services.s3.DefaultS3ClientBuilder.buildClient(DefaultS3ClientBuilder.java:22)
        at software.amazon.awssdk.core.client.builder.SdkDefaultClientBuilder.build(SdkDefaultClientBuilder.java:126)
        at org.openeo.geotrellissentinelhub.package$S3$.withClient(package.scala:94)
        at org.openeo.geotrellissentinelhub.package$S3$.withClient(package.scala:102)
        at org.openeo.geotrellissentinelhub.S3BatchProcessContextRepository.saveTo(S3BatchProcessContextRepository.scala:10)
        at org.openeo.geotrellissentinelhub.Sentinel2L2AInitialCacheOperation.saveInitialBatchProcessContext(InitialCacheOperation.scala:202)
        at org.openeo.geotrellissentinelhub.AbstractInitialCacheOperation.startBatchProcess(InitialCacheOperation.scala:91)
        at org.openeo.geotrellissentinelhub.BatchProcessingService.start_batch_process_cached(BatchProcessingService.scala:133)
        at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.base/java.lang.reflect.Method.invoke(Method.java:566)
        at py4j.reflection.MethodInvoker.invoke(MethodInvoker.java:244)
        at py4j.reflection.ReflectionEngine.invoke(ReflectionEngine.java:357)
        at py4j.Gateway.invoke(Gateway.java:282)
        at py4j.commands.AbstractCommand.invokeMethod(AbstractCommand.java:132)
        at py4j.commands.CallCommand.execute(CallCommand.java:79)
        at py4j.ClientServerConnection.waitForCommands(ClientServerConnection.java:182)
        at py4j.ClientServerConnection.run(ClientServerConnection.java:106)
        at java.base/java.lang.Thread.run(Thread.java:829)
Traceback (most recent call last):
  File "/opt/venv/lib64/python3.8/site-packages/flask/app.py", line 1516, in full_dispatch_request
    rv = self.dispatch_request()
  File "/opt/venv/lib64/python3.8/site-packages/flask/app.py", line 1502, in dispatch_request
    return self.ensure_sync(self.view_functions[rule.endpoint])(**req.view_args)
  File "/opt/venv/lib64/python3.8/site-packages/openeo_driver/users/auth.py", line 88, in decorated
    return f(*args, **kwargs)
  File "/opt/venv/lib64/python3.8/site-packages/openeo_driver/views.py", line 799, in queue_job
    backend_implementation.batch_jobs.start_job(job_id=job_id, user=user)
  File "/opt/venv/lib64/python3.8/site-packages/openeogeotrellis/backend.py", line 873, in start_job
    self._start_job(job_id, user.user_id)
  File "/opt/venv/lib64/python3.8/site-packages/openeogeotrellis/backend.py", line 901, in _start_job
    and self._scheduled_sentinelhub_batch_processes(spec['process_graph'], api_version, registry,
  File "/opt/venv/lib64/python3.8/site-packages/openeogeotrellis/backend.py", line 1333, in _scheduled_sentinelhub_batch_processes
    batch_request_id = batch_processing_service.start_batch_process_cached(
  File "/usr/local/spark/python/lib/py4j-0.10.9.2-src.zip/py4j/java_gateway.py", line 1309, in __call__
    return_value = get_return_value(
  File "/usr/local/spark/python/lib/py4j-0.10.9.2-src.zip/py4j/protocol.py", line 326, in get_return_value
    raise Py4JJavaError(
py4j.protocol.Py4JJavaError: An error occurred while calling o1598.start_batch_process_cached.
: software.amazon.awssdk.core.exception.SdkClientException: Unable to load region from any of the providers in the chain software.amazon.awssdk.regions.providers.DefaultAwsRegionProviderChain@3d793d27: [software.amazon.awssdk.regions.providers.SystemSettingsRegionProvider@600c3623: Unable to load region from system settings. Region must be specified either via environment variable (AWS_REGION) or  system property (aws.region)., software.amazon.awssdk.regions.providers.AwsProfileRegionProvider@7eaf41ee: No region provided in profile: default, software.amazon.awssdk.regions.providers.InstanceProfileRegionProvider@7602b838: Unable to contact EC2 metadata service.]
        at software.amazon.awssdk.core.exception.SdkClientException$BuilderImpl.build(SdkClientException.java:98)
        at software.amazon.awssdk.regions.providers.AwsRegionProviderChain.getRegion(AwsRegionProviderChain.java:70)
        at software.amazon.awssdk.awscore.client.builder.AwsDefaultClientBuilder.regionFromDefaultProvider(AwsDefaultClientBuilder.java:202)
        at software.amazon.awssdk.awscore.client.builder.AwsDefaultClientBuilder.resolveRegion(AwsDefaultClientBuilder.java:184)
        at software.amazon.awssdk.awscore.client.builder.AwsDefaultClientBuilder.finalizeChildConfiguration(AwsDefaultClientBuilder.java:135)
        at software.amazon.awssdk.core.client.builder.SdkDefaultClientBuilder.syncClientConfiguration(SdkDefaultClientBuilder.java:154)
        at software.amazon.awssdk.services.s3.DefaultS3ClientBuilder.buildClient(DefaultS3ClientBuilder.java:27)
        at software.amazon.awssdk.services.s3.DefaultS3ClientBuilder.buildClient(DefaultS3ClientBuilder.java:22)
        at software.amazon.awssdk.core.client.builder.SdkDefaultClientBuilder.build(SdkDefaultClientBuilder.java:126)
        at org.openeo.geotrellissentinelhub.package$S3$.withClient(package.scala:94)
        at org.openeo.geotrellissentinelhub.package$S3$.withClient(package.scala:102)
        at org.openeo.geotrellissentinelhub.S3BatchProcessContextRepository.saveTo(S3BatchProcessContextRepository.scala:10)
        at org.openeo.geotrellissentinelhub.Sentinel2L2AInitialCacheOperation.saveInitialBatchProcessContext(InitialCacheOperation.scala:202)
        at org.openeo.geotrellissentinelhub.AbstractInitialCacheOperation.startBatchProcess(InitialCacheOperation.scala:91)
        at org.openeo.geotrellissentinelhub.BatchProcessingService.start_batch_process_cached(BatchProcessingService.scala:133)
        at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.base/java.lang.reflect.Method.invoke(Method.java:566)
        at py4j.reflection.MethodInvoker.invoke(MethodInvoker.java:244)
        at py4j.reflection.ReflectionEngine.invoke(ReflectionEngine.java:357)
        at py4j.Gateway.invoke(Gateway.java:282)
        at py4j.commands.AbstractCommand.invokeMethod(AbstractCommand.java:132)
        at py4j.commands.CallCommand.execute(CallCommand.java:79)
        at py4j.ClientServerConnection.waitForCommands(ClientServerConnection.java:182)
        at py4j.ClientServerConnection.run(ClientServerConnection.java:106)
        at java.base/java.lang.Thread.run(Thread.java:829)
bossie commented 2 years ago

Include:

https://jira.vito.be/browse/EP-4018 https://jira.vito.be/browse/EP-4091

bossie commented 2 years ago

Test case:

    large_polygon = Polygon.from_bounds(2.640329849675133, 49.745440618122501, 3.297496358117944, 50.317367956014152)
    center_point = large_polygon.centroid

    geometries = GeometryCollection([large_polygon, center_point])

    data_cube = (auth_connection.load_collection('SENTINEL2_L2A_SENTINELHUB', bands=["B04", "B03", "B02"])
                 .filter_temporal(extent=["2019-09-26", "2019-09-26"])
                 .aggregate_spatial(geometries, "mean"))

    job = data_cube.execute_batch()

Ran it two times and compared the logs in /var/log/openeo/openeo-driver-746f3dc938bd.stdout on epod-openeo-dev.vgt.vito.be.

Logs for batch job 8426777d-aeac-441c-a015-679af5ba1dbb show that for this request, nothing's in the cache yet so it schedules a SHub batch process:

[2022-04-25 09:30:23,745] INFO in openeo_driver.views: Handling POST https://openeo-dev.vito.be/openeo/1.1.0/jobs/8426777d-aeac-441c-a015-679af5ba1dbb/results?_origin=openeo-geopyspark-integrationtests%2Ftest_point_timeseries_from_batch_process%5B1.1.0%5D with data b''
[2022-04-25 09:30:23,745] INFO in openeo_driver.util.logging: <class 'openeo_driver.util.logging.UserIdLogging'> storing user id vdboschj on <flask.g of 'openeo_driver.views'>
[2022-04-25 09:30:23,752] INFO in kazoo.client: Connecting to epod-master2.vgt.vito.be(192.168.207.57):2181, use_ssl: False
[2022-04-25 09:30:23,759] INFO in kazoo.client: Zookeeper connection established, state: CONNECTED
[2022-04-25 09:30:23,765] INFO in kazoo.client: Closing connection to epod-master2.vgt.vito.be:2181
[2022-04-25 09:30:23,765] INFO in kazoo.client: Zookeeper session closed, state: CLOSED
[2022-04-25 09:30:23,772] INFO in kazoo.client: Connecting to epod-master1.vgt.vito.be(192.168.207.56):2181, use_ssl: False
[2022-04-25 09:30:23,776] INFO in kazoo.client: Zookeeper connection established, state: CONNECTED
[2022-04-25 09:30:23,777] DEBUG in openeogeotrellis.backend: job_options: {}
[2022-04-25 09:30:23,783] INFO in kazoo.client: Connecting to epod-master3.vgt.vito.be(192.168.207.58):2181, use_ssl: False
[2022-04-25 09:30:23,793] INFO in kazoo.client: Zookeeper connection established, state: CONNECTED
[2022-04-25 09:30:23,805] INFO in kazoo.client: Closing connection to epod-master3.vgt.vito.be:2181
[2022-04-25 09:30:23,805] INFO in kazoo.client: Zookeeper session closed, state: CLOSED
[2022-04-25 09:30:23,805] INFO in openeogeotrellis.layercatalog: Reading layer catalog metadata from layercatalog.json
[2022-04-25 09:30:23,807] INFO in openeogeotrellis.layercatalog: Updating S1_GRD_SIGMA0_ASCENDING metadata from https://services.terrascope.be/catalogue:urn:eop:VITO:CGS_S1_GRD_SIGMA0_L1
[2022-04-25 09:30:23,808] INFO in openeogeotrellis.opensearch: Getting collection metadata from https://services.terrascope.be/catalogue/collections
[2022-04-25 09:30:23,933] INFO in openeogeotrellis.layercatalog: Updating S1_GRD_SIGMA0_DESCENDING metadata from https://services.terrascope.be/catalogue:urn:eop:VITO:CGS_S1_GRD_SIGMA0_L1
[2022-04-25 09:30:23,933] INFO in openeogeotrellis.layercatalog: Updating TERRASCOPE_S2_FAPAR_V2 metadata from https://services.terrascope.be/catalogue:urn:eop:VITO:TERRASCOPE_S2_FAPAR_V2
[2022-04-25 09:30:23,933] INFO in openeogeotrellis.layercatalog: Updating TERRASCOPE_S2_NDVI_V2 metadata from https://services.terrascope.be/catalogue:urn:eop:VITO:TERRASCOPE_S2_NDVI_V2
[2022-04-25 09:30:23,934] INFO in openeogeotrellis.layercatalog: Updating TERRASCOPE_S2_LAI_V2 metadata from https://services.terrascope.be/catalogue:urn:eop:VITO:TERRASCOPE_S2_LAI_V2
[2022-04-25 09:30:23,934] INFO in openeogeotrellis.layercatalog: Updating TERRASCOPE_S2_FCOVER_V2 metadata from https://services.terrascope.be/catalogue:urn:eop:VITO:TERRASCOPE_S2_FCOVER_V2
[2022-04-25 09:30:23,934] INFO in openeogeotrellis.layercatalog: Updating TERRASCOPE_S2_TOC_V2 metadata from https://services.terrascope.be/catalogue:urn:eop:VITO:TERRASCOPE_S2_TOC_V2
[2022-04-25 09:30:23,935] INFO in openeogeotrellis.layercatalog: Updating TERRASCOPE_S1_SLC_COHERENCE_V1 metadata from https://services.terrascope.be/catalogue:urn:eop:VITO:TERRASCOPE_S1_SLC_COHERENCE_V1
[2022-04-25 09:30:25,960] INFO in openeogeotrellis.layercatalog: Updating SENTINEL1_GAMMA0_SENTINELHUB metadata from https://collections.eurodatacube.com/stac/index.json:sentinel-1-grd
[2022-04-25 09:30:25,960] INFO in openeogeotrellis.layercatalog: Updating SENTINEL1_GRD metadata from https://collections.eurodatacube.com/stac/index.json:sentinel-1-grd
[2022-04-25 09:30:25,960] INFO in openeogeotrellis.layercatalog: Updating SENTINEL2_L1C_SENTINELHUB metadata from https://collections.eurodatacube.com/stac/index.json:sentinel-2-l1c
[2022-04-25 09:30:25,960] INFO in openeogeotrellis.layercatalog: Updating SENTINEL2_L2A_SENTINELHUB metadata from https://collections.eurodatacube.com/stac/index.json:sentinel-2-l2a
[2022-04-25 09:30:25,960] INFO in openeogeotrellis.layercatalog: Updating SENTINEL2_L2A_MOSAIC_120 metadata from https://collections.eurodatacube.com/stac/index.json:sentinel-s2-l2a-mosaic-120
[2022-04-25 09:30:25,960] INFO in openeogeotrellis.layercatalog: Updating PROBAV_L3_S10_TOC_333M metadata from https://services.terrascope.be/catalogue:urn:ogc:def:EOP:VITO:PROBAV_S10-TOC_333M_V001
[2022-04-25 09:30:25,961] INFO in openeogeotrellis.layercatalog: Updating PROBAV_L3_S5_TOC_100M metadata from https://services.terrascope.be/catalogue:urn:ogc:def:EOP:VITO:PROBAV_S5-TOC_100M_V001
[2022-04-25 09:30:25,961] INFO in openeogeotrellis.layercatalog: Updating TERRASCOPE_S5P_L3_NO2_TD_V1 metadata from https://services.terrascope.be/catalogue:urn:eop:VITO:TERRASCOPE_S5P_L3_NO2_TD_V1
[2022-04-25 09:30:25,961] INFO in openeogeotrellis.layercatalog: Updating TERRASCOPE_S5P_L3_NO2_TM_V1 metadata from https://services.terrascope.be/catalogue:urn:eop:VITO:TERRASCOPE_S5P_L3_NO2_TM_V1
[2022-04-25 09:30:25,961] INFO in openeogeotrellis.layercatalog: Updating TERRASCOPE_S5P_L3_NO2_TY_V1 metadata from https://services.terrascope.be/catalogue:urn:eop:VITO:TERRASCOPE_S5P_L3_NO2_TY_V1
[2022-04-25 09:30:25,962] INFO in openeogeotrellis.layercatalog: Updating TERRASCOPE_S5P_L3_CO_TD_V1 metadata from https://services.terrascope.be/catalogue:urn:eop:VITO:TERRASCOPE_S5P_L3_CO_TD_V1
[2022-04-25 09:30:25,962] INFO in openeogeotrellis.layercatalog: Updating TERRASCOPE_S5P_L3_CO_TM_V1 metadata from https://services.terrascope.be/catalogue:urn:eop:VITO:TERRASCOPE_S5P_L3_CO_TM_V1
[2022-04-25 09:30:25,962] INFO in openeogeotrellis.layercatalog: Updating TERRASCOPE_S5P_L3_CO_TY_V1 metadata from https://services.terrascope.be/catalogue:urn:eop:VITO:TERRASCOPE_S5P_L3_CO_TY_V1
[2022-04-25 09:30:25,962] INFO in openeogeotrellis.layercatalog: Updating LANDSAT8_L1 metadata from https://collections.eurodatacube.com/stac/index.json:landsat-8-l1
[2022-04-25 09:30:25,963] INFO in openeogeotrellis.layercatalog: Updating LANDSAT8-9_L1 metadata from https://collections.eurodatacube.com/stac/index.json:landsat-8-l1
[2022-04-25 09:30:25,963] INFO in openeogeotrellis.layercatalog: Updating LANDSAT8_L2 metadata from https://collections.eurodatacube.com/stac/index.json:landsat-8-l2
[2022-04-25 09:30:25,963] INFO in openeogeotrellis.layercatalog: Updating LANDSAT8-9_L2 metadata from https://collections.eurodatacube.com/stac/index.json:landsat-8-l2
[2022-04-25 09:30:25,963] INFO in openeogeotrellis.layercatalog: Updating LANDSAT4-5_TM_L1 metadata from https://collections.eurodatacube.com/stac/index.json:landsat-4-5-tm-l1
[2022-04-25 09:30:25,963] INFO in openeogeotrellis.layercatalog: Updating LANDSAT4-5_TM_L2 metadata from https://collections.eurodatacube.com/stac/index.json:landsat-4-5-tm-l2
[2022-04-25 09:30:25,963] INFO in openeogeotrellis.layercatalog: Updating LANDSAT7_ETM_L1 metadata from https://collections.eurodatacube.com/stac/index.json:landsat-7-etm+-l1
[2022-04-25 09:30:25,963] INFO in openeogeotrellis.layercatalog: Updating LANDSAT7_ETM_L2 metadata from https://collections.eurodatacube.com/stac/index.json:landsat-7-etm+-l2
[2022-04-25 09:30:25,963] INFO in openeogeotrellis.layercatalog: Updating MODIS metadata from https://collections.eurodatacube.com/stac/index.json:modis
[2022-04-25 09:30:25,963] INFO in openeogeotrellis.layercatalog: Updating SENTINEL3_OLCI_L1B metadata from https://collections.eurodatacube.com/stac/index.json:sentinel-3-l1b-olci
[2022-04-25 09:30:25,963] INFO in openeogeotrellis.layercatalog: Updating SENTINEL3_SLSTR metadata from https://collections.eurodatacube.com/stac/index.json:sentinel-3-l1b-slstr
[2022-04-25 09:30:25,964] INFO in openeogeotrellis.layercatalog: Updating COPERNICUS_30 metadata from https://services.terrascope.be/catalogue:urn:eop:VITO:COP_DEM_GLO_30M_COG
[2022-04-25 09:30:25,964] INFO in openeogeotrellis.layercatalog: Updating COPERNICUS_90 metadata from https://services.terrascope.be/catalogue:urn:eop:VITO:COP_DEM_GLO_90M_COG
[2022-04-25 09:30:25,964] INFO in openeogeotrellis.layercatalog: Updating TERRASCOPE_S2_RHOW_V1 metadata from https://services.terrascope.be/catalogue:urn:eop:VITO:TERRASCOPE_S2_RHOW_V1
[2022-04-25 09:30:25,965] INFO in openeogeotrellis.layercatalog: Updating TERRASCOPE_S2_CHL_V1 metadata from https://services.terrascope.be/catalogue:urn:eop:VITO:TERRASCOPE_S2_CHL_V1
[2022-04-25 09:30:25,965] INFO in openeogeotrellis.layercatalog: Updating TERRASCOPE_S2_SPM_V1 metadata from https://services.terrascope.be/catalogue:urn:eop:VITO:TERRASCOPE_S2_SPM_V1
[2022-04-25 09:30:25,965] INFO in openeogeotrellis.layercatalog: Updating TERRASCOPE_S2_TUR_V1 metadata from https://services.terrascope.be/catalogue:urn:eop:VITO:TERRASCOPE_S2_TUR_V1
[2022-04-25 09:30:25,966] INFO in openeogeotrellis.layercatalog: Updating ESA_WORLDCOVER_10M_2020_V1 metadata from https://services.terrascope.be/catalogue:urn:eop:VITO:ESA_WorldCover_10m_2020_V1
[2022-04-25 09:30:25,966] INFO in openeogeotrellis.layercatalog: Updating CORINE_LAND_COVER metadata from https://collections.eurodatacube.com/stac/index.json:corine-land-cover
[2022-04-25 09:30:25,966] INFO in openeogeotrellis.layercatalog: Updating CORINE_LAND_COVER_ACCOUNTING_LAYERS metadata from https://collections.eurodatacube.com/stac/index.json:corine-land-cover-accounting-layers
[2022-04-25 09:30:25,966] INFO in openeogeotrellis.layercatalog: Updating GHS_BUILT_S2 metadata from https://collections.eurodatacube.com/stac/index.json:global-human-settlement-layer-ghs-built-s2
[2022-04-25 09:30:25,966] INFO in openeogeotrellis.layercatalog: Updating GLOBAL_LAND_COVER metadata from https://collections.eurodatacube.com/stac/index.json:global-land-cover
[2022-04-25 09:30:25,966] INFO in openeogeotrellis.layercatalog: Updating GLOBAL_SURFACE_WATER metadata from https://collections.eurodatacube.com/stac/index.json:global-surface-water
[2022-04-25 09:30:25,966] INFO in openeogeotrellis.layercatalog: Updating POPULATION_DENSITY metadata from https://collections.eurodatacube.com/stac/index.json:population_density
[2022-04-25 09:30:25,966] INFO in openeogeotrellis.layercatalog: Updating SEA_ICE_INDEX metadata from https://collections.eurodatacube.com/stac/index.json:sea-ice-index
[2022-04-25 09:30:25,967] INFO in openeogeotrellis.layercatalog: Updating SENTINEL_5P_L2 metadata from https://collections.eurodatacube.com/stac/index.json:sentinel-5p-l2-tropomi
[2022-04-25 09:30:25,967] INFO in openeogeotrellis.layercatalog: Updating MAPZEN_DEM metadata from https://collections.eurodatacube.com/stac/index.json:mapzen-dem
[2022-04-25 09:30:25,967] INFO in openeogeotrellis.layercatalog: Updating LANDSAT1-5_MSS_L1 metadata from https://collections.eurodatacube.com/stac/index.json:landsat-1-5-mss-l1
[2022-04-25 09:30:25,967] INFO in openeogeotrellis.layercatalog: Updating WATER_BODIES metadata from https://collections.eurodatacube.com/stac/index.json:water-bodies
[2022-04-25 09:30:25,967] INFO in openeogeotrellis.layercatalog: Updating SENTINEL1_CARD4L metadata from https://collections.eurodatacube.com/stac/index.json:card4l
[2022-04-25 09:30:25,967] INFO in openeogeotrellis.layercatalog: Updating VEGETATION_INDICES metadata from https://collections.eurodatacube.com/stac/index.json:vegetation-indices
[2022-04-25 09:30:25,967] INFO in openeogeotrellis.layercatalog: Updating SEASONAL_TRAJECTORIES metadata from https://collections.eurodatacube.com/stac/index.json:seasonal-trajectories
[2022-04-25 09:30:25,967] INFO in openeogeotrellis.layercatalog: Updating VEGETATION_PHENOLOGY_AND_PRODUCTIVITY_PARAMETERS_SEASON_1 metadata from https://collections.eurodatacube.com/stac/index.json:vegetation-phenology-and-productivity-parameters-season-1
[2022-04-25 09:30:25,967] INFO in openeogeotrellis.layercatalog: Updating VEGETATION_PHENOLOGY_AND_PRODUCTIVITY_PARAMETERS_SEASON_2 metadata from https://collections.eurodatacube.com/stac/index.json:vegetation-phenology-and-productivity-parameters-season-2
[2022-04-25 09:30:25,968] DEBUG in openeogeotrellis.layercatalog: Creating merged collections for common names: {'SENTINEL2_L2A'}
[2022-04-25 09:30:26,008] INFO in kazoo.client: Connecting to epod-master3.vgt.vito.be(192.168.207.58):2181, use_ssl: False
[2022-04-25 09:30:26,016] INFO in kazoo.client: Zookeeper connection established, state: CONNECTED
[2022-04-25 09:30:26,023] INFO in kazoo.client: Closing connection to epod-master3.vgt.vito.be:2181
[2022-04-25 09:30:26,023] INFO in kazoo.client: Zookeeper session closed, state: CLOSED
[2022-04-25 09:30:26,024] INFO in openeo_driver.ProcessGraphDeserializer: Using process 'load_collection' from namespace 'backend'.
[2022-04-25 09:30:26,036] INFO in kazoo.client: Connecting to epod-master3.vgt.vito.be(192.168.207.58):2181, use_ssl: False
[2022-04-25 09:30:26,040] INFO in kazoo.client: Zookeeper connection established, state: CONNECTED
[2022-04-25 09:30:26,046] INFO in kazoo.client: Closing connection to epod-master3.vgt.vito.be:2181
[2022-04-25 09:30:26,046] INFO in kazoo.client: Zookeeper session closed, state: CLOSED
[2022-04-25 09:30:26,046] INFO in openeo_driver.ProcessGraphDeserializer: Using process 'filter_temporal' from namespace 'backend'.
[2022-04-25 09:30:26,054] INFO in kazoo.client: Connecting to epod-master2.vgt.vito.be(192.168.207.57):2181, use_ssl: False
[2022-04-25 09:30:26,062] INFO in kazoo.client: Zookeeper connection established, state: CONNECTED
[2022-04-25 09:30:26,068] INFO in kazoo.client: Closing connection to epod-master2.vgt.vito.be:2181
[2022-04-25 09:30:26,068] INFO in kazoo.client: Zookeeper session closed, state: CLOSED
[2022-04-25 09:30:26,068] INFO in openeo_driver.ProcessGraphDeserializer: Using process 'aggregate_spatial' from namespace 'backend'.
[2022-04-25 09:30:26,211] INFO in openeogeotrellis.backend: Dry run extracted these source constraints: [(('load_collection', ('SENTINEL2_L2A_SENTINELHUB', ())), {'temporal_extent': ('2019-09-26', '2019-09-26'), 'bands': ['B04', 'B03', 'B02'], 'aggregate_spatial': {'geometries': <shapely.geometry.collection.GeometryCollection object at 0x7fcc72ad5fd0>}, 'spatial_extent': {'west': 2.640329849675133, 'south': 49.7454406181225, 'east': 3.297496358117944, 'north': 50.31736795601415, 'crs': 'EPSG:4326'}})]
/opt/venv/lib64/python3.8/site-packages/pyproj/crs/crs.py:280: FutureWarning: '+init=<authority>:<code>' syntax is deprecated. '<authority>:<code>' is the preferred initialization method. When making the change, be mindful of axis order changes: https://pyproj4.github.io/pyproj/stable/gotchas.html#axis-order-changes-in-proj-6
  projstring = _prepare_from_string(projparams)
/opt/venv/lib64/python3.8/site-packages/pyproj/crs/crs.py:280: FutureWarning: '+init=<authority>:<code>' syntax is deprecated. '<authority>:<code>' is the preferred initialization method. When making the change, be mindful of axis order changes: https://pyproj4.github.io/pyproj/stable/gotchas.html#axis-order-changes-in-proj-6
  projstring = _prepare_from_string(projparams)
[2022-04-25 09:30:26,507] INFO in openeogeotrellis.backend: deemed collection SENTINEL2_L2A_SENTINELHUB AOI (2995296911.3364363 m²) large enough for batch processing (threshold 2500000000 m²)
22/04/25 09:30:28 DEBUG geotrellissentinelhub.Sentinel2L2AInitialCacheOperation: expecting 126 tiles for the initial request
22/04/25 09:30:29 DEBUG geotrellissentinelhub.Sentinel2L2AInitialCacheOperation: 126 tiles are not in the cache
22/04/25 09:30:30 DEBUG geotrellissentinelhub.MemoizedRlGuardAdapterCachedAccessTokenWithAuthApiFallbackAuthorizer: Zookeeper access token for client ID b667f624-3330-4bb8-a69e-6b0700d518a7 expires at 2022-04-25
T09:16:05Z: invalid
22/04/25 09:30:30 DEBUG geotrellissentinelhub.AuthApi: requesting new access token for client ID b667f624-3330-4bb8-a69e-6b0700d518a7
22/04/25 09:30:31 DEBUG geotrellissentinelhub.MemoizedRlGuardAdapterCachedAccessTokenWithAuthApiFallbackAuthorizer: Auth API access token for clientID b667f624-3330-4bb8-a69e-6b0700d518a7 expires within PT59M59S
22/04/25 09:30:31 DEBUG geotrellissentinelhub.AccessTokenCache$: access token that expires within PT59M59S is scheduled for eviction from the cache within 1483882 milliseconds
[2022-04-25 09:30:31,343] DEBUG in openeogeotrellis.backend: start_batch_process_cached(subfolder=1107b38a-84e0-4166-bd90-b63066518a19, collecting_folder=/tmp_epod/openeo_collecting/1107b38a-84e0-4166-bd90-b6306
6518a19) returned batch_request_id f53f8f9a-d721-4dfc-a57e-aa96b80eeb39
[2022-04-25 09:30:31,343] INFO in openeogeotrellis.backend: scheduled Sentinel Hub batch process(es) ['f53f8f9a-d721-4dfc-a57e-aa96b80eeb39'] for batch job 8426777d-aeac-441c-a015-679af5ba1dbb (CARD4L disabled)
[2022-04-25 09:30:31,357] INFO in kafka.conn: <BrokerConnection node_id=bootstrap-2 host=epod-master1.vgt.vito.be:6668 <connecting> [IPv4 ('192.168.207.56', 6668)]>: connecting to epod-master1.vgt.vito.be:6668 [
('192.168.207.56', 6668) IPv4]
[2022-04-25 09:30:31,357] INFO in kafka.conn: Probing node bootstrap-2 broker version
[2022-04-25 09:30:31,361] INFO in kafka.conn: <BrokerConnection node_id=bootstrap-2 host=epod-master1.vgt.vito.be:6668 <connecting> [IPv4 ('192.168.207.56', 6668)]>: Connection complete.
[2022-04-25 09:30:31,462] INFO in kafka.conn: Broker version identifed as 1.0.0
[2022-04-25 09:30:31,463] INFO in kafka.conn: Set configuration api_version=(1, 0, 0) to skip auto check_version requests on startup
[2022-04-25 09:30:31,469] INFO in kafka.conn: <BrokerConnection node_id=1005 host=epod-master1.vgt.vito.be:6668 <connecting> [IPv4 ('192.168.207.56', 6668)]>: connecting to epod-master1.vgt.vito.be:6668 [('192.1
68.207.56', 6668) IPv4]
[2022-04-25 09:30:31,470] INFO in kafka.conn: <BrokerConnection node_id=1005 host=epod-master1.vgt.vito.be:6668 <connecting> [IPv4 ('192.168.207.56', 6668)]>: Connection complete.
[2022-04-25 09:30:31,470] INFO in kafka.conn: <BrokerConnection node_id=bootstrap-2 host=epod-master1.vgt.vito.be:6668 <connected> [IPv4 ('192.168.207.56', 6668)]>: Closing connection. 
[2022-04-25 09:30:31,473] INFO in openeogeotrellis.async_task: scheduled task {"task_id": "poll_sentinelhub_batch_processes", "arguments": {"batch_job_id": "8426777d-aeac-441c-a015-679af5ba1dbb", "user_id": "vdb
oschj"}} on env dev
[2022-04-25 09:30:31,473] INFO in kafka.producer.kafka: Closing the Kafka producer with 9223372036.0 secs timeout.
[2022-04-25 09:30:31,473] INFO in kafka.conn: <BrokerConnection node_id=1005 host=epod-master1.vgt.vito.be:6668 <connected> [IPv4 ('192.168.207.56', 6668)]>: Closing connection. 
[2022-04-25 09:30:31,473] INFO in kafka.producer.kafka: Kafka producer closed
[2022-04-25 09:30:31,493] DEBUG in openeogeotrellis.job_registry: batch job 8426777d-aeac-441c-a015-679af5ba1dbb dependency -> awaiting
[2022-04-25 09:30:31,503] DEBUG in openeogeotrellis.job_registry: batch job 8426777d-aeac-441c-a015-679af5ba1dbb -> queued

Identical batch job 9de7b408-50fd-4eaf-a4fd-9800cdec1ec7, on the other hand, shows that now everything is in the cache, so it doesn't schedule additional SHub batch processes but instead uses the tiles in the cache:

[2022-04-25 09:48:15,286] INFO in openeo_driver.views: Handling POST https://openeo-dev.vito.be/openeo/1.1.0/jobs/9de7b408-50fd-4eaf-a4fd-9800cdec1ec7/results?_origin=openeo-geopyspark-integrationtests%2Ftest_point_timeseries_from_batch_process%5B1.1.0%5D with data b''
[2022-04-25 09:48:15,286] INFO in openeo_driver.util.logging: <class 'openeo_driver.util.logging.UserIdLogging'> storing user id vdboschj on <flask.g of 'openeo_driver.views'>
[2022-04-25 09:48:15,293] INFO in kazoo.client: Connecting to epod-master3.vgt.vito.be(192.168.207.58):2181, use_ssl: False
[2022-04-25 09:48:15,304] INFO in kazoo.client: Zookeeper connection established, state: CONNECTED
[2022-04-25 09:48:15,311] INFO in kazoo.client: Closing connection to epod-master3.vgt.vito.be:2181
[2022-04-25 09:48:15,311] INFO in kazoo.client: Zookeeper session closed, state: CLOSED
[2022-04-25 09:48:15,319] INFO in kazoo.client: Connecting to epod-master1.vgt.vito.be(192.168.207.56):2181, use_ssl: False
[2022-04-25 09:48:15,325] INFO in kazoo.client: Zookeeper connection established, state: CONNECTED
[2022-04-25 09:48:15,325] DEBUG in openeogeotrellis.backend: job_options: {}
[2022-04-25 09:48:15,333] INFO in kazoo.client: Connecting to epod-master2.vgt.vito.be(192.168.207.57):2181, use_ssl: False
[2022-04-25 09:48:15,340] INFO in kazoo.client: Zookeeper connection established, state: CONNECTED
[2022-04-25 09:48:15,345] INFO in kazoo.client: Closing connection to epod-master2.vgt.vito.be:2181
[2022-04-25 09:48:15,346] INFO in kazoo.client: Zookeeper session closed, state: CLOSED
[2022-04-25 09:48:15,346] INFO in openeogeotrellis.layercatalog: Reading layer catalog metadata from layercatalog.json
[2022-04-25 09:48:15,348] INFO in openeogeotrellis.layercatalog: Updating S1_GRD_SIGMA0_ASCENDING metadata from https://services.terrascope.be/catalogue:urn:eop:VITO:CGS_S1_GRD_SIGMA0_L1
[2022-04-25 09:48:15,348] INFO in openeogeotrellis.opensearch: Getting collection metadata from https://services.terrascope.be/catalogue/collections
[2022-04-25 09:48:15,847] INFO in openeogeotrellis.layercatalog: Updating S1_GRD_SIGMA0_DESCENDING metadata from https://services.terrascope.be/catalogue:urn:eop:VITO:CGS_S1_GRD_SIGMA0_L1
[2022-04-25 09:48:15,847] INFO in openeogeotrellis.layercatalog: Updating TERRASCOPE_S2_FAPAR_V2 metadata from https://services.terrascope.be/catalogue:urn:eop:VITO:TERRASCOPE_S2_FAPAR_V2
[2022-04-25 09:48:15,848] INFO in openeogeotrellis.layercatalog: Updating TERRASCOPE_S2_NDVI_V2 metadata from https://services.terrascope.be/catalogue:urn:eop:VITO:TERRASCOPE_S2_NDVI_V2
[2022-04-25 09:48:15,848] INFO in openeogeotrellis.layercatalog: Updating TERRASCOPE_S2_LAI_V2 metadata from https://services.terrascope.be/catalogue:urn:eop:VITO:TERRASCOPE_S2_LAI_V2
[2022-04-25 09:48:15,848] INFO in openeogeotrellis.layercatalog: Updating TERRASCOPE_S2_FCOVER_V2 metadata from https://services.terrascope.be/catalogue:urn:eop:VITO:TERRASCOPE_S2_FCOVER_V2
[2022-04-25 09:48:15,849] INFO in openeogeotrellis.layercatalog: Updating TERRASCOPE_S2_TOC_V2 metadata from https://services.terrascope.be/catalogue:urn:eop:VITO:TERRASCOPE_S2_TOC_V2
[2022-04-25 09:48:15,849] INFO in openeogeotrellis.layercatalog: Updating TERRASCOPE_S1_SLC_COHERENCE_V1 metadata from https://services.terrascope.be/catalogue:urn:eop:VITO:TERRASCOPE_S1_SLC_COHERENCE_V1
[2022-04-25 09:48:17,639] INFO in openeogeotrellis.layercatalog: Updating SENTINEL1_GAMMA0_SENTINELHUB metadata from https://collections.eurodatacube.com/stac/index.json:sentinel-1-grd
[2022-04-25 09:48:17,639] INFO in openeogeotrellis.layercatalog: Updating SENTINEL1_GRD metadata from https://collections.eurodatacube.com/stac/index.json:sentinel-1-grd
[2022-04-25 09:48:17,639] INFO in openeogeotrellis.layercatalog: Updating SENTINEL2_L1C_SENTINELHUB metadata from https://collections.eurodatacube.com/stac/index.json:sentinel-2-l1c
[2022-04-25 09:48:17,639] INFO in openeogeotrellis.layercatalog: Updating SENTINEL2_L2A_SENTINELHUB metadata from https://collections.eurodatacube.com/stac/index.json:sentinel-2-l2a
[2022-04-25 09:48:17,639] INFO in openeogeotrellis.layercatalog: Updating SENTINEL2_L2A_MOSAIC_120 metadata from https://collections.eurodatacube.com/stac/index.json:sentinel-s2-l2a-mosaic-120
[2022-04-25 09:48:17,640] INFO in openeogeotrellis.layercatalog: Updating PROBAV_L3_S10_TOC_333M metadata from https://services.terrascope.be/catalogue:urn:ogc:def:EOP:VITO:PROBAV_S10-TOC_333M_V001
[2022-04-25 09:48:17,640] INFO in openeogeotrellis.layercatalog: Updating PROBAV_L3_S5_TOC_100M metadata from https://services.terrascope.be/catalogue:urn:ogc:def:EOP:VITO:PROBAV_S5-TOC_100M_V001
[2022-04-25 09:48:17,640] INFO in openeogeotrellis.layercatalog: Updating TERRASCOPE_S5P_L3_NO2_TD_V1 metadata from https://services.terrascope.be/catalogue:urn:eop:VITO:TERRASCOPE_S5P_L3_NO2_TD_V1
[2022-04-25 09:48:17,640] INFO in openeogeotrellis.layercatalog: Updating TERRASCOPE_S5P_L3_NO2_TM_V1 metadata from https://services.terrascope.be/catalogue:urn:eop:VITO:TERRASCOPE_S5P_L3_NO2_TM_V1
[2022-04-25 09:48:17,641] INFO in openeogeotrellis.layercatalog: Updating TERRASCOPE_S5P_L3_NO2_TY_V1 metadata from https://services.terrascope.be/catalogue:urn:eop:VITO:TERRASCOPE_S5P_L3_NO2_TY_V1
[2022-04-25 09:48:17,641] INFO in openeogeotrellis.layercatalog: Updating TERRASCOPE_S5P_L3_CO_TD_V1 metadata from https://services.terrascope.be/catalogue:urn:eop:VITO:TERRASCOPE_S5P_L3_CO_TD_V1
[2022-04-25 09:48:17,641] INFO in openeogeotrellis.layercatalog: Updating TERRASCOPE_S5P_L3_CO_TM_V1 metadata from https://services.terrascope.be/catalogue:urn:eop:VITO:TERRASCOPE_S5P_L3_CO_TM_V1
[2022-04-25 09:48:17,642] INFO in openeogeotrellis.layercatalog: Updating TERRASCOPE_S5P_L3_CO_TY_V1 metadata from https://services.terrascope.be/catalogue:urn:eop:VITO:TERRASCOPE_S5P_L3_CO_TY_V1
[2022-04-25 09:48:17,642] INFO in openeogeotrellis.layercatalog: Updating LANDSAT8_L1 metadata from https://collections.eurodatacube.com/stac/index.json:landsat-8-l1
[2022-04-25 09:48:17,642] INFO in openeogeotrellis.layercatalog: Updating LANDSAT8-9_L1 metadata from https://collections.eurodatacube.com/stac/index.json:landsat-8-l1
[2022-04-25 09:48:17,642] INFO in openeogeotrellis.layercatalog: Updating LANDSAT8_L2 metadata from https://collections.eurodatacube.com/stac/index.json:landsat-8-l2
[2022-04-25 09:48:17,642] INFO in openeogeotrellis.layercatalog: Updating LANDSAT8-9_L2 metadata from https://collections.eurodatacube.com/stac/index.json:landsat-8-l2
[2022-04-25 09:48:17,642] INFO in openeogeotrellis.layercatalog: Updating LANDSAT4-5_TM_L1 metadata from https://collections.eurodatacube.com/stac/index.json:landsat-4-5-tm-l1
[2022-04-25 09:48:17,642] INFO in openeogeotrellis.layercatalog: Updating LANDSAT4-5_TM_L2 metadata from https://collections.eurodatacube.com/stac/index.json:landsat-4-5-tm-l2
[2022-04-25 09:48:17,642] INFO in openeogeotrellis.layercatalog: Updating LANDSAT7_ETM_L1 metadata from https://collections.eurodatacube.com/stac/index.json:landsat-7-etm+-l1
[2022-04-25 09:48:17,643] INFO in openeogeotrellis.layercatalog: Updating LANDSAT7_ETM_L2 metadata from https://collections.eurodatacube.com/stac/index.json:landsat-7-etm+-l2
[2022-04-25 09:48:17,643] INFO in openeogeotrellis.layercatalog: Updating MODIS metadata from https://collections.eurodatacube.com/stac/index.json:modis
[2022-04-25 09:48:17,643] INFO in openeogeotrellis.layercatalog: Updating SENTINEL3_OLCI_L1B metadata from https://collections.eurodatacube.com/stac/index.json:sentinel-3-l1b-olci
[2022-04-25 09:48:17,643] INFO in openeogeotrellis.layercatalog: Updating SENTINEL3_SLSTR metadata from https://collections.eurodatacube.com/stac/index.json:sentinel-3-l1b-slstr
[2022-04-25 09:48:17,643] INFO in openeogeotrellis.layercatalog: Updating COPERNICUS_30 metadata from https://services.terrascope.be/catalogue:urn:eop:VITO:COP_DEM_GLO_30M_COG
[2022-04-25 09:48:17,643] INFO in openeogeotrellis.layercatalog: Updating COPERNICUS_90 metadata from https://services.terrascope.be/catalogue:urn:eop:VITO:COP_DEM_GLO_90M_COG
[2022-04-25 09:48:17,644] INFO in openeogeotrellis.layercatalog: Updating TERRASCOPE_S2_RHOW_V1 metadata from https://services.terrascope.be/catalogue:urn:eop:VITO:TERRASCOPE_S2_RHOW_V1
[2022-04-25 09:48:17,644] INFO in openeogeotrellis.layercatalog: Updating TERRASCOPE_S2_CHL_V1 metadata from https://services.terrascope.be/catalogue:urn:eop:VITO:TERRASCOPE_S2_CHL_V1
[2022-04-25 09:48:17,644] INFO in openeogeotrellis.layercatalog: Updating TERRASCOPE_S2_SPM_V1 metadata from https://services.terrascope.be/catalogue:urn:eop:VITO:TERRASCOPE_S2_SPM_V1
[2022-04-25 09:48:17,645] INFO in openeogeotrellis.layercatalog: Updating TERRASCOPE_S2_TUR_V1 metadata from https://services.terrascope.be/catalogue:urn:eop:VITO:TERRASCOPE_S2_TUR_V1
[2022-04-25 09:48:17,645] INFO in openeogeotrellis.layercatalog: Updating ESA_WORLDCOVER_10M_2020_V1 metadata from https://services.terrascope.be/catalogue:urn:eop:VITO:ESA_WorldCover_10m_2020_V1
[2022-04-25 09:48:17,645] INFO in openeogeotrellis.layercatalog: Updating CORINE_LAND_COVER metadata from https://collections.eurodatacube.com/stac/index.json:corine-land-cover
[2022-04-25 09:48:17,645] INFO in openeogeotrellis.layercatalog: Updating CORINE_LAND_COVER_ACCOUNTING_LAYERS metadata from https://collections.eurodatacube.com/stac/index.json:corine-land-cover-accounting-layers
[2022-04-25 09:48:17,646] INFO in openeogeotrellis.layercatalog: Updating GHS_BUILT_S2 metadata from https://collections.eurodatacube.com/stac/index.json:global-human-settlement-layer-ghs-built-s2
[2022-04-25 09:48:17,646] INFO in openeogeotrellis.layercatalog: Updating GLOBAL_LAND_COVER metadata from https://collections.eurodatacube.com/stac/index.json:global-land-cover
[2022-04-25 09:48:17,646] INFO in openeogeotrellis.layercatalog: Updating GLOBAL_SURFACE_WATER metadata from https://collections.eurodatacube.com/stac/index.json:global-surface-water
[2022-04-25 09:48:17,646] INFO in openeogeotrellis.layercatalog: Updating POPULATION_DENSITY metadata from https://collections.eurodatacube.com/stac/index.json:population_density
[2022-04-25 09:48:17,646] INFO in openeogeotrellis.layercatalog: Updating SEA_ICE_INDEX metadata from https://collections.eurodatacube.com/stac/index.json:sea-ice-index
[2022-04-25 09:48:17,646] INFO in openeogeotrellis.layercatalog: Updating SENTINEL_5P_L2 metadata from https://collections.eurodatacube.com/stac/index.json:sentinel-5p-l2-tropomi
[2022-04-25 09:48:17,646] INFO in openeogeotrellis.layercatalog: Updating MAPZEN_DEM metadata from https://collections.eurodatacube.com/stac/index.json:mapzen-dem
[2022-04-25 09:48:17,646] INFO in openeogeotrellis.layercatalog: Updating LANDSAT1-5_MSS_L1 metadata from https://collections.eurodatacube.com/stac/index.json:landsat-1-5-mss-l1
[2022-04-25 09:48:17,646] INFO in openeogeotrellis.layercatalog: Updating WATER_BODIES metadata from https://collections.eurodatacube.com/stac/index.json:water-bodies
[2022-04-25 09:48:17,646] INFO in openeogeotrellis.layercatalog: Updating SENTINEL1_CARD4L metadata from https://collections.eurodatacube.com/stac/index.json:card4l
[2022-04-25 09:48:17,646] INFO in openeogeotrellis.layercatalog: Updating VEGETATION_INDICES metadata from https://collections.eurodatacube.com/stac/index.json:vegetation-indices
[2022-04-25 09:48:17,646] INFO in openeogeotrellis.layercatalog: Updating SEASONAL_TRAJECTORIES metadata from https://collections.eurodatacube.com/stac/index.json:seasonal-trajectories
[2022-04-25 09:48:17,647] INFO in openeogeotrellis.layercatalog: Updating VEGETATION_PHENOLOGY_AND_PRODUCTIVITY_PARAMETERS_SEASON_1 metadata from https://collections.eurodatacube.com/stac/index.json:vegetation-phenology-and-productivity-parameters-season-1
[2022-04-25 09:48:17,647] INFO in openeogeotrellis.layercatalog: Updating VEGETATION_PHENOLOGY_AND_PRODUCTIVITY_PARAMETERS_SEASON_2 metadata from https://collections.eurodatacube.com/stac/index.json:vegetation-phenology-and-productivity-parameters-season-2
[2022-04-25 09:48:17,648] DEBUG in openeogeotrellis.layercatalog: Creating merged collections for common names: {'SENTINEL2_L2A'}
[2022-04-25 09:48:17,688] INFO in kazoo.client: Connecting to epod-master3.vgt.vito.be(192.168.207.58):2181, use_ssl: False
[2022-04-25 09:48:17,700] INFO in kazoo.client: Zookeeper connection established, state: CONNECTED
[2022-04-25 09:48:17,705] INFO in kazoo.client: Closing connection to epod-master3.vgt.vito.be:2181
[2022-04-25 09:48:17,705] INFO in kazoo.client: Zookeeper session closed, state: CLOSED
[2022-04-25 09:48:17,706] INFO in openeo_driver.ProcessGraphDeserializer: Using process 'load_collection' from namespace 'backend'.
[2022-04-25 09:48:17,712] INFO in kazoo.client: Connecting to epod-master1.vgt.vito.be(192.168.207.56):2181, use_ssl: False
[2022-04-25 09:48:17,719] INFO in kazoo.client: Zookeeper connection established, state: CONNECTED
[2022-04-25 09:48:17,725] INFO in kazoo.client: Closing connection to epod-master1.vgt.vito.be:2181
[2022-04-25 09:48:17,725] INFO in kazoo.client: Zookeeper session closed, state: CLOSED
[2022-04-25 09:48:17,725] INFO in openeo_driver.ProcessGraphDeserializer: Using process 'filter_temporal' from namespace 'backend'.
[2022-04-25 09:48:17,732] INFO in kazoo.client: Connecting to epod-master2.vgt.vito.be(192.168.207.57):2181, use_ssl: False
[2022-04-25 09:48:17,740] INFO in kazoo.client: Zookeeper connection established, state: CONNECTED
[2022-04-25 09:48:17,747] INFO in kazoo.client: Closing connection to epod-master2.vgt.vito.be:2181
[2022-04-25 09:48:17,748] INFO in kazoo.client: Zookeeper session closed, state: CLOSED
[2022-04-25 09:48:17,748] INFO in openeo_driver.ProcessGraphDeserializer: Using process 'aggregate_spatial' from namespace 'backend'.
[2022-04-25 09:48:17,892] INFO in openeogeotrellis.backend: Dry run extracted these source constraints: [(('load_collection', ('SENTINEL2_L2A_SENTINELHUB', ())), {'temporal_extent': ('2019-09-26', '2019-09-26'), 'bands': ['B04', 'B03', 'B02'], 'aggregate_spatial': {'geometries': <shapely.geometry.collection.GeometryCollection object at 0x7fcc725f6190>}, 'spatial_extent': {'west': 2.640329849675133, 'south': 49.7454406181225, 'east': 3.297496358117944, 'north': 50.31736795601415, 'crs': 'EPSG:4326'}})]
/opt/venv/lib64/python3.8/site-packages/pyproj/crs/crs.py:280: FutureWarning: '+init=<authority>:<code>' syntax is deprecated. '<authority>:<code>' is the preferred initialization method. When making the change, be mindful of axis order changes: https://pyproj4.github.io/pyproj/stable/gotchas.html#axis-order-changes-in-proj-6
  projstring = _prepare_from_string(projparams)
/opt/venv/lib64/python3.8/site-packages/pyproj/crs/crs.py:280: FutureWarning: '+init=<authority>:<code>' syntax is deprecated. '<authority>:<code>' is the preferred initialization method. When making the change, be mindful of axis order changes: https://pyproj4.github.io/pyproj/stable/gotchas.html#axis-order-changes-in-proj-6
  projstring = _prepare_from_string(projparams)
[2022-04-25 09:48:18,188] INFO in openeogeotrellis.backend: deemed collection SENTINEL2_L2A_SENTINELHUB AOI (2995296911.3364363 m²) large enough for batch processing (threshold 2500000000 m²)
22/04/25 09:48:19 DEBUG geotrellissentinelhub.Sentinel2L2AInitialCacheOperation: expecting 126 tiles for the initial request
22/04/25 09:48:19 DEBUG geotrellissentinelhub.Sentinel2L2AInitialCacheOperation: symlinked cached file from the distant past: /tmp_epod/openeo_collecting/c3990ba1-c1f7-4d7a-9c90-32fffcb360eb/20190926-31UDR_9_7-B04.tif -> /data/projects/OpenEO/sentinel-hub-s2l2a-cache/20190926/31UDR_9_7/B04.tif
22/04/25 09:48:19 DEBUG geotrellissentinelhub.Sentinel2L2AInitialCacheOperation: symlinked cached file from the distant past: /tmp_epod/openeo_collecting/c3990ba1-c1f7-4d7a-9c90-32fffcb360eb/20190926-31UDR_9_7-B03.tif -> /data/projects/OpenEO/sentinel-hub-s2l2a-cache/20190926/31UDR_9_7/B03.tif
22/04/25 09:48:19 DEBUG geotrellissentinelhub.Sentinel2L2AInitialCacheOperation: symlinked cached file from the distant past: /tmp_epod/openeo_collecting/c3990ba1-c1f7-4d7a-9c90-32fffcb360eb/20190926-31UDR_9_7-B02.tif -> /data/projects/OpenEO/sentinel-hub-s2l2a-cache/20190926/31UDR_9_7/B02.tif
22/04/25 09:48:19 DEBUG geotrellissentinelhub.Sentinel2L2AInitialCacheOperation: symlinked cached file from the distant past: /tmp_epod/openeo_collecting/c3990ba1-c1f7-4d7a-9c90-32fffcb360eb/20190926-31UER_0_4-B04.tif -> /data/projects/OpenEO/sentinel-hub-s2l2a-cache/20190926/31UER_0_4/B04.tif
22/04/25 09:48:19 DEBUG geotrellissentinelhub.Sentinel2L2AInitialCacheOperation: symlinked cached file from the distant past: /tmp_epod/openeo_collecting/c3990ba1-c1f7-4d7a-9c90-32fffcb360eb/20190926-31UER_0_4-B03.tif -> /data/projects/OpenEO/sentinel-hub-s2l2a-cache/20190926/31UER_0_4/B03.tif
22/04/25 09:48:19 DEBUG geotrellissentinelhub.Sentinel2L2AInitialCacheOperation: symlinked cached file from the distant past: /tmp_epod/openeo_collecting/c3990ba1-c1f7-4d7a-9c90-32fffcb360eb/20190926-31UER_0_4-B02.tif -> /data/projects/OpenEO/sentinel-hub-s2l2a-cache/20190926/31UER_0_4/B02.tif
22/04/25 09:48:19 DEBUG geotrellissentinelhub.Sentinel2L2AInitialCacheOperation: symlinked cached file from the distant past: /tmp_epod/openeo_collecting/c3990ba1-c1f7-4d7a-9c90-32fffcb360eb/20190926-31UDR_8_8-B04.tif -> /data/projects/OpenEO/sentinel-hub-s2l2a-cache/20190926/31UDR_8_8/B04.tif
22/04/25 09:48:19 DEBUG geotrellissentinelhub.Sentinel2L2AInitialCacheOperation: symlinked cached file from the distant past: /tmp_epod/openeo_collecting/c3990ba1-c1f7-4d7a-9c90-32fffcb360eb/20190926-31UDR_8_8-B03.tif -> /data/projects/OpenEO/sentinel-hub-s2l2a-cache/20190926/31UDR_8_8/B03.tif
22/04/25 09:48:19 DEBUG geotrellissentinelhub.Sentinel2L2AInitialCacheOperation: symlinked cached file from the distant past: /tmp_epod/openeo_collecting/c3990ba1-c1f7-4d7a-9c90-32fffcb360eb/20190926-31UDR_8_8-B02.tif -> /data/projects/OpenEO/sentinel-hub-s2l2a-cache/20190926/31UDR_8_8/B02.tif
22/04/25 09:48:19 DEBUG geotrellissentinelhub.Sentinel2L2AInitialCacheOperation: symlinked cached file from the distant past: /tmp_epod/openeo_collecting/c3990ba1-c1f7-4d7a-9c90-32fffcb360eb/20190926-31UDR_9_4-B04.tif -> /data/projects/OpenEO/sentinel-hub-s2l2a-cache/20190926/31UDR_9_4/B04.tif
22/04/25 09:48:19 DEBUG geotrellissentinelhub.Sentinel2L2AInitialCacheOperation: symlinked cached file from the distant past: /tmp_epod/openeo_collecting/c3990ba1-c1f7-4d7a-9c90-32fffcb360eb/20190926-31UDR_9_4-B03.tif -> /data/projects/OpenEO/sentinel-hub-s2l2a-cache/20190926/31UDR_9_4/B03.tif
22/04/25 09:48:19 DEBUG geotrellissentinelhub.Sentinel2L2AInitialCacheOperation: symlinked cached file from the distant past: /tmp_epod/openeo_collecting/c3990ba1-c1f7-4d7a-9c90-32fffcb360eb/20190926-31UDR_9_4-B02.tif -> /data/projects/OpenEO/sentinel-hub-s2l2a-cache/20190926/31UDR_9_4/B02.tif
22/04/25 09:48:19 DEBUG geotrellissentinelhub.Sentinel2L2AInitialCacheOperation: symlinked cached file from the distant past: /tmp_epod/openeo_collecting/c3990ba1-c1f7-4d7a-9c90-32fffcb360eb/20190926-31UER_0_3-B04.tif -> /data/projects/OpenEO/sentinel-hub-s2l2a-cache/20190926/31UER_0_3/B04.tif
22/04/25 09:48:19 DEBUG geotrellissentinelhub.Sentinel2L2AInitialCacheOperation: symlinked cached file from the distant past: /tmp_epod/openeo_collecting/c3990ba1-c1f7-4d7a-9c90-32fffcb360eb/20190926-31UER_0_3-B03.tif -> /data/projects/OpenEO/sentinel-hub-s2l2a-cache/20190926/31UER_0_3/B03.tif
22/04/25 09:48:19 DEBUG geotrellissentinelhub.Sentinel2L2AInitialCacheOperation: symlinked cached file from the distant past: /tmp_epod/openeo_collecting/c3990ba1-c1f7-4d7a-9c90-32fffcb360eb/20190926-31UER_0_3-B02.tif -> /data/projects/OpenEO/sentinel-hub-s2l2a-cache/20190926/31UER_0_3/B02.tif
22/04/25 09:48:19 DEBUG geotrellissentinelhub.Sentinel2L2AInitialCacheOperation: symlinked cached file from the distant past: /tmp_epod/openeo_collecting/c3990ba1-c1f7-4d7a-9c90-32fffcb360eb/20190926-31UDR_8_2-B04.tif -> /data/projects/OpenEO/sentinel-hub-s2l2a-cache/20190926/31UDR_8_2/B04.tif
22/04/25 09:48:19 DEBUG geotrellissentinelhub.Sentinel2L2AInitialCacheOperation: symlinked cached file from the distant past: /tmp_epod/openeo_collecting/c3990ba1-c1f7-4d7a-9c90-32fffcb360eb/20190926-31UDR_8_2-B03.tif -> /data/projects/OpenEO/sentinel-hub-s2l2a-cache/20190926/31UDR_8_2/B03.tif
22/04/25 09:48:19 DEBUG geotrellissentinelhub.Sentinel2L2AInitialCacheOperation: symlinked cached file from the distant past: /tmp_epod/openeo_collecting/c3990ba1-c1f7-4d7a-9c90-32fffcb360eb/20190926-31UDR_8_2-B02.tif -> /data/projects/OpenEO/sentinel-hub-s2l2a-cache/20190926/31UDR_8_2/B02.tif
22/04/25 09:48:19 DEBUG geotrellissentinelhub.Sentinel2L2AInitialCacheOperation: symlinked cached file from the distant past: /tmp_epod/openeo_collecting/c3990ba1-c1f7-4d7a-9c90-32fffcb360eb/20190926-31UDR_9_3-B04.tif -> /data/projects/OpenEO/sentinel-hub-s2l2a-cache/20190926/31UDR_9_3/B04.tif
22/04/25 09:48:19 DEBUG geotrellissentinelhub.Sentinel2L2AInitialCacheOperation: symlinked cached file from the distant past: /tmp_epod/openeo_collecting/c3990ba1-c1f7-4d7a-9c90-32fffcb360eb/20190926-31UDR_9_3-B03.tif -> /data/projects/OpenEO/sentinel-hub-s2l2a-cache/20190926/31UDR_9_3/B03.tif
22/04/25 09:48:19 DEBUG geotrellissentinelhub.Sentinel2L2AInitialCacheOperation: symlinked cached file from the distant past: /tmp_epod/openeo_collecting/c3990ba1-c1f7-4d7a-9c90-32fffcb360eb/20190926-31UDR_9_3-B02.tif -> /data/projects/OpenEO/sentinel-hub-s2l2a-cache/20190926/31UDR_9_3/B02.tif
22/04/25 09:48:19 DEBUG geotrellissentinelhub.Sentinel2L2AInitialCacheOperation: symlinked cached file from the distant past: /tmp_epod/openeo_collecting/c3990ba1-c1f7-4d7a-9c90-32fffcb360eb/20190926-31UER_1_8-B04.tif -> /data/projects/OpenEO/sentinel-hub-s2l2a-cache/20190926/31UER_1_8/B04.tif
22/04/25 09:48:19 DEBUG geotrellissentinelhub.Sentinel2L2AInitialCacheOperation: symlinked cached file from the distant past: /tmp_epod/openeo_collecting/c3990ba1-c1f7-4d7a-9c90-32fffcb360eb/20190926-31UER_1_8-B03.tif -> /data/projects/OpenEO/sentinel-hub-s2l2a-cache/20190926/31UER_1_8/B03.tif
22/04/25 09:48:19 DEBUG geotrellissentinelhub.Sentinel2L2AInitialCacheOperation: symlinked cached file from the distant past: /tmp_epod/openeo_collecting/c3990ba1-c1f7-4d7a-9c90-32fffcb360eb/20190926-31UER_1_8-B02.tif -> /data/projects/OpenEO/sentinel-hub-s2l2a-cache/20190926/31UER_1_8/B02.tif
... snip ...
22/04/25 09:48:19 DEBUG geotrellissentinelhub.Sentinel2L2AInitialCacheOperation: symlinked cached file from the distant past: /tmp_epod/openeo_collecting/c3990ba1-c1f7-4d7a-9c90-32fffcb360eb/20190926-31UER_1_4-B02.tif -> /data/projects/OpenEO/sentinel-hub-s2l2a-cache/20190926/31UER_1_4/B02.tif
22/04/25 09:48:19 DEBUG geotrellissentinelhub.Sentinel2L2AInitialCacheOperation: everything's cached, no need for additional requests
[2022-04-25 09:48:19,946] DEBUG in openeogeotrellis.backend: start_batch_process_cached(subfolder=c3990ba1-c1f7-4d7a-9c90-32fffcb360eb, collecting_folder=/tmp_epod/openeo_collecting/c3990ba1-c1f7-4d7a-9c90-32fffcb360eb) returned batch_request_id None
[2022-04-25 09:48:19,946] INFO in openeogeotrellis.backend: scheduled Sentinel Hub batch process(es) [None] for batch job 9de7b408-50fd-4eaf-a4fd-9800cdec1ec7 (CARD4L disabled)
[2022-04-25 09:48:19,964] INFO in kafka.conn: <BrokerConnection node_id=bootstrap-0 host=epod-master1.vgt.vito.be:6668 <connecting> [IPv4 ('192.168.207.56', 6668)]>: connecting to epod-master1.vgt.vito.be:6668 [('192.168.207.56', 6668) IPv4]
[2022-04-25 09:48:19,964] INFO in kafka.conn: Probing node bootstrap-0 broker version
[2022-04-25 09:48:19,969] INFO in kafka.conn: <BrokerConnection node_id=bootstrap-0 host=epod-master1.vgt.vito.be:6668 <connecting> [IPv4 ('192.168.207.56', 6668)]>: Connection complete.
[2022-04-25 09:48:20,071] INFO in kafka.conn: Broker version identifed as 1.0.0
[2022-04-25 09:48:20,071] INFO in kafka.conn: Set configuration api_version=(1, 0, 0) to skip auto check_version requests on startup
[2022-04-25 09:48:20,077] INFO in kafka.conn: <BrokerConnection node_id=1005 host=epod-master1.vgt.vito.be:6668 <connecting> [IPv4 ('192.168.207.56', 6668)]>: connecting to epod-master1.vgt.vito.be:6668 [('192.168.207.56', 6668) IPv4]
[2022-04-25 09:48:20,077] INFO in kafka.conn: <BrokerConnection node_id=1005 host=epod-master1.vgt.vito.be:6668 <connecting> [IPv4 ('192.168.207.56', 6668)]>: Connection complete.
[2022-04-25 09:48:20,078] INFO in kafka.conn: <BrokerConnection node_id=bootstrap-0 host=epod-master1.vgt.vito.be:6668 <connected> [IPv4 ('192.168.207.56', 6668)]>: Closing connection. 
[2022-04-25 09:48:20,080] INFO in openeogeotrellis.async_task: scheduled task {"task_id": "poll_sentinelhub_batch_processes", "arguments": {"batch_job_id": "9de7b408-50fd-4eaf-a4fd-9800cdec1ec7", "user_id": "vdboschj"}} on env dev
[2022-04-25 09:48:20,080] INFO in kafka.producer.kafka: Closing the Kafka producer with 9223372036.0 secs timeout.
[2022-04-25 09:48:20,080] INFO in kafka.conn: <BrokerConnection node_id=1005 host=epod-master1.vgt.vito.be:6668 <connected> [IPv4 ('192.168.207.56', 6668)]>: Closing connection. 
[2022-04-25 09:48:20,081] INFO in kafka.producer.kafka: Kafka producer closed
[2022-04-25 09:48:20,103] DEBUG in openeogeotrellis.job_registry: batch job 9de7b408-50fd-4eaf-a4fd-9800cdec1ec7 dependency -> awaiting
[2022-04-25 09:48:20,115] DEBUG in openeogeotrellis.job_registry: batch job 9de7b408-50fd-4eaf-a4fd-9800cdec1ec7 -> queued
bossie commented 2 years ago

TODO: https://github.com/Open-EO/openeo-geopyspark-driver/issues/149#issuecomment-1108339384

bossie commented 2 years ago
bossie commented 2 years ago

Added filebeat configuration to https://git.vito.be/projects/PUPTAP/repos/hiera-modules/browse/production/nodes/dataflow.intern.vgt.vito.be.yaml:

profile_beats::filebeat::inputs:
  'openeo':
    input_type: 'log'
    config:
      paths:
        - '/opt/scripts/OpenEO/dev/logs/async_task_java.log*'
        - '/opt/scripts/OpenEO/dev/logs/async_task_python.log*'
        - '/opt/scripts/OpenEO/dev/logs/job_tracker_python.log*'
      tags:
        - 'openeo-nifi'

Adapted filter configuration in https://git.vito.be/projects/BIGGEO/repos/logstash_config/browse/config/filter.conf to properly deconstruct JSON:

  if "openeo-yarn" in [tags] or "openeo-nifi" in [tags] {
    json {
      source => "message"
    }
  }
bossie commented 2 years ago

Scala logging from the caching system, includes batch job ID and user ID:

https://kibana-infra.vgt.vito.be/app/kibana#/discover?_g=(filters:!(),refreshInterval:(pause:!t,value:0),time:(from:now-1h,to:now))&_a=(columns:!(message,levelname,created,name,filename,lineno,process,job_id,user_id),filters:!(('$state':(store:appState),meta:(alias:!n,disabled:!f,index:'06ccb600-1ef9-11e9-90ab-57e2708ee7ad',key:host.name,negate:!f,params:(query:dataflow.intern.vgt.vito.be),type:phrase),query:(match:(host.name:(query:dataflow.intern.vgt.vito.be,type:phrase)))),('$state':(store:appState),meta:(alias:!n,disabled:!f,index:ec984030-8791-11ea-92fb-09142a8b5be0,key:name,negate:!f,params:(query:org.openeo.geotrellissentinelhub.CachingService),type:phrase),query:(match:(name:(query:org.openeo.geotrellissentinelhub.CachingService,type:phrase))))),index:ec984030-8791-11ea-92fb-09142a8b5be0,interval:auto,query:(language:kuery,query:''),sort:!(!('@timestamp',desc)))

bossie commented 2 years ago

Deriving @timestamp from "created" property (= epoch seconds), otherwise filebeat/logstash will take the time at which it processes the message:

    date {
      match => ["created", "UNIX"]
    }
bossie commented 2 years ago

So the caching is logged and immediately visible in Kibana with the correct user ID, batch job ID and timestamp.