Possible issue with logger batch handler on longer running tests?

[pnmcosta]

Hi,

In my github CI on one of my longer test I get the following error

To give you some context, the actual message being logged happens on a BeforeServe event, which I've tried to replicate as below:

package main

import (
    "log"
    "log/slog"
    "net/http"

    "github.com/labstack/echo/v5"
    "github.com/pocketbase/pocketbase"
    "github.com/pocketbase/pocketbase/core"
)

func Bind(app core.App) {
    app.OnBeforeServe().Add(func(e *core.ServeEvent) error {
        logger := app.Logger().With("test", true)
        // simulate data loading and emit logs on bootstrap
        for i := 0; i < 500; i++ {
            logger.Info("spam logs", slog.Int("index", i))
        }

        // only here to wire in tests
        e.Router.GET("/test", func(c echo.Context) error {
            return c.NoContent(http.StatusOK)
        })

        return nil
    })
}
func main() {
    app := pocketbase.New()

    Bind(app)
    if err := app.Start(); err != nil {
        log.Fatal(err)
    }
}

I've also induced a delay on the test to see if the batch handler would kick in.

package main

import (
    "net/http"
    "testing"
    "time"

    "github.com/pocketbase/pocketbase/tests"
)

func TestMain(t *testing.T) {
    scenarios := []tests.ApiScenario{
        {
            Name:            "should 200",
            Method:          http.MethodGet,
            Delay:           5 * time.Second,
            Url:             "/test",
            ExpectedStatus:  http.StatusOK,
            ExpectedContent: []string{""},
            TestAppFactory:  NewTestApp(),
        },
    }

    for _, scenario := range scenarios {
        scenario.Test(t)
    }
}

func NewTestApp() func(t *testing.T) *tests.TestApp {
    return func(t *testing.T) *tests.TestApp {
        app, err := tests.NewTestApp()
        if err != nil {
            t.Fatal(err)
        }

        Bind(app)
        return app
    }
}

Unfortunately I have not been able to replicate the error locally, my hypothesis is that perhaps it's because many more tests are running on CI and not just the one, and obviously resource wise my local machine is much beefier than the runners.

This is not a major issue, tests still pass fine and AFAIK there are not known artifacts, but I thought you may want to know about it.

If you need any more info, happy to troubleshoot some more.

P.s. I'm using the command go run gotest.tools/gotestsum@v1.11.0 --format-hide-empty-pkg -f testname -- ./... -race -short -failfast -count=1 both locally and on the CI.

[ganigeorgiev]

In your actual test environment do you specify a test pb_data when initializing NewTestApp?

[pnmcosta]

No, just the test_pb_data\data.db file that is in source control.

[pnmcosta]

Sorry I think I misunderstood you, there is also no pb_data on the local test, just:

[pnmcosta]

here's the go.mod of my local test:

module myapp

go 1.22.1

require (
    github.com/labstack/echo/v5 v5.0.0-20230722203903-ec5b858dab61
    github.com/pocketbase/pocketbase v0.22.4
)

