The allocation stopped as expected

[sentry-io]

Sentry Issue: CODEOCEAN-123

An error occurred during code execution while being connected to wss://poseidon-terraform.compute.internal:7200/api/v1/runners/10-25237a45-751f-11ef-badf-fa163efe023e/websocket?executionID=61e88f26-dfa3-43c1-8701-1436c94e29c9.

---

On September 17th at 18:30 UTC, we got another the allocation stopped as expected occurrence (specific Sentry event). While this was initially tracked in #423, I thought it was resolved back then despite a follow-up issue in #487.

When checking the Poseidon log, I didn't notice something super specific. Hence, I just wanted to clarify what might have caused the issue.

Poseidon logs around that time

2024-09-17T18:30:02.513461+00:00 poseidon-terraform poseidon[46732]: time="2024-09-17T18:30:02.513071Z" level=info msg="Execution returned" environment_id=10 package=api runner_id=10-25237a45-751f-11ef-badf-fa163efe023e
2024-09-17T18:30:03.779610+00:00 poseidon-terraform poseidon[46732]: time="2024-09-17T18:30:03.779205Z" level=debug code=204 duration=129.85339ms method=PATCH path=/api/v1/runners/10-25237a45-751f-11ef-badf-fa163efe023e/files user_agent="Faraday
 v2.10.1"
