pangeo-forge-runner does not guarantee "status" fields on every log line

[cisaacstern]

I just called a recipe test here pangeo-forge/staged-recipes#183 (comment)

The resulting pangeo-forge-runner subprocess call failed with a KeyError

2022-09-19T16:31:51.157842+00:00 app[web.1]: subprocess.CalledProcessError: Command '['pangeo-forge-runner', 'bake', '--repo=https://github.com/eooffshore/staged-recipes', '--ref=037542663cb7f7bc4a04777c90d85accbff01c8c', '--json', '--prune', '--Bake.recipe_id=eooffshore_ics_cmems_WIND_GLO_WIND_L3_NRT_OBSERVATIONS_012_002_MetOp_ASCAT', '-f=/tmp/tmp5_e7dib5.json', '--feedstock-subdir=recipes/eooffshore_ics_cms_WIND_GLO_WIND_L3_OBSERVATIONS_Metop_ASCAT']' returned non-zero exit status 1.
2022-09-19T16:31:51.157842+00:00 app[web.1]: 
2022-09-19T16:31:51.157842+00:00 app[web.1]: During handling of the above exception, another exception occurred:
2022-09-19T16:31:51.157843+00:00 app[web.1]: 
2022-09-19T16:31:51.157843+00:00 app[web.1]: Traceback (most recent call last):
2022-09-19T16:31:51.157844+00:00 app[web.1]: File "/usr/local/lib/python3.9/dist-packages/uvicorn/protocols/http/h11_impl.py", line 373, in run_asgi
2022-09-19T16:31:51.157844+00:00 app[web.1]: result = await app(self.scope, self.receive, self.send)
2022-09-19T16:31:51.157851+00:00 app[web.1]: File "/usr/local/lib/python3.9/dist-packages/uvicorn/middleware/proxy_headers.py", line 75, in __call__
2022-09-19T16:31:51.157851+00:00 app[web.1]: return await self.app(scope, receive, send)
2022-09-19T16:31:51.157851+00:00 app[web.1]: File "/usr/local/lib/python3.9/dist-packages/fastapi/applications.py", line 208, in __call__
2022-09-19T16:31:51.157852+00:00 app[web.1]: await super().__call__(scope, receive, send)
2022-09-19T16:31:51.157852+00:00 app[web.1]: File "/usr/local/lib/python3.9/dist-packages/starlette/applications.py", line 112, in __call__
2022-09-19T16:31:51.157853+00:00 app[web.1]: await self.middleware_stack(scope, receive, send)
2022-09-19T16:31:51.157853+00:00 app[web.1]: File "/usr/local/lib/python3.9/dist-packages/starlette/middleware/errors.py", line 181, in __call__
2022-09-19T16:31:51.157853+00:00 app[web.1]: raise exc
2022-09-19T16:31:51.157854+00:00 app[web.1]: File "/usr/local/lib/python3.9/dist-packages/starlette/middleware/errors.py", line 159, in __call__
2022-09-19T16:31:51.157854+00:00 app[web.1]: await self.app(scope, receive, _send)
2022-09-19T16:31:51.157854+00:00 app[web.1]: File "/usr/local/lib/python3.9/dist-packages/starlette/middleware/cors.py", line 84, in __call__
2022-09-19T16:31:51.157855+00:00 app[web.1]: await self.app(scope, receive, send)
2022-09-19T16:31:51.157855+00:00 app[web.1]: File "/usr/local/lib/python3.9/dist-packages/starlette/exceptions.py", line 82, in __call__
2022-09-19T16:31:51.157855+00:00 app[web.1]: raise exc
2022-09-19T16:31:51.157856+00:00 app[web.1]: File "/usr/local/lib/python3.9/dist-packages/starlette/exceptions.py", line 71, in __call__
2022-09-19T16:31:51.157856+00:00 app[web.1]: await self.app(scope, receive, sender)
2022-09-19T16:31:51.157856+00:00 app[web.1]: File "/usr/local/lib/python3.9/dist-packages/starlette/routing.py", line 656, in __call__
2022-09-19T16:31:51.157856+00:00 app[web.1]: await route.handle(scope, receive, send)
2022-09-19T16:31:51.157857+00:00 app[web.1]: File "/usr/local/lib/python3.9/dist-packages/starlette/routing.py", line 259, in handle
2022-09-19T16:31:51.157857+00:00 app[web.1]: await self.app(scope, receive, send)
2022-09-19T16:31:51.157857+00:00 app[web.1]: File "/usr/local/lib/python3.9/dist-packages/starlette/routing.py", line 64, in app
2022-09-19T16:31:51.157858+00:00 app[web.1]: await response(scope, receive, send)
2022-09-19T16:31:51.157858+00:00 app[web.1]: File "/usr/local/lib/python3.9/dist-packages/starlette/responses.py", line 159, in __call__
2022-09-19T16:31:51.157858+00:00 app[web.1]: await self.background()
2022-09-19T16:31:51.157859+00:00 app[web.1]: File "/usr/local/lib/python3.9/dist-packages/starlette/background.py", line 35, in __call__
2022-09-19T16:31:51.157859+00:00 app[web.1]: await task()
2022-09-19T16:31:51.157859+00:00 app[web.1]: File "/usr/local/lib/python3.9/dist-packages/starlette/background.py", line 18, in __call__
2022-09-19T16:31:51.157859+00:00 app[web.1]: await self.func(*self.args, **self.kwargs)
2022-09-19T16:31:51.157860+00:00 app[web.1]: File "/opt/app/pangeo_forge_orchestrator/routers/github_app.py", line 838, in run_recipe_test
2022-09-19T16:31:51.157860+00:00 app[web.1]: await run(*args, **kws, gh=gh, db_session=db_session)
2022-09-19T16:31:51.157860+00:00 app[web.1]: File "/opt/app/pangeo_forge_orchestrator/routers/github_app.py", line 618, in run
2022-09-19T16:31:51.157860+00:00 app[web.1]: if p["status"] == "failed":
2022-09-19T16:31:51.157861+00:00 app[web.1]: KeyError: 'status'

