With redis and cloud.google.com/go/datastore in v1.4.0 or later, put fail.

[ktis]

When using redis and cloud.google.com/go/datastore which is after V1.4.0, if the time.Time type member of the struct is uninitialized, the struct cannot be put to datastore. Without redis, put work well. Using cloud.google.com/go/datastore V1.3.0, put work well. (Few days ago I updated go.mod, then my unittest failed. datastrore V1.3.0 is OK, V1.4.0 or later is fail.)

Below is my Test code.

package main

import (
        orgdatastore "cloud.google.com/go/datastore"
        "context"
        "fmt"
        "github.com/gomodule/redigo/redis"
        "go.mercari.io/datastore"
        "go.mercari.io/datastore/clouddatastore"
        "go.mercari.io/datastore/dsmiddleware/rediscache"
        "log"
        "net"
        "time"
)
type Entity struct {
        Tp time.Time //About cloud.google.com/go/datastore, in v1.4.0 or later, redis will result in an error unless it is explicitly initialized. No error occurs to v1.3.0
        P  int
}

var ename string
var pname string
var eid string

func main() {
        loc, err := time.LoadLocation("Asia/Tokyo")
        if err != nil {
                loc = time.FixedZone("Asia/Tokyo", 9*60*60)
        }
        time.Local = loc
        ename = "Entity"
        pname = "my-project"
        eid = "eid"
        //pattern_originalDatastore()
        pattern_mercariDatastore(true, false)
        pattern_mercariDatastore(true, true)
}

func pattern_mercariDatastore(withRedis, doInitTimeMember bool) {
        dbkind := fmt.Sprintf("mercari_redis_%v_timeInit_%v", withRedis, doInitTimeMember)
        fail := false
        c := context.Background()
        client := getMercariClient(c, withRedis)
        defer client.Close()

        k := client.NameKey(ename, eid, nil)
        e := new(Entity)
        if err := client.Get(c, k, e); err != nil {
                //This is first get, then err shold not be nil.
                //log.Printf("%s Get Error %v\n", dbkind, err)
        } else {
                log.Printf("%s initialize miss\n", dbkind)
                fail = true
        }

        e.P = 50
        if doInitTimeMember { //cloud.google.com/go/datastore in v1.4.0 or later, this is necessary.
                e.Tp = time.Now()
        }
        if _, err := client.Put(c, k, e); err != nil {
                log.Printf("%s Put Error %v\n", dbkind, err)
                fail = true
        }
        e2 := new(Entity)
        if err := client.Get(c, k, e2); err != nil {
                log.Printf("%s Put Fail %v\n", dbkind, err)
                fail = true
        }
        if e2.P != 50 {
                log.Printf("%s Put Fail 50, now %d\n", dbkind, e2.P)
                fail = true
        }
        e2.P = 100
        client.Put(c, k, e2)

        e3 := new(Entity)
        if err := client.Get(c, k, e3); err != nil {
                log.Printf("%s Put Fail %v\n", dbkind, err)
                fail = true
        }
        if e3.P != 100 {
                log.Printf("%s Put100 Fail \n", dbkind)
                fail = true
        }
        client.Delete(c, k)
        if fail {
                log.Printf("----- %s Fail -----", dbkind)
        } else {
                log.Printf("----- %s OK -----", dbkind)
        }
}

func pattern_originalDatastore() {
        dbkind := "original"
        fail := false
        c := context.Background()
        client, _ := orgdatastore.NewClient(c, pname)
        defer client.Close()

        k := orgdatastore.NameKey(ename, eid, nil)
        e := new(Entity)
        if err := client.Get(c, k, e); err != nil {
                //This is first get, then err shold not be nil.
                //log.Printf("%s Get Error %v\n", dbkind, err)
        } else {
                log.Printf("%s initialize miss\n", dbkind)
                fail = true
        }

        e.P = 50
        if _, err := client.Put(c, k, e); err != nil {
                log.Printf("%s Put Error %v\n", dbkind, err)
                fail = true
        }
        e2 := new(Entity)
        if err := client.Get(c, k, e2); err != nil {
                log.Printf("%s Put Fail %v\n", dbkind, err)
                fail = true
        }
        if e2.P != 50 {
                log.Printf("%s Put Fail 50, now %d\n", dbkind, e2.P)
                fail = true
        }
        e2.P = 100
        client.Put(c, k, e2)

        e3 := new(Entity)
        if err := client.Get(c, k, e3); err != nil {
                log.Printf("%s Put Fail %v\n", dbkind, err)
                fail = true
        }
        if e3.P != 100 {
                log.Printf("%s Put100 Fail \n", dbkind)
                fail = true
        }
        client.Delete(c, k)

        if fail {
                log.Printf("----- %s Fail -----", dbkind)
        } else {
                log.Printf("----- %s OK -----", dbkind)
        }
}

