Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

logadmin: Unable to paginate entries throught different processes/requests #8186

Closed
beni0888 opened this issue Jun 29, 2023 · 4 comments · Fixed by #8221
Closed

logadmin: Unable to paginate entries throught different processes/requests #8186

beni0888 opened this issue Jun 29, 2023 · 4 comments · Fixed by #8221
Assignees
Labels
api: logging Issues related to the Cloud Logging API. priority: p3 Desirable enhancement or fix. May not be included in next release. type: bug Error or flaw in code with unintended results or allowing sub-optimal usage patterns.

Comments

@beni0888
Copy link

Client

logadmin.Client

Environment

macOS Ventura 13.4 - Apple M1 Pro

Go Environment

$ go version
go version go1.20.3 darwin/arm64
$ go env
GOARCH="arm64"
GOCACHE="/Users/myuser/Library/Caches/go-build"
GOENV="/Users/myuser/Library/Application Support/go/env"
GOHOSTARCH="arm64"
GOHOSTOS="darwin"
GOMODCACHE="/Users/myuser/.asdf/installs/golang/1.20.3/packages/pkg/mod"
GOOS="darwin"
GOPATH="/Users/myuser/.asdf/installs/golang/1.20.3/packages"
GOROOT="/Users/myuser/.asdf/installs/golang/1.20.3/go"
GOTOOLDIR="/Users/myuser/.asdf/installs/golang/1.20.3/go/pkg/tool/darwin_arm64"
GOVERSION="go1.20.3"
GCCGO="gccgo"
AR="ar"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
CGO_CFLAGS="-O2 -g"
CGO_CXXFLAGS="-O2 -g"
CGO_FFLAGS="-O2 -g"
CGO_LDFLAGS="-O2 -g"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -arch arm64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/k2/c4by0t896cl33tv1bt6dty0r0000gq/T/go-build2139043596=/tmp/go-build -gno-record-gcc-switches -fno-common"

Code

The code can be found here.

package main

import (
        "bytes"
        "context"
        "flag"
        "fmt"
        "html/template"
        "log"
        "net/http"

        "cloud.google.com/go/logging"
        "cloud.google.com/go/logging/logadmin"
        "google.golang.org/api/iterator"
)

var (
        client    *logadmin.Client
        projectID = flag.String("project-id", "", "ID of the project to use")
)

func main() {
        // This example demonstrates how to iterate through items a page at a time
        // even if each successive page is fetched by a different process. It is a
        // complete web server that displays pages of log entries. To run it as a
        // standalone program, rename both the package and this function to "main".
        ctx := context.Background()
        flag.Parse()
        if *projectID == "" {
                log.Fatal("-project-id missing")
        }
        var err error
        client, err = logadmin.NewClient(ctx, *projectID)
        if err != nil {
                log.Fatalf("creating logging client: %v", err)
        }

        http.HandleFunc("/entries", handleEntries)
        log.Print("listening on 8080")
        log.Fatal(http.ListenAndServe(":8080", nil))
}

var pageTemplate = template.Must(template.New("").Parse(`
<table>
  {{range .Entries}}
    <tr><td>{{.}}</td></tr>
  {{end}}
</table>
{{if .Next}}
  <a href="/entries?pageToken={{.Next}}">Next Page</a>
{{end}}
`))

func handleEntries(w http.ResponseWriter, r *http.Request) {
        ctx := context.Background()
        filter := fmt.Sprintf(`logName = "projects/%s/logs/testlog"`, *projectID)
        it := client.Entries(ctx, logadmin.Filter(filter))
        var entries []*logging.Entry
        nextTok, err := iterator.NewPager(it, 5, r.URL.Query().Get("pageToken")).NextPage(&entries)
        if err != nil {
                http.Error(w, fmt.Sprintf("problem getting the next page: %v", err), http.StatusInternalServerError)
                return
        }
        data := struct {
                Entries []*logging.Entry
                Next    string
        }{
                entries,
                nextTok,
        }
        var buf bytes.Buffer
        if err := pageTemplate.Execute(&buf, data); err != nil {
                http.Error(w, fmt.Sprintf("problem executing page template: %v", err), http.StatusInternalServerError)
        }
        if _, err := buf.WriteTo(w); err != nil {
                log.Printf("writing response: %v", err)
        }
}

Expected behavior