2024-09-17T18:30:03.834687+00:00 poseidon-terraform poseidon[46732]: time="2024-09-17T18:30:03.834575Z" level=debug code=200 duration="108.427µs" method=POST path=/api/v1/runners/10-25237a45-751f-11ef-badf-fa163efe023e/execute user_agent="Farada
y v2.10.1"
2024-09-17T18:30:03.849164+00:00 poseidon-terraform poseidon[46732]: time="2024-09-17T18:30:03.849086Z" level=info msg="Running execution" environment_id=10 executionID=f56302d2-e5b5-4c7c-ac4c-1022d9ddfeed package=api runner_id=10-25237a45-751f-
11ef-badf-fa163efe023e
2024-09-17T18:30:04.525831+00:00 poseidon-terraform poseidon[46732]: time="2024-09-17T18:30:04.525705Z" level=info msg="Execution returned" environment_id=10 package=api runner_id=10-25237a45-751f-11ef-badf-fa163efe023e
2024-09-17T18:30:04.525954+00:00 poseidon-terraform poseidon[46732]: time="2024-09-17T18:30:04.525791Z" level=debug code=200 duration=676.763687ms method=GET path=/api/v1/runners/10-25237a45-751f-11ef-badf-fa163efe023e/websocket user_agent=
2024-09-17T18:30:04.557147+00:00 poseidon-terraform poseidon[46732]: time="2024-09-17T18:30:04.556628Z" level=debug code=200 duration="111.864µs" method=POST path=/api/v1/runners/10-25237a45-751f-11ef-badf-fa163efe023e/execute user_agent="Farada
y v2.10.1"
2024-09-17T18:30:04.571436+00:00 poseidon-terraform poseidon[46732]: time="2024-09-17T18:30:04.571351Z" level=info msg="Running execution" environment_id=10 executionID=61e88f26-dfa3-43c1-8701-1436c94e29c9 package=api runner_id=10-25237a45-751f-11ef-badf-fa163efe023e
2024-09-17T18:30:05.030709+00:00 poseidon-terraform poseidon[46732]: time="2024-09-17T18:30:05.030265Z" level=debug msg="The client closed the connection." code=1000 environment_id=10 package=api runner_id=10-25237a45-751f-11ef-badf-fa163efe023e text=
2024-09-17T18:30:05.033455+00:00 poseidon-terraform poseidon[46732]: time="2024-09-17T18:30:05.033306Z" level=debug code=200 duration=17.521198041s method=GET path=/api/v1/runners/10-25237a45-751f-11ef-badf-fa163efe023e/websocket user_agent=
2024-09-17T18:30:05.134155+00:00 poseidon-terraform poseidon[46732]: time="2024-09-17T18:30:05.133889Z" level=debug msg="Destroying Runner" destroy_reason="the client wants to stop the runner" package=runner runner_id=10-25237a45-751f-11ef-badf-fa163efe023e
2024-09-17T18:30:05.136501+00:00 poseidon-terraform poseidon[46732]: time="2024-09-17T18:30:05.135489Z" level=info msg="Execution returned" environment_id=10 package=api runner_id=10-25237a45-751f-11ef-badf-fa163efe023e
2024-09-17T18:30:05.136563+00:00 poseidon-terraform poseidon[46732]: time="2024-09-17T18:30:05.135522Z" level=debug code=200 duration=564.223405ms method=GET path=/api/v1/runners/10-25237a45-751f-11ef-badf-fa163efe023e/websocket user_agent=
2024-09-17T18:30:05.152465+00:00 poseidon-terraform poseidon[46732]: time="2024-09-17T18:30:05.152368Z" level=debug msg="Runner stopped" package=runner runner_id=10-25237a45-751f-11ef-badf-fa163efe023e
2024-09-17T18:30:05.152885+00:00 poseidon-terraform poseidon[46732]: time="2024-09-17T18:30:05.152843Z" level=debug code=204 duration=18.989239ms method=DELETE path=/api/v1/runners/10-25237a45-751f-11ef-badf-fa163efe023e user_agent="Faraday v2.10.1"
2024-09-17T18:30:05.182366+00:00 poseidon-terraform poseidon[46732]: time="2024-09-17T18:30:05.182262Z" level=debug code=410 duration="19.997µs" method=DELETE path=/api/v1/runners/10-25237a45-751f-11ef-badf-fa163efe023e user_agent="Faraday v2.10.1"
2024-09-17T18:30:05.214875+00:00 poseidon-terraform poseidon[46732]: time="2024-09-17T18:30:05.214772Z" level=debug msg="Execution canceled by context" environment_id=10 package=nomad runner_id=10-25237a45-751f-11ef-badf-fa163efe023e
2024-09-17T18:30:05.215059+00:00 poseidon-terraform poseidon[46732]: time="2024-09-17T18:30:05.214850Z" level=debug msg="Execution canceled by context" environment_id=10 package=nomad runner_id=10-25237a45-751f-11ef-badf-fa163efe023e
2024-09-17T18:30:05.215147+00:00 poseidon-terraform poseidon[46732]: time="2024-09-17T18:30:05.214864Z" level=debug msg="Execution terminated after SIGQUIT" package=runner runner_id=10-25237a45-751f-11ef-badf-fa163efe023e
2024-09-17T18:30:05.340500+00:00 poseidon-terraform poseidon[46732]: time="2024-09-17T18:30:05.340339Z" level=debug msg="Execution canceled by context" environment_id=10 package=nomad runner_id=10-25237a45-751f-11ef-badf-fa163efe023e
2024-09-17T18:30:05.340676+00:00 poseidon-terraform poseidon[46732]: time="2024-09-17T18:30:05.340386Z" level=debug msg="Execution terminated after SIGQUIT" package=runner runner_id=10-25237a45-751f-11ef-badf-fa163efe023e
2024-09-17T18:30:17.632952+00:00 poseidon-terraform poseidon[46732]: time="2024-09-17T18:30:17.632440Z" level=debug code=410 duration="54.534µs" method=PATCH path=/api/v1/runners/10-25237a45-751f-11ef-badf-fa163efe023e/files user_agent="Faraday v2.10.1"
2024-09-17T18:30:17.635024+00:00 poseidon-terraform poseidon[46732]: time="2024-09-17T18:30:17.634343Z" level=debug code=200 duration="74.873µs" method=POST path=/api/v1/runners user_agent="Faraday v2.10.1"
2024-09-17T18:30:17.651915+00:00 poseidon-terraform poseidon[46732]: time="2024-09-17T18:30:17.651694Z" level=debug msg="Handle Allocation Event" ClientStatus=pending DesiredStatus=run NextAllocation= PrevAllocation= alloc_id=3e8a7f2f-1ec0-93f8-c0d7-6d98b4344634 package=nomad
2024-09-17T18:30:17.671424+00:00 poseidon-terraform poseidon[46732]: time="2024-09-17T18:30:17.671354Z" level=debug msg="Ignoring duplicate event" allocID=9a5c2645-221a-278a-bc90-b1035b2f36fc package=nomad
2024-09-17T18:30:17.779303+00:00 poseidon-terraform poseidon[46732]: time="2024-09-17T18:30:17.779155Z" level=debug code=204 duration=136.483399ms method=PATCH path=/api/v1/runners/10-5a382ea3-7516-11ef-badf-fa163efe023e/files user_agent="Faraday v2.10.1"
2024-09-17T18:30:17.838928+00:00 poseidon-terraform poseidon[46732]: time="2024-09-17T18:30:17.838754Z" level=debug code=200 duration="79.031µs" method=POST path=/api/v1/runners/10-5a382ea3-7516-11ef-badf-fa163efe023e/execute user_agent="Faraday v2.10.1"
2024-09-17T18:30:17.853720+00:00 poseidon-terraform poseidon[46732]: time="2024-09-17T18:30:17.853627Z" level=info msg="Running execution" environment_id=10 executionID=55102a9c-ac3f-4529-981b-3927dc0e9ca9 package=api runner_id=10-5a382ea3-7516-11ef-badf-fa163efe023e
2024-09-17T18:30:18.307736+00:00 poseidon-terraform poseidon[46732]: time="2024-09-17T18:30:18.307610Z" level=debug msg="Handle Allocation Event" ClientStatus=running DesiredStatus=run NextAllocation= PrevAllocation= alloc_id=3e8a7f2f-1ec0-93f8-c0d7-6d98b4344634 package=nomad
2024-09-17T18:30:18.307849+00:00 poseidon-terraform poseidon[46732]: time="2024-09-17T18:30:18.307649Z" level=debug msg="Runner started" package=runner runner_id=10-e367cf4b-7522-11ef-badf-fa163efe023e startupDuration=655.918436ms
2024-09-17T18:30:18.570840+00:00 poseidon-terraform poseidon[46732]: time="2024-09-17T18:30:18.570594Z" level=info msg="Execution returned" environment_id=10 package=api runner_id=10-5a382ea3-7516-11ef-badf-fa163efe023e
2024-09-17T18:30:18.570930+00:00 poseidon-terraform poseidon[46732]: time="2024-09-17T18:30:18.570638Z" level=debug code=200 duration=717.08005ms method=GET path=/api/v1/runners/10-5a382ea3-7516-11ef-badf-fa163efe023e/websocket user_agent=
2024-09-17T18:30:18.599336+00:00 poseidon-terraform poseidon[46732]: time="2024-09-17T18:30:18.598851Z" level=debug code=200 duration="64.715µs" method=POST path=/api/v1/runners/10-5a382ea3-7516-11ef-badf-fa163efe023e/execute user_agent="Faraday

[mpass99]

When tracking the runner id (10-25237a45-751f-11ef-badf-fa163efe023e) and execution id (61e88f26-dfa3-43c1-8701-1436c94e29c9) in the logs, we come across the interesting log The client closed the connection. This means that CodeOcean has closed the WebSocket connection to the execution. In response, we cancel the execution and send the WebSocketOutputError The allocation stopped as expected. As stated in #423, I still think it's nice to do so.
So, I would say, the question is: Why did CodeOcean still receive the error when it has closed the WebSocket connection? Why does CodeOcean throw an error when Poseidon notifies about the canceled execution?

[MrSerth]

We assume that this is a problem in CodeOcean, not being caused by Poseidon.