which indicates that the assumption that failed pangeo-forge-runner calls will always provide a log line with a "status" field

pangeo-forge-orchestrator/pangeo_forge_orchestrator/routers/github_app.py

Lines 615 to 618 in ac024db

	except subprocess.CalledProcessError as e:
	for line in e.output.splitlines():
	p = json.loads(line)
	if p["status"] == "failed":

is faulty.

[cisaacstern]

Correction to above, the traceback line does have a "status" field. It seems like the faulty assumption is that every line will have a "status" field. Here is the logging for the call which raised a KeyError:

$ pangeo-forge-runner bake --repo=https://github.com/eooffshore/staged-recipes --ref=037542663cb7f7bc4a04777c90d85accbff01c8c --json --prune --Bake.recipe_id=eooffshore_ics_cmems_WIND_GLO_WIND_L3_NRT_OBSERVATIONS_012_002_MetOp_ASCAT -f=/tmp/tmp5_e7dib5.json --feedstock-subdir=recipes/eooffshore_ics_cms_WIND_GLO_WIND_L3_OBSERVATIONS_Metop_ASCAT

{"message": "Target Storage is FSSpecTarget(AbstractFileSystem(, root_path=\"\")\n", "status": "setup"}
{"message": "Input Cache Storage is CacheFSSpecTarget(AbstractFileSystem(, root_path=\"\")\n", "status": "setup"}
{"message": "Metadata Cache Storage is MetadataTarget(AbstractFileSystem(, root_path=\"\")\n", "status": "setup"}
{"message": "Picked Git content provider.\n", "status": "fetching"}
{"message": "Cloning into '/var/folders/tt/4f941hdn0zq549zdwhcgg98c0000gn/T/tmp6mcx0gyk'...\n", "status": "fetching"}
{"message": "HEAD is now at 0375426 Removed references to setup_logging\n", "status": "fetching"}
{"message": "Parsing recipes...", "status": "running"}
{"message": "Baking only recipe_id='eooffshore_ics_cmems_WIND_GLO_WIND_L3_NRT_OBSERVATIONS_012_002_MetOp_ASCAT'"}
{"message": "Error during running: object of type function not serializable", "exc_info": "Traceback (most recent call last):\n  File \"/Users/charlesstern/miniconda3/envs/pfo-new/bin/pangeo-forge-runner\", line 8, in <module>\n    sys.exit(main())\n  File \"/Users/charlesstern/miniconda3/envs/pfo-new/lib/python3.9/site-packages/pangeo_forge_runner/cli.py\", line 28, in main\n    app.start()\n  File \"/Users/charlesstern/miniconda3/envs/pfo-new/lib/python3.9/site-packages/pangeo_forge_runner/cli.py\", line 23, in start\n    super().start()\n  File \"/Users/charlesstern/miniconda3/envs/pfo-new/lib/python3.9/site-packages/traitlets/config/application.py\", line 462, in start\n    return self.subapp.start()\n  File \"/Users/charlesstern/miniconda3/envs/pfo-new/lib/python3.9/site-packages/pangeo_forge_runner/commands/bake.py\", line 130, in start\n    job_name = f\"{name}-{recipe.sha256().hex()}-{int(datetime.now().timestamp())}\"\n  File \"/Users/charlesstern/miniconda3/envs/pfo-new/lib/python3.9/site-packages/pangeo_forge_recipes/recipes/base.py\", line 51, in sha256\n    return dataclass_sha256(self, ignore_keys=self._hash_exclude_)\n  File \"/Users/charlesstern/miniconda3/envs/pfo-new/lib/python3.9/site-packages/pangeo_forge_recipes/serialization.py\", line 70, in dataclass_sha256\n    return dict_to_sha256(d)\n  File \"/Users/charlesstern/miniconda3/envs/pfo-new/lib/python3.9/site-packages/pangeo_forge_recipes/serialization.py\", line 31, in dict_to_sha256\n    b = dumps(\n  File \"/Users/charlesstern/miniconda3/envs/pfo-new/lib/python3.9/json/__init__.py\", line 234, in dumps\n    return cls(\n  File \"/Users/charlesstern/miniconda3/envs/pfo-new/lib/python3.9/json/encoder.py\", line 199, in encode\n    chunks = self.iterencode(o, _one_shot=True)\n  File \"/Users/charlesstern/miniconda3/envs/pfo-new/lib/python3.9/json/encoder.py\", line 257, in iterencode\n    return _iterencode(o, 0)\n  File \"/Users/charlesstern/miniconda3/envs/pfo-new/lib/python3.9/site-packages/pangeo_forge_recipes/serialization.py\", line 20, in either_encode_or_hash\n    raise TypeError(f\"object of type {type(obj).__name__} not serializable\")\nTypeError: object of type function not serializable", "status": "failed"}

[cisaacstern]

On closer inspection, it looks like the offending line is

{"message": "Baking only recipe_id='eooffshore_ics_cmems_WIND_GLO_WIND_L3_NRT_OBSERVATIONS_012_002_MetOp_ASCAT'"}

which I added in

https://github.com/pangeo-forge/pangeo-forge-runner/pull/14/files#diff-41ded1244d8db995f0817420e6cb43675a93be3657bf5d9ce75137f9babe37edR106

So this is my fault 😆

[cisaacstern]

Note: the patch implemented in #154 can be removed if/when this issue is resolved upstream.