func getMercariClient(c context.Context, withredis bool) datastore.Client {
        orgClient, _ := orgdatastore.NewClient(c, "my-project")
        client, _ := clouddatastore.FromClient(c, orgClient)
        dial, err := net.Dial("tcp", "localhost:6379")
        if err != nil {
                log.Printf("getMercariClient %v", err)
        }
        if withredis {
                conn := redis.NewConn(dial, 100*time.Millisecond, 100*time.Millisecond)
                //defer conn.Close()
                mw := rediscache.New(conn,
                        rediscache.WithLogger(func(ctx context.Context, format string, args ...interface{}) {
                                log.Printf(format, args...)
                        }))
                rediscachemw := mw
                client.AppendMiddleware(rediscachemw)
        }
        return client
}

[ktis]

Log with datastore V1.4.0　(Put100 Fail)

main.go
2021/10/15 14:11:53 dsmiddleware/rediscache.GetMulti: incoming len=1
2021/10/15 14:11:53 dsmiddleware/rediscache.GetMulti: hit=0 miss=1
[datastore] The health check endpoint for this emulator instance is http://localhost:8081/Oct 15, 2021 2:11:53 PM io.gapi.emulators.grpc.GrpcServer$3 operationComplete
[datastore] INFO: Adding handler(s) to newly registered Channel.
[datastore] Oct 15, 2021 2:11:53 PM io.gapi.emulators.netty.HttpVersionRoutingHandler channelRead
[datastore] INFO: Detected HTTP/2 connection.
2021/10/15 14:11:53 dsmiddleware/rediscache.SetMulti: incoming len=1
2021/10/15 14:11:53 dsmiddleware/rediscache.SetMulti: gob.Encode error key=/Entity,eid err=Time.MarshalBinary: zone offset has fractional minute
2021/10/15 14:11:53 dsmiddleware/rediscache.SetMulti: len=0
2021/10/15 14:11:53 dsmiddleware/rediscache.GetMulti: incoming len=1
2021/10/15 14:11:53 dsmiddleware/rediscache.GetMulti: hit=0 miss=1
2021/10/15 14:11:53 dsmiddleware/rediscache.SetMulti: incoming len=1
2021/10/15 14:11:53 dsmiddleware/rediscache.SetMulti: len=1
2021/10/15 14:11:53 dsmiddleware/rediscache.SetMulti: incoming len=1
2021/10/15 14:11:53 dsmiddleware/rediscache.SetMulti: gob.Encode error key=/Entity,eid err=Time.MarshalBinary: zone offset has fractional minute
2021/10/15 14:11:53 dsmiddleware/rediscache.SetMulti: len=0
2021/10/15 14:11:53 dsmiddleware/rediscache.GetMulti: incoming len=1
2021/10/15 14:11:53 dsmiddleware/rediscache.GetMulti: hit=1 miss=0
2021/10/15 14:11:53 mercari_redis_true_timeInit_false Put100 Fail
2021/10/15 14:11:53 dsmiddleware/rediscache.DeleteMulti: incoming len=1
2021/10/15 14:11:53 ----- mercari_redis_true_timeInit_false Fail -----
2021/10/15 14:11:53 dsmiddleware/rediscache.GetMulti: incoming len=1
2021/10/15 14:11:53 dsmiddleware/rediscache.GetMulti: hit=0 miss=1
[datastore] Oct 15, 2021 2:11:53 PM io.gapi.emulators.grpc.GrpcServer$3 operationComplete
[datastore] INFO: Adding handler(s) to newly registered Channel.
[datastore] Oct 15, 2021 2:11:53 PM io.gapi.emulators.netty.HttpVersionRoutingHandler channelRead
[datastore] INFO: Detected HTTP/2 connection.
2021/10/15 14:11:53 dsmiddleware/rediscache.SetMulti: incoming len=1
2021/10/15 14:11:53 dsmiddleware/rediscache.SetMulti: len=1
2021/10/15 14:11:53 dsmiddleware/rediscache.GetMulti: incoming len=1
2021/10/15 14:11:53 dsmiddleware/rediscache.GetMulti: hit=1 miss=0
2021/10/15 14:11:53 dsmiddleware/rediscache.SetMulti: incoming len=1
2021/10/15 14:11:53 dsmiddleware/rediscache.SetMulti: len=1
2021/10/15 14:11:53 dsmiddleware/rediscache.GetMulti: incoming len=1
2021/10/15 14:11:53 dsmiddleware/rediscache.GetMulti: hit=1 miss=0
2021/10/15 14:11:53 dsmiddleware/rediscache.DeleteMulti: incoming len=1
2021/10/15 14:11:53 ----- mercari_redis_true_timeInit_true OK -----

Log with datastore V1.3.0　(Put100 OK)

