(bug) AO indicated running but they aint - no logged errors

Question

(bug) AO indicated running but they aint - no logged errors

Closed this issue 2 years ago · 6 comments

3.31.1 stable

AOs.not.running.mp4

Ping-pong fails to create pongs, upon closer inspection all AOs show to be stalled.

This time, no logged errors of connectivity or whatever. At least previously, we had the 'cancel-cross' go missing, but that no longer applies.

The case of #705 is not solved. Same now as #751, except there is no problem logged before it the AO dropped.

The log shows:
a) Creating a 3rd AO Ping-Pong
b) Meta-reloaded after 1 hour or so
c) The Pings are triggered but no Pongs issued (already stalled)
d) Attempt to close the AOs is rejected as they are not running

bfx:hf:algo:ao-host:ws2:bind-bus enqueue order:new +5m
bfx:hf:algo:ao-host:ws2:process-message process order:new [-150/-150 @ 1.02 ACTIVE] +5m
bfx:hf:algo:ao-host triggering order event orders:order_new for AO bfx-ping_pong [gid 3689588785152, o cid 3689588785153, -150 @ 1.02 ACTIVE] +41ms
bfx:hf:algo:bfx-ping_pong:3689588785152 order successfully submitted: LIMIT -150 @ 1.02 ACTIVE +31ms
bfx:hf:algo:ao-host:ws2:bind-bus enqueue order:new +3ms
bfx:hf:algo:ao-host:ws2:process-message process order:new [-150/-150 @ 1.0229 ACTIVE] +2ms
bfx:hf:algo:ao-host triggering order event orders:order_new for AO bfx-ping_pong [gid 3689588785152, o cid 3689588785154, -150 @ 1.0229 ACTIVE] +2ms
bfx:hf:algo:bfx-ping_pong:3689588785152 order successfully submitted: LIMIT -150 @ 1.0229 ACTIVE +2ms
bfx:hf:algo:bfx-ping_pong:3689588785152 order successfully submitted: LIMIT -150 @ 1.0257 ACTIVE +4ms
bfx:hf:algo:ao-host:ws2:bind-bus enqueue order:new +7ms
bfx:hf:algo:ao-host:ws2:process-message process order:new [-150/-150 @ 1.0257 ACTIVE] +7ms
bfx:hf:algo:ao-host triggering order event orders:order_new for AO bfx-ping_pong [gid 3689588785152, o cid 3689588785155, -150 @ 1.0257 ACTIVE] +7ms
bfx:hf:algo:bfx-ping_pong:3689588785152 order successfully submitted: LIMIT -150 @ 1.0286 ACTIVE +8ms
bfx:hf:algo:ao-host:ws2:bind-bus enqueue order:new +6ms
bfx:hf:algo:ao-host:ws2:process-message process order:new [-150/-150 @ 1.0286 ACTIVE] +7ms
bfx:hf:algo:ao-host triggering order event orders:order_new for AO bfx-ping_pong [gid 3689588785152, o cid 3689588785156, -150 @ 1.0286 ACTIVE] +7ms
bfx:hf:algo:ao-host:ws2:bind-bus enqueue order:new +7ms
bfx:hf:algo:ao-host:ws2:process-message process order:new [-150/-150 @ 1.0314 ACTIVE] +6ms
bfx:hf:algo:ao-host triggering order event orders:order_new for AO bfx-ping_pong [gid 3689588785152, o cid 3689588785157, -150 @ 1.0314 ACTIVE] +6ms
bfx:hf:algo:bfx-ping_pong:3689588785152 order successfully submitted: LIMIT -150 @ 1.0314 ACTIVE +8ms
bfx:hf:algo:ao-host:ws2:bind-bus enqueue order:new +4ms
bfx:hf:algo:ao-host:ws2:process-message process order:new [-150/-150 @ 1.0343 ACTIVE] +4ms
bfx:hf:algo:ao-host triggering order event orders:order_new for AO bfx-ping_pong [gid 3689588785152, o cid 3689588785158, -150 @ 1.0343 ACTIVE] +4ms
bfx:hf:algo:bfx-ping_pong:3689588785152 order successfully submitted: LIMIT -150 @ 1.0343 ACTIVE +4ms
bfx:hf:algo:ao-host:ws2:bind-bus enqueue order:new +6ms
bfx:hf:algo:ao-host:ws2:process-message process order:new [-150/-150 @ 1.0371 ACTIVE] +6ms
bfx:hf:algo:ao-host triggering order event orders:order_new for AO bfx-ping_pong [gid 3689588785152, o cid 3689588785159, -150 @ 1.0371 ACTIVE] +6ms
bfx:hf:algo:bfx-ping_pong:3689588785152 order successfully submitted: LIMIT -150 @ 1.0371 ACTIVE +7ms
bfx:hf:algo:ao-host:ws2:bind-bus enqueue order:new +7ms
bfx:hf:algo:ao-host:ws2:process-message process order:new [-150/-150 @ 1.04 ACTIVE] +7ms
bfx:hf:algo:ao-host triggering order event orders:order_new for AO bfx-ping_pong [gid 3689588785152, o cid 3689588785160, -150 @ 1.04 ACTIVE] +8ms
bfx:hf:algo:bfx-ping_pong:3689588785152 order successfully submitted: LIMIT -150 @ 1.04 ACTIVE +7ms
bfx:hf:algo:bfx-ping_pong:3689588785152 order successfully submitted: LIMIT -150 @ 1.0429 ACTIVE +3ms
bfx:hf:algo:ao-host:ws2:bind-bus enqueue order:new +6ms
bfx:hf:algo:ao-host:ws2:process-message process order:new [-150/-150 @ 1.0429 ACTIVE] +6ms
bfx:hf:algo:ao-host triggering order event orders:order_new for AO bfx-ping_pong [gid 3689588785152, o cid 3689588785161, -150 @ 1.0429 ACTIVE] +5ms
bfx:hf:algo:bfx-ping_pong:3689588785152 order successfully submitted: LIMIT -150 @ 1.0457 ACTIVE +5ms
bfx:hf:algo:ao-host:ws2:bind-bus enqueue order:new +5ms
bfx:hf:algo:ao-host:ws2:process-message process order:new [-150/-150 @ 1.0457 ACTIVE] +5ms
bfx:hf:algo:ao-host triggering order event orders:order_new for AO bfx-ping_pong [gid 3689588785152, o cid 3689588785162, -150 @ 1.0457 ACTIVE] +5ms
bfx:hf:algo:bfx-ping_pong:3689588785152 order successfully submitted: LIMIT -150 @ 1.0486 ACTIVE +5ms
bfx:hf:algo:ao-host:ws2:bind-bus enqueue order:new +4ms
bfx:hf:algo:ao-host:ws2:process-message process order:new [-150/-150 @ 1.0486 ACTIVE] +4ms
bfx:hf:algo:ao-host triggering order event orders:order_new for AO bfx-ping_pong [gid 3689588785152, o cid 3689588785163, -150 @ 1.0486 ACTIVE] +5ms
bfx:hf:algo:bfx-ping_pong:3689588785152 order successfully submitted: LIMIT -150 @ 1.0514 ACTIVE +6ms
bfx:hf:algo:ao-host:ws2:bind-bus enqueue order:new +6ms
bfx:hf:algo:ao-host:ws2:process-message process order:new [-150/-150 @ 1.0514 ACTIVE] +7ms
bfx:hf:algo:ao-host triggering order event orders:order_new for AO bfx-ping_pong [gid 3689588785152, o cid 3689588785164, -150 @ 1.0514 ACTIVE] +6ms
bfx:hf:algo:ao-host:ws2:bind-bus enqueue order:new +9ms
bfx:hf:algo:ao-host:ws2:process-message process order:new [-150/-150 @ 1.0543 ACTIVE] +8ms
bfx:hf:algo:ao-host triggering order event orders:order_new for AO bfx-ping_pong [gid 3689588785152, o cid 3689588785165, -150 @ 1.0543 ACTIVE] +8ms
bfx:hf:algo:bfx-ping_pong:3689588785152 order successfully submitted: LIMIT -150 @ 1.0543 ACTIVE +10ms
bfx:hf:algo:bfx-ping_pong:3689588785152 order successfully submitted: LIMIT -150 @ 1.0571 ACTIVE +2ms
bfx:hf:algo:ao-host:ws2:bind-bus enqueue order:new +3ms
bfx:hf:algo:ao-host:ws2:process-message process order:new [-150/-150 @ 1.0571 ACTIVE] +4ms
bfx:hf:algo:ao-host triggering order event orders:order_new for AO bfx-ping_pong [gid 3689588785152, o cid 3689588785166, -150 @ 1.0571 ACTIVE] +4ms
bfx:hf:algo:bfx-ping_pong:3689588785152 order successfully submitted: LIMIT -150 @ 1.06 ACTIVE +6ms
bfx:hf:server:algo-worker ao started: Ping/Pong PP 15x -150:150 @ 1.02..1.06:-0.01 | (-2250:2250) +5m
bfx:hf:server:algo-worker ao instance updated 3689588785152 +1ms
bfx:hf:algo:ao-host:ws2:bind-bus enqueue order:new +7ms
bfx:hf:algo:ao-host:ws2:process-message process order:new [-150/-150 @ 1.06 ACTIVE] +6ms
bfx:hf:algo:ao-host triggering order event orders:order_new for AO bfx-ping_pong [gid 3689588785152, o cid 3689588785167, -150 @ 1.06 ACTIVE] +6ms
bfx:hf:algo:ao-host:ws2:bind-bus enqueue open +1h
bfx:hf:algo:ao-host:ws2:process-message process open +1h
bfx:hf:server:algo-worker meta reloaded +1h
bfx:hf:algo:ao-host:ws2:bind-bus enqueue auth:success +31ms
bfx:hf:algo:ao-host:ws2:process-message process auth:success +30ms
bfx:hf:algo:ao-host:ws2:bind-bus enqueue order:snapshot +41ms
bfx:hf:algo:ao-host:ws2:process-message process order:snapshot +42ms
bfx:hf:algo:ao-host:ws2:bind-bus enqueue order:update +9h
bfx:hf:algo:ao-host:ws2:process-message process order:update [-146.5/-150 @ 1.02 PARTIALLY FILLED @ 1.02(-3.5)] +9h
bfx:hf:algo:ao-host:ws2:bind-bus enqueue order:update +5s
bfx:hf:algo:ao-host:ws2:process-message process order:update [-102.176227/-150 @ 1.02 PARTIALLY FILLED @ 1.02(-3.5), PARTIALLY FILLED @ 1.02(-44.323773)] +5s
bfx:hf:algo:ao-host:ws2:bind-bus enqueue order:update +2h
bfx:hf:algo:ao-host:ws2:process-message process order:update [-100.03152797/-150 @ 1.02 PARTIALLY FILLED @ 1.02(-3.5), PARTIALLY FILLED @ 1.02(-44.323773), PARTIALLY FILLED @ 1.02(-2.14469903)] +2h
bfx:hf:algo:ao-host:ws2:bind-bus enqueue order:update +2h
bfx:hf:algo:ao-host:ws2:process-message process order:update [-96.7784408/-150 @ 1.02 PARTIALLY FILLED @ 1.02(-3.5), PARTIALLY FILLED @ 1.02(-44.323773), PARTIALLY FILLED @ 1.02(-2.14469903), PARTIALLY FILLED @ 1.02(-3.25308717)] +2h
bfx:hf:algo:ao-host:ws2:bind-bus enqueue order:close +2h
bfx:hf:algo:ao-host:ws2:process-message process order:close [0/-150 @ 1.02 EXECUTED @ 1.02(-96.7784408): was PARTIALLY FILLED @ 1.02(-3.5), PARTIALLY FILLED @ 1.02(-44.323773), PARTIALLY FILLED @ 1.02(-2.14469903), PARTIALLY FILLED @ 1.02(-3.25308717)] +2h
bfx:hf:algo:ao-host:ws2:bind-bus enqueue order:update +6m
bfx:hf:algo:ao-host:ws2:process-message process order:update [-111.3276/-150 @ 1.0229 PARTIALLY FILLED @ 1.0229(-38.6724)] +6m
bfx:hf:algo:ao-host:ws2:bind-bus enqueue order:close +260ms
bfx:hf:algo:ao-host:ws2:process-message process order:close [0/-150 @ 1.0229 EXECUTED @ 1.0229(-111.3276): was PARTIALLY FILLED @ 1.0229(-38.6724)] +260ms
bfx:hf:algo:ao-host:ws2:bind-bus enqueue order:update +1m
bfx:hf:algo:ao-host:ws2:process-message process order:update [-100/-150 @ 1.0257 PARTIALLY FILLED @ 1.0257(-50.0)] +1m
bfx:hf:algo:ao-host:ws2:bind-bus enqueue order:close +11s
bfx:hf:algo:ao-host:ws2:process-message process order:close [0/-150 @ 1.0257 EXECUTED @ 1.0257(-100.0): was PARTIALLY FILLED @ 1.0257(-50.0)] +11s
bfx:hf:algo:ao-host:ws2:bind-bus enqueue order:update +35m
bfx:hf:algo:ao-host:ws2:process-message process order:update [-100/-150 @ 1.0286 PARTIALLY FILLED @ 1.0286(-50.0)] +35m
bfx:hf:algo:ao-host:ws2:bind-bus enqueue order:update +701ms
bfx:hf:algo:ao-host:ws2:process-message process order:update [-0.0001/-150 @ 1.0286 PARTIALLY FILLED @ 1.0286(-50.0), PARTIALLY FILLED @ 1.0286(-99.9999)] +700ms
bfx:hf:algo:ao-host:ws2:bind-bus enqueue order:close +15s
bfx:hf:algo:ao-host:ws2:process-message process order:close [0/-150 @ 1.0286 EXECUTED @ 1.0286(-0.0001): was PARTIALLY FILLED @ 1.0286(-50.0), PARTIALLY FILLED @ 1.0286(-99.9999)] +15s
bfx:hf:algo:ao-host:ws2:bind-bus enqueue order:update +40s
bfx:hf:algo:ao-host:ws2:process-message process order:update [-100/-150 @ 1.0314 PARTIALLY FILLED @ 1.0314(-50.0)] +40s
bfx:hf:algo:ao-host:ws2:bind-bus enqueue order:update +486ms
bfx:hf:algo:ao-host:ws2:process-message process order:update [-98/-150 @ 1.0314 PARTIALLY FILLED @ 1.0314(-50.0), PARTIALLY FILLED @ 1.0314(-2.0)] +486ms
bfx:hf:algo:ao-host:ws2:bind-bus enqueue order:update +348ms
bfx:hf:algo:ao-host:ws2:process-message process order:update [-48/-150 @ 1.0314 PARTIALLY FILLED @ 1.0314(-50.0), PARTIALLY FILLED @ 1.0314(-2.0), PARTIALLY FILLED @ 1.0314(-50.0)] +348ms
bfx:hf:algo:ao-host:ws2:bind-bus enqueue order:close +18s
bfx:hf:algo:ao-host:ws2:process-message process order:close [0/-150 @ 1.0314 EXECUTED @ 1.0314(-48.0): was PARTIALLY FILLED @ 1.0314(-50.0), PARTIALLY FILLED @ 1.0314(-2.0), PARTIALLY FILLED @ 1.0314(-50.0)] +18s
bfx:hf:algo:ao-host:ws2:bind-bus enqueue order:update +1m
bfx:hf:algo:ao-host:ws2:process-message process order:update [-100/-150 @ 1.0343 PARTIALLY FILLED @ 1.0343(-50.0)] +1m
bfx:hf:algo:ao-host:ws2:bind-bus enqueue order:update +583ms
bfx:hf:algo:ao-host:ws2:process-message process order:update [-50/-150 @ 1.0343 PARTIALLY FILLED @ 1.0343(-50.0), PARTIALLY FILLED @ 1.0343(-50.0)] +583ms
bfx:hf:algo:ao-host:ws2:bind-bus enqueue order:close +16s
bfx:hf:algo:ao-host:ws2:process-message process order:close [0/-150 @ 1.0343 EXECUTED @ 1.0343(-50.0): was PARTIALLY FILLED @ 1.0343(-50.0), PARTIALLY FILLED @ 1.0343(-50.0)] +16s
bfx:hf:algo:ao-host:ws2:bind-bus enqueue order:update +56s
bfx:hf:algo:ao-host:ws2:process-message process order:update [-0.0001/-150 @ 1.0371 PARTIALLY FILLED @ 1.0371(-149.9999)] +56s
bfx:hf:algo:ao-host:ws2:bind-bus enqueue order:close +43s
bfx:hf:algo:ao-host:ws2:process-message process order:close [0/-150 @ 1.0371 EXECUTED @ 1.0371(-0.0001): was PARTIALLY FILLED @ 1.0371(-149.9999)] +43s
bfx:hf:algo:ao-host:ws2:bind-bus enqueue order:close +51s
bfx:hf:algo:ao-host:ws2:process-message process order:close [0/-150 @ 1.04 EXECUTED @ 1.04(-150.0)] +51s
bfx:hf:algo:ao-host:ws2:bind-bus enqueue order:update +5m
bfx:hf:algo:ao-host:ws2:process-message process order:update [-147.7091994/-150 @ 1.0429 PARTIALLY FILLED @ 1.0429(-2.2908006)] +5m
bfx:hf:algo:ao-host:ws2:bind-bus enqueue order:update +13s
bfx:hf:algo:ao-host:ws2:process-message process order:update [-145.05709226/-150 @ 1.0429 PARTIALLY FILLED @ 1.0429(-2.2908006), PARTIALLY FILLED @ 1.0429(-2.65210714)] +13s
bfx:hf:algo:ao-host:ws2:bind-bus enqueue order:update +1m
bfx:hf:algo:ao-host:ws2:process-message process order:update [-25.05709226/-150 @ 1.0429 PARTIALLY FILLED @ 1.0429(-2.2908006), PARTIALLY FILLED @ 1.0429(-2.65210714), PARTIALLY FILLED @ 1.0429(-120.0)] +1m
bfx:hf:algo:ao-host:ws2:bind-bus enqueue order:update +41s
bfx:hf:algo:ao-host:ws2:process-message process order:update [-0.05709226/-150 @ 1.0429 PARTIALLY FILLED @ 1.0429(-2.2908006), PARTIALLY FILLED @ 1.0429(-2.65210714), PARTIALLY FILLED @ 1.0429(-120.0), PARTIALLY FILLED @ 1.0429(-25.0)] +41s
bfx:hf:algo:ao-host:ws2:bind-bus enqueue order:close +32ms
bfx:hf:algo:ao-host:ws2:process-message process order:close [0/-150 @ 1.0429 EXECUTED @ 1.0429(-0.05709226): was PARTIALLY FILLED @ 1.0429(-2.2908006), PARTIALLY FILLED @ 1.0429(-2.65210714), PARTIALLY FILLED @ 1.0429(-120.0), PARTIALLY FILLED @ 1.0429(-25.0)] +31ms
bfx:hf:algo:ao-host:ws2:bind-bus enqueue order:update +2m
bfx:hf:algo:ao-host:ws2:process-message process order:update [-146.08841242/-150 @ 1.0457 PARTIALLY FILLED @ 1.0457(-3.91158758)] +2m
bfx:hf:algo:ao-host:ws2:bind-bus enqueue order:close +4s
bfx:hf:algo:ao-host:ws2:process-message process order:close [0/-150 @ 1.0457 EXECUTED @ 1.0457(-146.08841242): was PARTIALLY FILLED @ 1.0457(-3.91158758)] +4s
bfx:hf:algo:ao-host:ws2:bind-bus enqueue order:close +5m
bfx:hf:algo:ao-host:ws2:process-message process order:close [0/-150 @ 1.0486 EXECUTED @ 1.0486(-150.0)] +5m
bfx:hf:algo:ao-host:ws2:bind-bus enqueue order:update +6m
bfx:hf:algo:ao-host:ws2:process-message process order:update [-123.57138109/-150 @ 1.0514 PARTIALLY FILLED @ 1.0514(-26.42861891)] +6m
bfx:hf:algo:ao-host:ws2:bind-bus enqueue order:close +1ms
bfx:hf:algo:ao-host:ws2:process-message process order:close [0/-150 @ 1.0514 EXECUTED @ 1.0514(-123.57138109): was PARTIALLY FILLED @ 1.0514(-26.42861891)] +1ms
bfx:hf:algo:ao-host:ws2:bind-bus enqueue order:close +1h
bfx:hf:algo:ao-host:ws2:process-message process order:close [0/-150 @ 1.0543 EXECUTED @ 1.0543(-150.0)] +1h
bfx:hf:algo:ao-host:ws2:bind-bus enqueue order:update +10m
bfx:hf:algo:ao-host:ws2:process-message process order:update [-70/-150 @ 1.0571 PARTIALLY FILLED @ 1.0571(-80.0)] +10m
bfx:hf:algo:ao-host:ws2:bind-bus enqueue order:close +9s
bfx:hf:algo:ao-host:ws2:process-message process order:close [0/-150 @ 1.0571 EXECUTED @ 1.0571(-70.0): was PARTIALLY FILLED @ 1.0571(-80.0)] +9s
bfx:hf:algo:ao-host:ws2:bind-bus enqueue order:close +448ms
bfx:hf:algo:ao-host:ws2:process-message process order:close [0/-150 @ 1.06 EXECUTED @ 1.06(-150.0)] +448ms
websocket error: Requested algo order not running, cannot stop
websocket error: Requested algo order not running, cannot stop
websocket error: Requested algo order not running, cannot stop
websocket error: Requested algo order not running, cannot stop
websocket error: Requested algo order not running, cannot stop
websocket error: Requested algo order not running, cannot stop

