Fix Learning: Cell Executions Not Being Added to BlockLogs (#233)

* Learning was broken because cell executions were not being properly
extracted from LogEvents and added to the BlockLog.
* The problem is that the logging of LogEvents happens inside an
anonymous function. Therefore the function name generated by GoLang has
a suffix like "func1"; therefore our code in the Analyzer was not
correctly matching it and therefore log events were not being processed.
* The fix is to match by using `HasPrefix`. This is still brittle. 
* Per #232 we'd like to start to fix this brittleness by using
reflection and source code analysis in unittests to ensure the
correctness of matchers for LogEntries.
* This PR introduces a matchers package which verifies correctness of
the function name but doesn't properly catch the anonymous function
which broke learning here

* Update the troubleshooting guide for learning
  * Move the troubleshooting guide into the docs page
* Update the instructions for fetching the blocklogs; we now use the
connect protocol

## Strip metadata from markdown

* Create a simple tool to strip cell ids from markdown.
* This is hack to make it easy to use RunMe markdown docs with Hugo; see
stateful/runme#663

app/pkg/analyze/analyzer.go

@@ -11,6 +11,8 @@ import (
 	"sync"
 	"time"
 
+	"github.com/jlewi/foyle/app/pkg/logs/matchers"
+
 	"github.com/jlewi/foyle/app/pkg/runme/converters"
 	parserv1 "github.com/stateful/runme/v3/pkg/api/gen/proto/go/runme/parser/v1"
 	"google.golang.org/protobuf/proto"
@@ -257,7 +259,7 @@ func (a *Analyzer) processLogFile(ctx context.Context, path string) error {
 				continue
 			}
 
-			if strings.HasSuffix(entry.Function(), "agent.(*Agent).LogEvents") {
+			if matchers.IsLogEvent(entry.Function()) {
 				a.processLogEvent(ctx, entry)
 				continue
 			}
@@ -375,7 +377,6 @@ func (a *Analyzer) setLogFileOffset(path string, offset int64) {
 	if err := os.Rename(tempFile, a.logOffsetsFile); err != nil {
 		log.Error(err, "Failed to rename watermarks file", "tempFile", tempFile, "logOffsetsFile", a.logOffsetsFile)
 	}
-	log.V(logs.Debug).Info("Wrote watermarks", "logOffsetsFile", a.logOffsetsFile)
 }
 
 func (a *Analyzer) Shutdown(ctx context.Context) error {

app/pkg/logs/matchers/names.go

@@ -0,0 +1,17 @@
+// Package matchers contains matchers to detect if a log entry corresponds to a particular type of event.
+// These function names are used to delegate the log message to the correct post processor.
+// Correctness is ensured via the unittest which uses reflection to ensure the function names are correct.
+package matchers
+
+import "strings"
+
+const (
+	LogEvents      = "github.com/jlewi/foyle/app/pkg/agent.(*Agent).LogEvents"
+	StreamGenerate = "github.com/jlewi/foyle/app/pkg/agent.(*Agent).StreamGenerate"
+)
+
+func IsLogEvent(fname string) bool {
+	// We need to use HasPrefix because the logging statement is nested inside an anonymous function so there
+	// will be a suffix like "func1"
+	return strings.HasPrefix(fname, LogEvents)
+}

app/pkg/logs/matchers/names_test.go

@@ -0,0 +1,43 @@
+package matchers
+
+import (
+	"reflect"
+	"runtime"
+	"strings"
+	"testing"
+
+	"github.com/jlewi/foyle/app/pkg/agent"
+)
+
+func GetFunctionNameFromFunc(f interface{}) string {
+	name := runtime.FuncForPC(reflect.ValueOf(f).Pointer()).Name()
+
+	// GoLang adds a -fm suffix to the function name when dealing with a method that
+	// has been converted to a function value. So we trim it to match what we get at runtime.
+	name = strings.TrimSuffix(name, "-fm")
+	return name
+}
+
+func Test_Names(t *testing.T) {
+	type testCases struct {
+		expected string
+		input    interface{}
+	}
+
+	cases := []testCases{
+		{
+			expected: LogEvents,
+			input:    (&agent.Agent{}).LogEvents,
+		},
+		{
+			expected: StreamGenerate,
+			input:    (&agent.Agent{}).StreamGenerate,
+		},
+	}
+
+	for _, c := range cases {
+		if got := GetFunctionNameFromFunc(c.input); got != c.expected {
+			t.Errorf("Expected %s, but got %s", c.expected, got)
+		}
+	}
+}

docs/content/en/docs/learning/troubleshoot_learning.md

@@ -0,0 +1,165 @@
+# Troubleshoot Learning
+
+## What You'll Learn
+
+* How to ensure learning is working and monitor learning
+
+## Check Examples
+
+If Foyle is learning there should be example files in ${HOME}/.foyle/training
+
+```sh
+ls -la ~/.foyle/training
+```
+
+The output should include `example.binpb` files as illustrated below.
+
+```sh
+-rw-r--r--    1 jlewi  staff   9895 Aug 28 07:46 01J6CQ6N02T7J16RFEYCT8KYWP.example.binpb
+```
+
+If there aren't any then no examples have been learned.
+
+## Trigger Learning
+
+Foyle's learning is triggered by the following sequence of actions:
+
+1. Foyle generates a suggested cell which is added to the notebook as a Ghost Cell
+2. You accept the suggested cell by putting the focus on the cell
+3. You edit the cell
+4. You execute the cell
+
+When you execute the cell, the execution is logged to Foyle. For each executed cell Foyle checks
+
+1. Was that cell generated by Foyle
+2. If the cell was generated by Foyle did the actual command executed differ from the suggested command
+3. If the cell was changed by the user than Foyle attempts to learn from that execution
+
+Crucially, every cell created by Foyle is assigned an ID. This ID can be used to track how the cell was generated and if learning occurred.
+
+To get the cell ID for a given cell
+
+1. Open the raw markdown file by right clicking on it in VSCode and selecting `Open With` -> `Text Editor`
+2. Find code block containing your cell
+3. Your cell will contain metadata which contains the ID e.g.
+
+```
+```bash {"id":"01J6DG428ER427GJNTKC15G6JM"}
+CELLID=01J6DFZ9V3R29TCDEY2AYA8XTV
+curl http://localhost:8080/api/blocklogs/${CELLID} | jq .
+```
+```
+
+## Did Block Logs Get Created
+
+* Get the block logs for the cell
+* Change the cell ID to the ULID of the cell (you can view this in the markdown)
+* The cell should be one that was generated by the AI and you think learning should have occurred on
+
+```bash
+CELLID=01J7KQPBYCT9VM2KFBY48JC7J0
+curl -X POST http://localhost:8877/api/foyle.logs.LogsService/GetBlockLog -H "Content-Type: application/json" -d "{\"id\": \"${CELLID}\"}" | jq .
+```
+
+* If this returns not found then no log was created for this cell and there is a problem with Log Processing
+* The correct output should look like the following
+
+```
+{
+  "blockLog": {
+    "id": "01J7KQPBYCT9VM2KFBY48JC7J0",
+    "genTraceId": "0376c6dc6309bcd5d61e7b56e41d6411",
+    "doc": {
+      ...
+    },
+    "generatedBlock": {
+      "kind": "CODE",
+      "language": "bash",
+      "contents": "jq -c 'select(.severity == \"error\" or .level == \"error\")' ${LASTLOG}",
+      "id": "01J7KQPBYCT9VM2KFBY48JC7J0"
+    },
+    "executedBlock": {
+      "kind": "CODE",
+      "contents": "CELLID=01J7KQPBYCT9VM2KFBY48JC7J0\ncurl -X POST http://localhost:8877/api/foyle.logs.LogsService/GetBlockLog -H \"Content-Type: application/json\" -d \"{\\\"id\\\": \\\"${CELLID}\\\"}\" | jq .",
+      "id": "01J7KQPBYCT9VM2KFBY48JC7J0"
+    },
+    "resourceVersion": "34d933d8-abe6-4ad3-b9cf-5a2392f34abb"
+  }
+}
+```
+
+* Notably the output should include the following fields
+
+  * **generatedBlock** - This is the block that was generated by the AI
+  * **executedBlock** - This is the block that the user actually executed
+
+* If the **generatedBlock** and **executedBlock** are the same then no learning occured
+* If the **generatedBlock** is missing then this means the block wasn't generated by Foyle and learning won't occur
+  * This can happen if you insert a blank cell and manually enter a command
+* If the **executedBlock** is missing then this means the block wasn't executed and learning won't occur
+
+## Was a cell executed?
+
+* If a block is missing the **executedBlock** then we should check the logs to see if there is an event for cell execution
+
+```bash
+export LASTLOG=~/.foyle/logs/raw/$(ls -t ~/.foyle/logs/raw | head -n 1 )
+echo "Last log file: ${LASTLOG}"
+jq -c "select(.selectedCellId == \"01J7KQPBYCT9VM2KFBY48JC7J0\")" ${LASTLOG}
+```
+
+* If there are no execution events then the cell was never executed
+* If you executed the cell but there are no log events then there is most likely a bug and please open an issue in [GitHub](https://github.com/jlewi/foyle/issues)
+
+## Check the logs associated with that cell
+
+* We can search for all logs associated with that cell
+
+```bash
+export LASTLOG=~/.foyle/logs/raw/$(ls -t ~/.foyle/logs/raw | head -n 1 )
+echo "Last log file: ${LASTLOG}"
+jq -c "select(.blockId == \"${CELLID}\")" ${LASTLOG}
+```
+
+* Check for any errors processing the block
+* Note that the above command will only process the most recent log file
+* Each time Foyle is restarted it will create a new log file.
+
+### Did we try to create an example from any cells?
+
+* If Foyle tries to learn from a cell it logs a message [here](https://github.com/jlewi/foyle/blob/4288e91ac805b46103d94230b32dd1bc2f957095/app/pkg/learn/learner.go#L155)
+* We can query for that log as follows
+
+```bash
+jq -c 'select(.message == "Found new training example")' ${LASTLOG}
+```
+
+* If that returns nothing then we know Foyle never tried to learn from any cells
+* If it returns something then we know Foyle tried to learn from a cell but it may have failed
+* If there is an error processing an example it gets logged [here](https://github.com/jlewi/foyle/blob/4288e91ac805b46103d94230b32dd1bc2f957095/app/pkg/learn/learner.go#L205)
+* So we can search for that error message in the logs
+
+```bash
+jq -c 'select(.level == "Failed to write example")' ${LASTLOG}
+```
+
+```bash
+jq -c 'select(.level == "error" and .message == "Failed to write example")' ${LASTLOG}
+```
+
+## Ensure Block Logs are being created
+
+* The query below checks that block logs are being created.
+* If no logs are being processed than there is a problem with the block log processing.
+
+```bash
+jq -c 'select(.message == "Building block log")' ${LASTLOG}
+```
+
+## Are there any errors in the logs
+
+* The query below should show you any errors in the logs.
+
+```bash
+jq -c 'select(.severity == "error")' ${LASTLOG}
+```

tools/stripmetadata/go.mod

@@ -0,0 +1,11 @@
+module github.com/jlewi/foyle/tools/stripmetadata
+
+go 1.22.5
+
+require (
+	github.com/Kunde21/markdownfmt/v3 v3.1.0
+	github.com/pkg/errors v0.9.1
+	github.com/yuin/goldmark v1.7.4
+)
+
+require github.com/mattn/go-runewidth v0.0.9 // indirect

tools/stripmetadata/go.sum

@@ -0,0 +1,16 @@
+github.com/Kunde21/markdownfmt/v3 v3.1.0 h1:KiZu9LKs+wFFBQKhrZJrFZwtLnCCWJahL+S+E/3VnM0=
+github.com/Kunde21/markdownfmt/v3 v3.1.0/go.mod h1:tPXN1RTyOzJwhfHoon9wUr4HGYmWgVxSQN6VBJDkrVc=
+github.com/davecgh/go-spew v1.1.1 h1:vj9j/u1bqnvCEfJOwUhtlOARqs3+rkHYY13jYWTU97c=
+github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38=
+github.com/mattn/go-runewidth v0.0.9 h1:Lm995f3rfxdpd6TSmuVCHVb/QhupuXlYr8sCI/QdE+0=
+github.com/mattn/go-runewidth v0.0.9/go.mod h1:H031xJmbD/WCDINGzjvQ9THkh0rPKHF+m2gUSrubnMI=
+github.com/pkg/errors v0.9.1 h1:FEBLx1zS214owpjy7qsBeixbURkuhQAwrK5UwLGTwt4=
+github.com/pkg/errors v0.9.1/go.mod h1:bwawxfHBFNV+L2hUp1rHADufV3IMtnDRdf1r5NINEl0=
+github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZbAQM=
+github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4=
+github.com/stretchr/testify v1.8.1 h1:w7B6lhMri9wdJUVmEZPGGhZzrYTPvgJArz7wNPgYKsk=
+github.com/stretchr/testify v1.8.1/go.mod h1:w2LPCIKwWwSfY2zedu0+kehJoqGctiVI29o6fzry7u4=
+github.com/yuin/goldmark v1.7.4 h1:BDXOHExt+A7gwPCJgPIIq7ENvceR7we7rOS9TNoLZeg=
+github.com/yuin/goldmark v1.7.4/go.mod h1:uzxRWxtg69N339t3louHJ7+O03ezfj6PlliRlaOzY1E=
+gopkg.in/yaml.v3 v3.0.1 h1:fxVm/GzAzEWqLHuvctI91KS9hhNmmWOoWu0XTYJS7CA=
+gopkg.in/yaml.v3 v3.0.1/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM=