RavenPy paper notebook timeout on CRIM / birdhouse-deploy CI #154
Description
Description
The following notebook seems to raise a Timeout (5s) issue when reaching cell 14.
Note that all other RavenPy notebooks and cells doing various WPS call or data compute/display do not fail. Therefore, it seems unlikely to be the cause. The timeout must be related to another operation (e.g. a xarray command not returning any responses, an underlying hidden request, or maybe the ProgressBar capturing outputs)?
I have not been able to replicate the issue yet.
Example Output
21:05:35 ============================= test session starts ==============================
21:05:35 platform linux -- Python 3.11.12, pytest-8.3.5, pluggy-1.5.0
21:05:35 rootdir: /home/jenkins/agent/workspace/PAVICS-e2e-workflow-tests_master
21:05:35 plugins: anyio-4.9.0, dash-3.0.3, nbval-0.11.0, tornasync-0.6.0.post2, xdist-3.6.1
21:05:35 collected 236 items
21:05:35
21:05:37 RavenPy-main/docs/notebooks/00_Introduction_to_JupyterLab.ipynb ...... [ 2%]
21:05:48 RavenPy-main/docs/notebooks/01_Getting_watershed_boundaries.ipynb ...... [ 5%]
21:05:48 .. [ 5%]
21:05:56 RavenPy-main/docs/notebooks/02_Extract_geographical_watershed_properties.ipynb . [ 6%]
21:06:00 ............. [ 11%]
21:07:39 RavenPy-main/docs/notebooks/03_Extracting_forcing_data.ipynb ........... [ 16%]
21:07:39 [ 16%]
21:07:44 RavenPy-main/docs/notebooks/04_Emulating_hydrological_models.ipynb ..... [ 18%]
21:07:51 ............... [ 25%]
21:07:57 RavenPy-main/docs/notebooks/05_Advanced_RavenPy_configuration.ipynb .... [ 26%]
21:08:05 ......... [ 30%]
21:08:17 RavenPy-main/docs/notebooks/06_Raven_calibration.ipynb ...... [ 33%]
21:08:23 RavenPy-main/docs/notebooks/07_Making_and_using_hotstart_files.ipynb ... [ 34%]
21:08:26 ... [ 35%]
21:08:48 RavenPy-main/docs/notebooks/08_Getting_and_bias_correcting_CMIP6_data.ipynb . [ 36%]
21:16:33 ............... [ 42%]
21:16:38 RavenPy-main/docs/notebooks/09_Hydrological_impacts_of_climate_change.ipynb . [ 42%]
21:16:45 .... [ 44%]
21:17:24 RavenPy-main/docs/notebooks/10_Data_assimilation.ipynb ........ [ 47%]
21:17:35 RavenPy-main/docs/notebooks/11_Climatological_ESP_forecasting.ipynb .... [ 49%]
21:18:00 .... [ 51%]
21:18:08 RavenPy-main/docs/notebooks/12_Performing_hindcasting_experiments.ipynb . [ 51%]
21:18:18 ....... [ 54%]
21:18:43 RavenPy-main/docs/notebooks/Assess_probabilistic_flood_risk.ipynb ...... [ 57%]
21:18:44 . [ 57%]
21:18:52 RavenPy-main/docs/notebooks/Comparing_hindcasts_and_ESP_forecasts.ipynb . [ 58%]
21:19:13 ....... [ 61%]
21:19:20 RavenPy-main/docs/notebooks/Distributed_hydrological_modelling.ipynb ... [ 62%]
21:19:39 .... [ 63%]
21:19:50 RavenPy-main/docs/notebooks/Hydrological_realtime_forecasting.ipynb .... [ 65%]
21:19:57 .. [ 66%]
21:20:30 RavenPy-main/docs/notebooks/Managing_Jupyter_Environments.ipynb ... [ 67%]
21:20:56 RavenPy-main/docs/notebooks/Perform_Regionalization.ipynb ....... [ 70%]
21:21:03 RavenPy-main/docs/notebooks/Running_HMETS_with_CANOPEX_dataset.ipynb ... [ 72%]
21:21:19 .......... [ 76%]
21:21:39 RavenPy-main/docs/notebooks/Sensitivity_analysis.ipynb ...... [ 78%]
21:21:46 RavenPy-main/docs/notebooks/time_series_analysis.ipynb ........... [ 83%]
21:21:54 RavenPy-main/docs/notebooks/paper/Perform_a_climate_change_impact_study_on_a_watershed.ipynb . [ 83%]
21:28:40 .............Fxxxxxx [ 92%]
21:28:40 notebooks/hummingbird.ipynb ............ [ 97%]
21:31:10 notebooks/stress-tests.ipynb ...... [100%]
21:31:10
21:31:10 =================================== FAILURES ===================================
21:31:10 _ RavenPy-main/docs/notebooks/paper/Perform_a_climate_change_impact_study_on_a_watershed.ipynb::Cell 14 _
21:31:10 Notebook cell execution failed
21:31:10 Cell 14: Timeout of 5 seconds exceeded waiting for output.
21:31:10
21:31:10 Input:
21:31:10 # Convert the reference corrected data into netCDF file.
21:31:10 # We will then apply a special code to remove a dimension in the dataset to make it applicable to the RAVEN models.
21:31:10 ref_dataset = xr.merge(
21:31:10 [
21:31:10 corrected_ref_precip.to_dataset(name="pr"),
21:31:10 corrected_ref_tasmax.to_dataset(name="tasmax"),
21:31:10 corrected_ref_tasmin.to_dataset(name="tasmin"),
21:31:10 ]
21:31:10 )
21:31:10
21:31:10 # Write to temporary folder.
21:31:10 fn_tmp_ref = tmp / "reference_dataset_tmp.nc"
21:31:10 ref_dataset.to_netcdf(fn_tmp_ref)
21:31:10
21:31:10 # Convert the future corrected data into netCDF file.
21:31:10 fut_dataset = xr.merge(
21:31:10 [
21:31:10 corrected_fut_precip.to_dataset(name="pr"),
21:31:10 corrected_fut_tasmax.to_dataset(name="tasmax"),
21:31:10 corrected_fut_tasmin.to_dataset(name="tasmin"),
21:31:10 ]
21:31:10 )
21:31:10 # Write to temporary folder.
21:31:10 with ProgressBar():
21:31:10 fn_tmp_fut = tmp / "future_dataset_tmp.nc"
21:31:10 fut_dataset.to_netcdf(fn_tmp_fut)
21:31:10
21:31:10 # Write the data to disk to a temporary location for future use.
21:31:10 ref_dataset = xr.open_dataset(fn_tmp_ref)
21:31:10 ref_dataset.isel(geom=0).squeeze().to_netcdf(tmp / "reference_dataset.nc")
21:31:10
21:31:10 fut_dataset = xr.open_dataset(fn_tmp_fut)
21:31:10 fut_dataset.isel(geom=0).squeeze().to_netcdf(tmp / "future_dataset.nc")
21:31:10
21:31:10 =========================== short test summary info ============================
21:31:10 FAILED RavenPy-main/docs/notebooks/paper/Perform_a_climate_change_impact_study_on_a_watershed.ipynb::Cell 14
21:31:10 ============ 1 failed, 229 passed, 6 xfailed in 1530.45s (0:25:30) =============Save Output Step
Unfortunately, the nbconvert step takes too long, so it is not available.
However, it might hint at the cause, since the nbconvert timeout occurs during the same cell as the timeout with pytest+nbval above.
21:45:18 + jupyter nbconvert --to notebook --execute --ExecutePreprocessor.timeout=240 --allow-errors --output-dir buildout --output RavenPy-main/docs/notebooks/paper/Perform_a_climate_change_impact_study_on_a_watershed.output.ipynb RavenPy-main/docs/notebooks/paper/Perform_a_climate_change_impact_study_on_a_watershed.ipynb
21:45:20 [NbConvertApp] Converting notebook RavenPy-main/docs/notebooks/paper/Perform_a_climate_change_impact_study_on_a_watershed.ipynb to notebook
21:50:57 [NbConvertApp] ERROR | Timeout waiting for execute reply (240s).
21:50:58 Traceback (most recent call last):
21:50:58 File "/opt/conda/envs/birdy/lib/python3.11/site-packages/nbclient/client.py", line 782, in _async_poll_for_reply
21:50:58 msg = await ensure_async(self.kc.shell_channel.get_msg(timeout=new_timeout))
21:50:58 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
21:50:58 File "/opt/conda/envs/birdy/lib/python3.11/site-packages/jupyter_core/utils/__init__.py", line 198, in ensure_async
21:50:58 result = await obj
21:50:58 ^^^^^^^^^
21:50:58 File "/opt/conda/envs/birdy/lib/python3.11/site-packages/jupyter_client/channels.py", line 230, in get_msg
21:50:58 raise Empty
21:50:58 _queue.Empty
21:50:58
21:50:58 During handling of the above exception, another exception occurred:
21:50:58
21:50:58 Traceback (most recent call last):
21:50:58 File "/opt/conda/envs/birdy/bin/jupyter-nbconvert", line 10, in <module>
21:50:58 sys.exit(main())
21:50:58 ^^^^^^
21:50:58 File "/opt/conda/envs/birdy/lib/python3.11/site-packages/jupyter_core/application.py", line 283, in launch_instance
21:50:58 super().launch_instance(argv=argv, **kwargs)
21:50:58 File "/opt/conda/envs/birdy/lib/python3.11/site-packages/traitlets/config/application.py", line 1075, in launch_instance
21:50:58 app.start()
21:50:58 File "/opt/conda/envs/birdy/lib/python3.11/site-packages/nbconvert/nbconvertapp.py", line 420, in start
21:50:58 self.convert_notebooks()
21:50:58 File "/opt/conda/envs/birdy/lib/python3.11/site-packages/nbconvert/nbconvertapp.py", line 597, in convert_notebooks
21:50:58 self.convert_single_notebook(notebook_filename)
21:50:58 File "/opt/conda/envs/birdy/lib/python3.11/site-packages/nbconvert/nbconvertapp.py", line 563, in convert_single_notebook
21:50:58 output, resources = self.export_single_notebook(
21:50:58 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
21:50:58 File "/opt/conda/envs/birdy/lib/python3.11/site-packages/nbconvert/nbconvertapp.py", line 487, in export_single_notebook
21:50:58 output, resources = self.exporter.from_filename(
21:50:58 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
21:50:58 File "/opt/conda/envs/birdy/lib/python3.11/site-packages/nbconvert/exporters/exporter.py", line 201, in from_filename
21:50:58 return self.from_file(f, resources=resources, **kw)
21:50:58 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
21:50:58 File "/opt/conda/envs/birdy/lib/python3.11/site-packages/nbconvert/exporters/exporter.py", line 220, in from_file
21:50:58 return self.from_notebook_node(
21:50:58 ^^^^^^^^^^^^^^^^^^^^^^^^
21:50:58 File "/opt/conda/envs/birdy/lib/python3.11/site-packages/nbconvert/exporters/notebook.py", line 36, in from_notebook_node
21:50:58 nb_copy, resources = super().from_notebook_node(nb, resources, **kw)
21:50:58 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
21:50:58 File "/opt/conda/envs/birdy/lib/python3.11/site-packages/nbconvert/exporters/exporter.py", line 154, in from_notebook_node
21:50:58 nb_copy, resources = self._preprocess(nb_copy, resources)
21:50:58 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
21:50:58 File "/opt/conda/envs/birdy/lib/python3.11/site-packages/nbconvert/exporters/exporter.py", line 353, in _preprocess
21:50:58 nbc, resc = preprocessor(nbc, resc)
21:50:58 ^^^^^^^^^^^^^^^^^^^^^^^
21:50:58 File "/opt/conda/envs/birdy/lib/python3.11/site-packages/nbconvert/preprocessors/base.py", line 48, in __call__
21:50:58 return self.preprocess(nb, resources)
21:50:58 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
21:50:58 File "/opt/conda/envs/birdy/lib/python3.11/site-packages/nbconvert/preprocessors/execute.py", line 103, in preprocess
21:50:58 self.preprocess_cell(cell, resources, index)
21:50:58 File "/opt/conda/envs/birdy/lib/python3.11/site-packages/nbconvert/preprocessors/execute.py", line 124, in preprocess_cell
21:50:58 cell = self.execute_cell(cell, index, store_history=True)
21:50:58 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
21:50:58 File "/opt/conda/envs/birdy/lib/python3.11/site-packages/jupyter_core/utils/__init__.py", line 165, in wrapped
21:50:58 return loop.run_until_complete(inner)
21:50:58 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
21:50:58 File "/opt/conda/envs/birdy/lib/python3.11/asyncio/base_events.py", line 654, in run_until_complete
21:50:58 return future.result()
21:50:58 ^^^^^^^^^^^^^^^
21:50:58 File "/opt/conda/envs/birdy/lib/python3.11/site-packages/nbclient/client.py", line 1005, in async_execute_cell
21:50:58 exec_reply = await self.task_poll_for_reply
21:50:58 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
21:50:58 File "/opt/conda/envs/birdy/lib/python3.11/site-packages/nbclient/client.py", line 806, in _async_poll_for_reply
21:50:58 error_on_timeout_execute_reply = await self._async_handle_timeout(timeout, cell)
21:50:58 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
21:50:58 File "/opt/conda/envs/birdy/lib/python3.11/site-packages/nbclient/client.py", line 856, in _async_handle_timeout
21:50:58 raise CellTimeoutError.error_from_timeout_and_cell(
21:50:58 nbclient.exceptions.CellTimeoutError: A cell timed out while it was being executed, after 240 seconds.
21:50:58 The message was: Cell execution timed out.
21:50:58 Here is a preview of the cell contents:
21:50:58 -------------------
21:50:58 ['# Convert the reference corrected data into netCDF file.', '# We will then apply a special code to remove a dimension in the dataset to make it applicable to the RAVEN models.', 'ref_dataset = xr.merge(', ' [', ' corrected_ref_precip.to_dataset(name="pr"),']
21:50:58 ...
21:50:58 [' ref_dataset = xr.open_dataset(fn_tmp_ref)', ' ref_dataset.isel(geom=0).squeeze().to_netcdf(tmp / "reference_dataset.nc")', '', ' fut_dataset = xr.open_dataset(fn_tmp_fut)', ' fut_dataset.isel(geom=0).squeeze().to_netcdf(tmp / "future_dataset.nc")']
21:50:58 -------------------