Answer 1 · 2022-10-15T14:43:34.000Z

Kindly note this issue is not reporting the AOs dropped offline, but the fact that this is not indicated at all

How to populate the place-holder in the WS2 API with correct AO count, when the HF-UI itself cannot show what's running and what's not?!

The longevity of 1 (or 3) hours is not the greatest, sure.

But at least a month ago we could see the AOs are stopped with the "X" button go missing, but even that is lost.

What is the way out, feels like reporting the same over and over again.

Answer 2 · 2022-10-24T18:12:35.000Z

Honey really needs to catch these and report to the user. Average AO survival time 1hr 15 mins 👎

Answer 3 · 2022-10-25T18:31:38.000Z

Hi @pointops, thanks for sharing more info; it will be helpful for us to investigate. We are currently working on improving the logs and the overall resilience of the app.

Answer 4 · 2022-10-26T06:08:36.000Z

I need a bit of help, perhaps. Running the develpment mode and in-browser access on localhost:3000 - are there any logfiles being created? I cannot seem to find them, all I have is the watch of the processes in my tmux. Many thanks, p/o. On 25.10.2022 20:31:51, Tarcísio Zotelli Ferraz ***@***.***> wrote: Hi @pointops [https://github.com/pointops], thanks for sharing more info; it will be helpful for us to investigate. We are currently working on improving the logs and the overall resilience of the app. — Reply to this email directly, view it on GitHub [#756 (comment)], or unsubscribe [https://github.com/notifications/unsubscribe-auth/ATHKSQX7LAK7EWC6EP4HUL3WFARRJANCNFSM6AAAAAARF53P7U]. You are receiving this because you were mentioned.Message ID: ***@***.***> [75c14ee2-752a-4ab6-9197-908364e8ec49]

Answer 5 · 2022-10-28T23:09:02.000Z

More error showed and logged, yet no UI reaction or re-launch.

Answer 6 · 2022-12-21T19:28:01.000Z

The AOs are now removed from view after a meta-reloaded flush. Core of the issue is fixed.