search

jlewi / foyle

Foyle is a copilot to help developers deploy and operate their applications.
https://foyle.io
Apache License 2.0
111 stars 10 forks source link

Suggestions stop being generated when linger on a cell - Empty String Used For Completion #305

Closed jlewi closed 1 month ago

jlewi commented 1 month ago

I'm noticing instances in which if I edit a cell for a really long time completions stop being generated. I'm running with vscode extension with https://github.com/stateful/vscode-runme/pull/1713 which has support for rendering markup cells.

Foyle Server logs show.

2024-10-16T06:24:15.096-0700    INFO    agent/agent.go:452  Context cancelled; stopping streaming request   {"traceId": "2a4f9abef851a7ec16fc3930d10bfaba", "evalMode": false, "err": "context canceled"}
2024-10-16T06:24:15.097-0700    INFO    agent/agent.go:292  Context cancelled; stopping completion generation   {"traceId": "2a4f9abef851a7ec16fc3930d10bfaba", "evalMode": false}
[GIN] 2024/10/16 - 06:24:15 | 200 |          1m0s |       127.0.0.1 | POST     "/api/AIService/StreamGenerate"
2024-10-16T06:24:15.097-0700    INFO    agent/agent.go:327  Context cancelled; stop listening for requests  {"traceId": "2a4f9abef851a7ec16fc3930d10bfaba", "evalMode": false}
2024-10-16T06:24:16.307-0700    INFO    analyze/analyzer.go:522 Combining entries for trace {"targetTraceId": "2a4f9abef851a7ec16fc3930d10bfaba", "numEntries": 177}

So it looks like the streaming request hit the 1minute timeout and was cancelled. That's working as expected but the client should have attempted to start a new connection and doesn't appear to have done so.

jlewi commented 1 month ago

The output terminal in vscode for Runme shows the following.

[2024-10-16T13:23:41.461Z] INFO Runme: onDidChangeVisibleTextEditors Fired for editor vscode-notebook-cell:/Users/jlewi/foyle_experiments/20241015-ghostmarkup/experiment_ghostmarkup2.md#Y150sZmlsZQ%3D%3D
[2024-10-16T13:24:15.097Z] ERROR Runme: Error processing response: ConnectError: [internal] Stream closed with error code NGHTTP2_INTERNAL_ERROR; details: ; rawMessage: Stream closed with error code NGHTTP2_INTERNAL_ERROR
[2024-10-16T13:24:15.097Z] INFO Runme: Stream closed due to error; resetting iterator
[2024-10-16T13:31:43.545Z] INFO Runme: onDidChangeVisibleTextEditors Fired for editor vscode-notebook-cell:/Users/jlewi/foyle_experiments/20241015-baseline/experiment_baseline.md#Y313sZmlsZQ%3D%3D
[2024-10-16T13:31:43.546Z] INFO Runme: onDidChangeVisibleTextEditors Fired for editor vscode-notebook-cell:/Users/jlewi/foyle_experiments/20241015-baseline/experiment_baseline.md#Y305sZmlsZQ%3D%3D
[2024-10-16T13:31:43.546Z] INFO Runme: onDidChangeVisibleTextEditors Fired for editor vscode-notebook-cell:/Users/jlewi/foyle_experiments/20241015-baseline/experiment_baseline.md#Y303sZmlsZQ%3D%3D
[2024-10-16T13:31:43.546Z] INFO Runme: onDidChangeVisibleTextEditors Fired for editor vscode-notebook-cell:/Users/jlewi/foyle_experiments/20241015-baseline/experiment_baseline.md#Y314sZmlsZQ%3D%3D
[2024-10-16T13:31:43.546Z] INFO Runme: onDidChangeVisibleTextEditors Fired for editor vscode-notebook-cell:/Users/jlewi/foyle_experiments/20241015-baseline/experiment_baseline.md#Y330sZmlsZQ%3D%3D
[2024-10-16T13:31:43.546Z] INFO Runme: onDidChangeVisibleTextEditors Fired for editor vscode-notebook-cell:/Users/jlewi/foyle_experiments/20241015-ghostmarkup/experiment_ghostmarkup2.md#X66sZmlsZQ%3D%3D
[2024-10-16T13:31:43.546Z] INFO Runme: onDidChangeVisibleTextEditors Fired for editor vscode-notebook-cell:/Users/jlewi/foyle_experiments/20241015-ghostmarkup/experiment_ghostmarkup2.md#Y150sZmlsZQ%3D%3D
[2024-10-16T13:31:43.546Z] INFO Runme: onDidChangeVisibleTextEditors Fired for editor output:extension-output-stateful.runme-%231-Runme
[2024-10-16T13:31:43.546Z] INFO Runme: onDidChangeVisibleTextEditors Fired fo output:extension-output-stateful.runme-%231-Runme
[2024-10-16T13:31:43.578Z] INFO Runme: onDidChangeActiveTextEditor fired: editor: output:extension-output-stateful.runme-%231-Runme; new contextID: 01JAARDY2NNF0RZMH15Q27MFB7; old contextID: 01JAAQRQ8GDBQS6Z4CD4VP0XBT
jlewi commented 1 month ago