When a request is made providing a valid pagination token in the pageToken query parameter (e.g. http://localhost:8080/entries?pageToken=EAA4n_GIvMjgk6THAUq0BSIe...) the corresponding page of the list of logs is returned.

Actual behavior

When you provide the pageToken query param with a valid pagination token, you get an error saying problem getting the next page: rpc error: code = InvalidArgument desc = page_token doesn't match arguments from the request

Additional context

go 1.20

require (
cloud.google.com/go/logging v1.7.0
google.golang.org/api v0.129.0
)

@beni0888 beni0888 added the triage me I really want to be triaged. label Jun 29, 2023
@quartzmo
Copy link
Member

@beni0888 Thank you for reporting this issue with the pagination sample for logadmin (*Client) Entries. I reproduced the error myself by downloading the sample from cloud.google.com and running it without modification apart from the log name:

problem getting the next page: rpc error: code = InvalidArgument desc = page_token doesn't match arguments from the request

@quartzmo quartzmo added the api: logging Issues related to the Cloud Logging API. label Jun 29, 2023
@quartzmo quartzmo assigned daniel-sanche and unassigned quartzmo Jun 29, 2023
@beni0888
Copy link
Author

@quartzmo Thank you for taking a look! Can we expect this issue to be fixed in the short term?

@noahdietz noahdietz added type: bug Error or flaw in code with unintended results or allowing sub-optimal usage patterns. priority: p2 Moderately-important priority. Fix may not be included in next release. and removed triage me I really want to be triaged. labels Jul 5, 2023
@noahdietz
Copy link
Contributor

After some debugging and trial & error I found that reusing the same *EntryIterator between requests made it work. To the sample, I added the following

// ...
var (
  // ...
  it *EntryIterator
)

// ...
func handleEntries(w http.ResponseWriter, r *http.Request) {
        // ...
	if it == nil {
		it = client.Entries(ctx, logadmin.Filter(filter))
	}
        // ...

The reason this worked is because of the following interesting default behavior:
A timestamp filter is added to the ListLogEntriesRequest.Filter when there isn't one present in the initial client.Entries call. This is documented as "last 24 hours" of logs. It is standard behavior that the Filter, OrderBy, and various other fields must not change between calls when using a NextPageToken. However, because this example was creating a new EntryIterator on each request, a new timestamp was added to the also new Filter field, thus invalidating the NextPageToken returned from the EntryIterator created on the previous call.

To test this hunch I added AND timestamp to the Filter being created for the logName in the example and removed the EntryIterator caching logic - this worked. Including timestamp in the filter (even without a value) is a documented workaround for disabling the automatic default timestamp filter injection.

So nothing is broken except for this sample. We should either add AND timestamp (or a legit timestamp filter, not this workaround) to the Filter or do the aforementioned EntryIterator caching (I don't think this is a good practice to share though).

@noahdietz noahdietz added priority: p3 Desirable enhancement or fix. May not be included in next release. and removed priority: p2 Moderately-important priority. Fix may not be included in next release. labels Jul 6, 2023
@noahdietz noahdietz assigned noahdietz and unassigned daniel-sanche Jul 6, 2023
@noahdietz
Copy link
Contributor

I decided to just add a timestamp and create the filter once, on server start up.

gcf-merge-on-green bot pushed a commit that referenced this issue Jul 6, 2023
Without supplying a `timestamp` in the `ListLogEntries.Filter`, the client by default sets one for the last twenty-four hours when the `EntryIterator` is created. Since this example creates a new `EntryIterator` on each request, a new `timestamp` of a slightly different twenty-four hour window is added. When the `Next Page` button is pressed, it reuses the `NextPageToken` from the previous call, but that was created for a different twenty-four hour window `Filter`. This creates a mismatch between the requested `Filter` and the `Filter` used to create the `NextPageToken`, resulting in an error.

To address this, we create the filter in the main function before server start up. In this filter, we set a timestamp **explicitly**. 

Note: I made this a `fix` commit because this is part of the GoDoc examples and we need this to appear as the latest release, otherwise no one will see it until another release comes along.

Fixes #8186.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
api: logging Issues related to the Cloud Logging API. priority: p3 Desirable enhancement or fix. May not be included in next release. type: bug Error or flaw in code with unintended results or allowing sub-optimal usage patterns.
Projects
None yet
Development

Successfully merging a pull request may close this issue.

4 participants