main.go
command-line-arguments
2021/10/15 14:13:38 dsmiddleware/rediscache.GetMulti: incoming len=1
2021/10/15 14:13:38 dsmiddleware/rediscache.GetMulti: hit=0 miss=1
[datastore] The health check endpoint for this emulator instance is http://localhost:8081/Oct 15, 2021 2:13:38 PM io.gapi.emulators.grpc.GrpcServer$3 operationComplete
[datastore] INFO: Adding handler(s) to newly registered Channel.
[datastore] Oct 15, 2021 2:13:38 PM io.gapi.emulators.netty.HttpVersionRoutingHandler channelRead
[datastore] INFO: Detected HTTP/2 connection.
2021/10/15 14:13:38 dsmiddleware/rediscache.SetMulti: incoming len=1
2021/10/15 14:13:38 dsmiddleware/rediscache.SetMulti: gob.Encode error key=/Entity,eid err=Time.MarshalBinary: zone offset has fractional minute
2021/10/15 14:13:38 dsmiddleware/rediscache.SetMulti: len=0
2021/10/15 14:13:38 dsmiddleware/rediscache.GetMulti: incoming len=1
2021/10/15 14:13:38 dsmiddleware/rediscache.GetMulti: hit=0 miss=1
2021/10/15 14:13:38 dsmiddleware/rediscache.SetMulti: incoming len=1
2021/10/15 14:13:38 dsmiddleware/rediscache.SetMulti: gob.Encode error key=/Entity,eid err=Time.MarshalBinary: zone offset has fractional minute
2021/10/15 14:13:38 dsmiddleware/rediscache.SetMulti: len=0
2021/10/15 14:13:38 dsmiddleware/rediscache.SetMulti: incoming len=1
2021/10/15 14:13:38 dsmiddleware/rediscache.SetMulti: gob.Encode error key=/Entity,eid err=Time.MarshalBinary: zone offset has fractional minute
2021/10/15 14:13:38 dsmiddleware/rediscache.SetMulti: len=0
2021/10/15 14:13:38 dsmiddleware/rediscache.GetMulti: incoming len=1
2021/10/15 14:13:38 dsmiddleware/rediscache.GetMulti: hit=0 miss=1
2021/10/15 14:13:38 dsmiddleware/rediscache.SetMulti: incoming len=1
2021/10/15 14:13:38 dsmiddleware/rediscache.SetMulti: gob.Encode error key=/Entity,eid err=Time.MarshalBinary: zone offset has fractional minute
2021/10/15 14:13:38 dsmiddleware/rediscache.SetMulti: len=0
2021/10/15 14:13:38 dsmiddleware/rediscache.DeleteMulti: incoming len=1
2021/10/15 14:13:38 ----- mercari_redis_true_timeInit_false OK -----
2021/10/15 14:13:38 dsmiddleware/rediscache.GetMulti: incoming len=1
2021/10/15 14:13:38 dsmiddleware/rediscache.GetMulti: hit=0 miss=1
[datastore] Oct 15, 2021 2:13:38 PM io.gapi.emulators.grpc.GrpcServer$3 operationComplete
[datastore] INFO: Adding handler(s) to newly registered Channel.
[datastore] Oct 15, 2021 2:13:38 PM io.gapi.emulators.netty.HttpVersionRoutingHandler channelRead
[datastore] INFO: Detected HTTP/2 connection.
2021/10/15 14:13:38 dsmiddleware/rediscache.SetMulti: incoming len=1
2021/10/15 14:13:38 dsmiddleware/rediscache.SetMulti: len=1
2021/10/15 14:13:38 dsmiddleware/rediscache.GetMulti: incoming len=1
2021/10/15 14:13:38 dsmiddleware/rediscache.GetMulti: hit=1 miss=0
2021/10/15 14:13:39 dsmiddleware/rediscache.SetMulti: incoming len=1
2021/10/15 14:13:39 dsmiddleware/rediscache.SetMulti: len=1
2021/10/15 14:13:39 dsmiddleware/rediscache.GetMulti: incoming len=1
2021/10/15 14:13:39 dsmiddleware/rediscache.GetMulti: hit=1 miss=0
2021/10/15 14:13:39 dsmiddleware/rediscache.DeleteMulti: incoming len=1
2021/10/15 14:13:39 ----- mercari_redis_true_timeInit_true OK -----

[ktis]

The trouble is that even if the data put fails, there is no programmatic error. Using rediscache.WithLogger, I found that datastore V1.4.0 had a gob error in the uninitialized time.Time member.

[vvakame]

@ktis sorry for late response.

I checked v1.4.0 release note. https://github.com/googleapis/google-cloud-go/releases/tag/datastore%2Fv1.4.0

minimal reproduction code

func TestIssue88_mini(t *testing.T) {
	loc, err := time.LoadLocation("Asia/Tokyo")
	if err != nil {
		t.Fatal(err)
	}

	zeroT := time.Time{}.In(loc)
	name, offset := zeroT.Zone()
        // name: LMT, offset: 33539
	t.Logf("name: %s, offset: %d", name, offset)

	var buf bytes.Buffer
	err = gob.NewEncoder(&buf).Encode(zeroT)
	if err != nil {
		t.Fatal(err)
	}
}

I found interesting article. https://www.m3tech.blog/entry/timezone-091859

I recommend you to use below code on start-up.

loc := time.FixedZone("Asia/Tokyo", 9*60*60)
time.Local = loc

[ktis]

Thank you for answering the cause and how to fix it. Fix my code that way.