The Foyle Server logs also show a log events showing the session id changed.

2024-10-16T06:31:43.616-0700    INFO    agent/agent.go:580  LogEvent    {"eventId": "01JAARDY2QXBEC0EJY7YX10BE5", "eventType": "SESSION_END", "contextId": "01JAAQRQ8GDBQS6Z4CD4VP0XBT", "selectedCellId": "", "event": {"contextId":"01JAAQRQ8GDBQS6Z4CD4VP0XBT","eventId":"01JAARDY2QXBEC0EJY7YX10BE5","type":"SESSION_END"}}
2024-10-16T06:31:43.617-0700    INFO    agent/agent.go:580  LogEvent    {"eventId": "01JAARDY2QNXWFAP42GQDBEVP4", "eventType": "SESSION_START", "contextId": "01JAARDY2NNF0RZMH15Q27MFB7", "selectedCellId": "", "event": {"contextId":"01JAARDY2NNF0RZMH15Q27MFB7","eventId":"01JAARDY2QNXWFAP42GQDBEVP4","type":"SESSION_START"}}

This suggests the active cell editor might no longer be the same.

jlewi commented 1 month ago

If you put the focus on the output window showing VSCode Logs I think that might be triggering a change in session.

jlewi commented 1 month ago

I think there might be two issues here.

Looking at the logs it looks like no response gets generated. It looks like the LLM failed because two of the level 1 assertions failed

2024-10-16T06:47:26.763-0700    INFO    agent/agent.go:191  Level1Assert    {"traceId": "c102186465d13e31645c8f076f957af1", "streamTraceId": "48f447dde4da1aa6e7aa3f1e1f77adba", "contextId": "01JAASAERT8051YPRN6YHJ3B5Q", "traceId": "c102186465d13e31645c8f076f957af1", "evalMode": false, "assertion": {"name": "NON_EMPTY_DOC", "result": "FAILED", "detail": "", "id": "01JAASAQ5B9GDB7WNAJFX6DS6A"}}
2024-10-16T06:47:26.763-0700    INFO    agent/agent.go:202  Level1Assert    {"traceId": "c102186465d13e31645c8f076f957af1", "streamTraceId": "48f447dde4da1aa6e7aa3f1e1f77adba", "contextId": "01JAASAERT8051YPRN6YHJ3B5Q", "traceId": "c102186465d13e31645c8f076f957af1", "evalMode": false, "assertion": {"name": "NON_EMPTY_DOC", "result": "FAILED", "detail": "", "id": "01JAASAQ5B9GDB7WNAJFX6DS6A"}}
2024-10-16T06:47:26.763-0700    INFO    agent/agent.go:119  Level1Assert    {"traceId": "c102186465d13e31645c8f076f957af1", "streamTraceId": "48f447dde4da1aa6e7aa3f1e1f77adba", "contextId": "01JAASAERT8051YPRN6YHJ3B5Q", "traceId": "c102186465d13e31645c8f076f957af1", "evalMode": false, "assertion": {"name": "AT_LEAST_ONE_BLOCK_POST_PROCESSED", "result": "FAILED", "detail": "", "id": "01JAASAQ5B9GDB7WNAJHXFS68P"}}
2024-10-16T06:47:26.763-0700    INFO    agent/agent.go:129  Agent.Generate returning blocks {"traceId": "c102186465d13e31645c8f076f957af1", "streamTraceId": "48f447dde4da1aa6e7aa3f1e1f77adba", "contextId": "01JAASAERT8051YPRN6YHJ3B5Q", "traceId": "c102186465d13e31645c8f076f957af1", "evalMode": false, "blockIds": []}

So no blocks are being returned.

However, its still not clear to me why in the original logs a new Stream request wasn't initiated after the context was cancelled.

jlewi commented 1 month ago

In the current implementation, if no non-empty blocks are generated then no response is returned to the client. This was done intentionally to prevent "empty response" from wiping out previous completions. This change happened in #270. So I think what I'm observing is that for some reason the doc ends up being empty leading to no response cells being generated; in which case we keep whatever suggestion is already there.