require (
    github.com/AlecAivazis/survey/v2 v2.3.7 // indirect
    github.com/asaskevich/govalidator v0.0.0-20230301143203-a9d515a09cc2 // indirect
    github.com/aws/aws-sdk-go v1.51.3 // indirect
    github.com/aws/aws-sdk-go-v2 v1.26.0 // indirect
    github.com/aws/aws-sdk-go-v2/aws/protocol/eventstream v1.6.1 // indirect
    github.com/aws/aws-sdk-go-v2/config v1.27.8 // indirect
    github.com/aws/aws-sdk-go-v2/credentials v1.17.8 // indirect
    github.com/aws/aws-sdk-go-v2/feature/ec2/imds v1.15.4 // indirect
    github.com/aws/aws-sdk-go-v2/feature/s3/manager v1.16.12 // indirect
    github.com/aws/aws-sdk-go-v2/internal/configsources v1.3.4 // indirect
    github.com/aws/aws-sdk-go-v2/internal/endpoints/v2 v2.6.4 // indirect
    github.com/aws/aws-sdk-go-v2/internal/ini v1.8.0 // indirect
    github.com/aws/aws-sdk-go-v2/internal/v4a v1.3.4 // indirect
    github.com/aws/aws-sdk-go-v2/service/internal/accept-encoding v1.11.1 // indirect
    github.com/aws/aws-sdk-go-v2/service/internal/checksum v1.3.6 // indirect
    github.com/aws/aws-sdk-go-v2/service/internal/presigned-url v1.11.6 // indirect
    github.com/aws/aws-sdk-go-v2/service/internal/s3shared v1.17.4 // indirect
    github.com/aws/aws-sdk-go-v2/service/s3 v1.53.0 // indirect
    github.com/aws/aws-sdk-go-v2/service/sso v1.20.3 // indirect
    github.com/aws/aws-sdk-go-v2/service/ssooidc v1.23.3 // indirect
    github.com/aws/aws-sdk-go-v2/service/sts v1.28.5 // indirect
    github.com/aws/smithy-go v1.20.1 // indirect
    github.com/disintegration/imaging v1.6.2 // indirect
    github.com/domodwyer/mailyak/v3 v3.6.2 // indirect
    github.com/dustin/go-humanize v1.0.1 // indirect
    github.com/fatih/color v1.16.0 // indirect
    github.com/gabriel-vasile/mimetype v1.4.3 // indirect
    github.com/ganigeorgiev/fexpr v0.4.0 // indirect
    github.com/go-ozzo/ozzo-validation/v4 v4.3.0 // indirect
    github.com/goccy/go-json v0.10.2 // indirect
    github.com/golang-jwt/jwt/v4 v4.5.0 // indirect
    github.com/golang/groupcache v0.0.0-20210331224755-41bb18bfe9da // indirect
    github.com/golang/protobuf v1.5.4 // indirect
    github.com/google/uuid v1.6.0 // indirect
    github.com/google/wire v0.6.0 // indirect
    github.com/googleapis/gax-go/v2 v2.12.3 // indirect
    github.com/hashicorp/golang-lru/v2 v2.0.7 // indirect
    github.com/inconshreveable/mousetrap v1.1.0 // indirect
    github.com/jmespath/go-jmespath v0.4.0 // indirect
    github.com/kballard/go-shellquote v0.0.0-20180428030007-95032a82bc51 // indirect
    github.com/mattn/go-colorable v0.1.13 // indirect
    github.com/mattn/go-isatty v0.0.20 // indirect
    github.com/mattn/go-sqlite3 v1.14.22 // indirect
    github.com/mgutz/ansi v0.0.0-20200706080929-d51e80ef957d // indirect
    github.com/ncruces/go-strftime v0.1.9 // indirect
    github.com/pocketbase/dbx v1.10.1 // indirect
    github.com/remyoudompheng/bigfft v0.0.0-20230129092748-24d4a6f8daec // indirect
    github.com/spf13/cast v1.6.0 // indirect
    github.com/spf13/cobra v1.8.0 // indirect
    github.com/spf13/pflag v1.0.5 // indirect
    github.com/valyala/bytebufferpool v1.0.0 // indirect
    github.com/valyala/fasttemplate v1.2.2 // indirect
    go.opencensus.io v0.24.0 // indirect
    gocloud.dev v0.37.0 // indirect
    golang.org/x/crypto v0.21.0 // indirect
    golang.org/x/image v0.15.0 // indirect
    golang.org/x/net v0.22.0 // indirect
    golang.org/x/oauth2 v0.18.0 // indirect
    golang.org/x/sync v0.6.0 // indirect
    golang.org/x/sys v0.18.0 // indirect
    golang.org/x/term v0.18.0 // indirect
    golang.org/x/text v0.14.0 // indirect
    golang.org/x/time v0.5.0 // indirect
    golang.org/x/xerrors v0.0.0-20231012003039-104605ab7028 // indirect
    google.golang.org/api v0.170.0 // indirect
    google.golang.org/appengine v1.6.8 // indirect
    google.golang.org/genproto/googleapis/rpc v0.0.0-20240318140521-94a12d6c2237 // indirect
    google.golang.org/grpc v1.62.1 // indirect
    google.golang.org/protobuf v1.33.0 // indirect
    modernc.org/gc/v3 v3.0.0-20240304020402-f0dba7c97c2b // indirect
    modernc.org/libc v1.46.0 // indirect
    modernc.org/mathutil v1.6.0 // indirect
    modernc.org/memory v1.7.2 // indirect
    modernc.org/sqlite v1.29.5 // indirect
    modernc.org/strutil v1.2.0 // indirect
    modernc.org/token v1.1.0 // indirect
)

[ganigeorgiev]

I'm not sure how to replicate the "no such table: _logs" error.

It is possible that there is a race condition between the logger timer and when TestApp.Cleanup() is called because we currently don't manually trigger the OnTerminate hook on cleanup, which is responsible for stopping the timer. But in that case I expect the error to have been "no such file or directory" since the entire db test file is deleted.

I'll try to investigate it in more details tomorrow (at the minimum we can stop the logger timer on test cleanup).

[pnmcosta]

Yeah it bugs me I can't replicate it locally either!

It definitely happens on github runner, is there anything I could do to help troubleshoot there?

Thank you so much for you time on this.

[ganigeorgiev]

I was able to reproduce the "no such table: _logs" error.

It is happening because we don't run the migrations when creating the test app instance (I don't remember why exactly; it is possible that this was introduced during the restructuring of the serve command and the apis.InitApi).

You are not able to reproduce it locally because probably your test pb_data has logs.db file already initialized.

I'll submit a fix for this and the cleanup OnTerminate call tomorrow, but in both cases the regular app server shouldn't be affected by this.

[ganigeorgiev]

I've pushed a fix in the develop and it will be available with the next minor v0.22.5 release sometime tomorrow.

[pnmcosta]

Brilliant, thank you so much for looking into this.