go.mercari.io/datastore@v1.8.2/dsmiddleware/aememcache/aememcache_test.go (about)

     1  package aememcache
     2  
     3  import (
     4  	"bytes"
     5  	"context"
     6  	"fmt"
     7  	"os"
     8  	"regexp"
     9  	"strings"
    10  	"testing"
    11  
    12  	"github.com/favclip/testerator/v2"
    13  	_ "github.com/favclip/testerator/v2/datastore"
    14  	_ "github.com/favclip/testerator/v2/memcache"
    15  
    16  	"github.com/MakeNowJust/heredoc/v2"
    17  	"go.mercari.io/datastore"
    18  	"go.mercari.io/datastore/dsmiddleware/dslog"
    19  	"go.mercari.io/datastore/dsmiddleware/storagecache"
    20  	"go.mercari.io/datastore/internal/testutils"
    21  	"google.golang.org/api/iterator"
    22  	"google.golang.org/appengine/memcache"
    23  )
    24  
    25  func TestMain(m *testing.M) {
    26  	_, _, err := testerator.SpinUp()
    27  	if err != nil {
    28  		fmt.Fprint(os.Stderr, err.Error())
    29  		os.Exit(1)
    30  	}
    31  
    32  	status := m.Run()
    33  
    34  	err = testerator.SpinDown()
    35  	if err != nil {
    36  		fmt.Fprint(os.Stderr, err.Error())
    37  		os.Exit(1)
    38  	}
    39  
    40  	os.Exit(status)
    41  }
    42  
    43  func inCache(ctx context.Context, ch storagecache.Storage, key datastore.Key) (bool, error) {
    44  	resp, err := ch.GetMulti(ctx, []datastore.Key{key})
    45  	if err != nil {
    46  		return false, err
    47  	} else if v := len(resp); v != 1 {
    48  		return false, nil
    49  	} else if v := resp[0]; v == nil {
    50  		return false, nil
    51  	}
    52  
    53  	return true, nil
    54  }
    55  
    56  func TestAEMemcacheCache_Basic(t *testing.T) {
    57  	ctx, client, cleanUp := testutils.SetupAEDatastore(t)
    58  	defer cleanUp()
    59  
    60  	var logs []string
    61  	logf := func(ctx context.Context, format string, args ...interface{}) {
    62  		t.Logf(format, args...)
    63  		logs = append(logs, fmt.Sprintf(format, args...))
    64  	}
    65  
    66  	// setup. strategies are first in - first apply.
    67  
    68  	bLog := dslog.NewLogger("before: ", logf)
    69  	client.AppendMiddleware(bLog)
    70  	defer func() {
    71  		// stop logging before cleanUp func called.
    72  		client.RemoveMiddleware(bLog)
    73  	}()
    74  
    75  	ch := New(
    76  		WithLogger(logf),
    77  	)
    78  	client.AppendMiddleware(ch)
    79  	defer func() {
    80  		// stop logging before cleanUp func called.
    81  		client.RemoveMiddleware(ch)
    82  	}()
    83  
    84  	aLog := dslog.NewLogger("after: ", logf)
    85  	client.AppendMiddleware(aLog)
    86  	defer func() {
    87  		// stop logging before cleanUp func called.
    88  		client.RemoveMiddleware(aLog)
    89  	}()
    90  
    91  	// exec.
    92  
    93  	type Data struct {
    94  		Name string
    95  	}
    96  
    97  	// Put. add to cache.
    98  	key := client.IDKey("Data", 111, nil)
    99  	objBefore := &Data{Name: "Data"}
   100  	_, err := client.Put(ctx, key, objBefore)
   101  	if err != nil {
   102  		t.Fatal(err)
   103  	}
   104  
   105  	hit, err := inCache(ctx, ch, key)
   106  	if err != nil {
   107  		t.Fatal(err)
   108  	} else if v := hit; !v {
   109  		t.Fatalf("unexpected: %v", v)
   110  	}
   111  
   112  	// Get. from cache.
   113  	objAfter := &Data{}
   114  	err = client.Get(ctx, key, objAfter)
   115  	if err != nil {
   116  		t.Fatal(err)
   117  	}
   118  
   119  	// Delete.
   120  	err = client.Delete(ctx, key)
   121  	if err != nil {
   122  		t.Fatal(err)
   123  	}
   124  
   125  	hit, err = inCache(ctx, ch, key)
   126  	if err != nil {
   127  		t.Fatal(err)
   128  	} else if v := hit; v {
   129  		t.Fatalf("unexpected: %v", v)
   130  	}
   131  
   132  	expected := heredoc.Doc(`
   133  		before: PutMultiWithoutTx #1, len(keys)=1, keys=[/Data,111]
   134  		after: PutMultiWithoutTx #1, len(keys)=1, keys=[/Data,111]
   135  		after: PutMultiWithoutTx #1, keys=[/Data,111]
   136  		dsmiddleware/aememcache.SetMulti: incoming len=1
   137  		dsmiddleware/aememcache.SetMulti: len=1
   138  		before: PutMultiWithoutTx #1, keys=[/Data,111]
   139  		dsmiddleware/aememcache.GetMulti: incoming len=1
   140  		dsmiddleware/aememcache.GetMulti: hit=1 miss=0
   141  		before: GetMultiWithoutTx #2, len(keys)=1, keys=[/Data,111]
   142  		dsmiddleware/aememcache.GetMulti: incoming len=1
   143  		dsmiddleware/aememcache.GetMulti: hit=1 miss=0
   144  		before: DeleteMultiWithoutTx #3, len(keys)=1, keys=[/Data,111]
   145  		after: DeleteMultiWithoutTx #2, len(keys)=1, keys=[/Data,111]
   146  		dsmiddleware/aememcache.DeleteMulti: incoming len=1
   147  		dsmiddleware/aememcache.GetMulti: incoming len=1
   148  		dsmiddleware/aememcache.GetMulti: hit=0 miss=1
   149  	`)
   150  
   151  	if v := strings.Join(logs, "\n") + "\n"; v != expected {
   152  		t.Errorf("unexpected: %v", v)
   153  	}
   154  }
   155  
   156  func TestAEMemcacheCache_Query(t *testing.T) {
   157  	ctx, client, cleanUp := testutils.SetupAEDatastore(t)
   158  	defer cleanUp()
   159  
   160  	var logs []string
   161  	logf := func(ctx context.Context, format string, args ...interface{}) {
   162  		t.Logf(format, args...)
   163  		logs = append(logs, fmt.Sprintf(format, args...))
   164  	}
   165  
   166  	// setup. strategies are first in - first apply.
   167  
   168  	bLog := dslog.NewLogger("before: ", logf)
   169  	client.AppendMiddleware(bLog)
   170  	defer func() {
   171  		// stop logging before cleanUp func called.
   172  		client.RemoveMiddleware(bLog)
   173  	}()
   174  
   175  	ch := New(
   176  		WithLogger(logf),
   177  	)
   178  	client.AppendMiddleware(ch)
   179  	defer func() {
   180  		// stop logging before cleanUp func called.
   181  		client.RemoveMiddleware(ch)
   182  	}()
   183  
   184  	aLog := dslog.NewLogger("after: ", logf)
   185  	client.AppendMiddleware(aLog)
   186  	defer func() {
   187  		// stop logging before cleanUp func called.
   188  		client.RemoveMiddleware(aLog)
   189  	}()
   190  
   191  	// exec.
   192  
   193  	type Data struct {
   194  		Name string
   195  	}
   196  
   197  	const size = 3
   198  
   199  	keys := make([]datastore.Key, size)
   200  	list := make([]*Data, size)
   201  	for i := 0; i < size; i++ {
   202  		keys[i] = client.NameKey("Data", fmt.Sprintf("#%d", i+1), nil)
   203  		list[i] = &Data{
   204  			Name: fmt.Sprintf("#%d", i+1),
   205  		}
   206  	}
   207  	_, err := client.PutMulti(ctx, keys, list)
   208  	if err != nil {
   209  		t.Fatal(err)
   210  	}
   211  
   212  	q := client.NewQuery("Data").Order("-Name")
   213  
   214  	// Run
   215  	iter := client.Run(ctx, q)
   216  
   217  	// Next
   218  	cnt := 0
   219  	for {
   220  		obj := &Data{}
   221  		key, err := iter.Next(obj)
   222  		if err == iterator.Done {
   223  			break
   224  		} else if err != nil {
   225  			t.Fatal(err)
   226  		}
   227  		if v := obj.Name; v == "" || v != key.Name() {
   228  			t.Errorf("unexpected: %v", cnt)
   229  		}
   230  		cnt++
   231  	}
   232  	if cnt != size {
   233  		t.Errorf("unexpected: %v", cnt)
   234  	}
   235  
   236  	// GetAll
   237  	list = nil
   238  	_, err = client.GetAll(ctx, q, &list)
   239  	if err != nil {
   240  		t.Fatal(err)
   241  	}
   242  
   243  	expected := heredoc.Doc(`
   244  		before: PutMultiWithoutTx #1, len(keys)=3, keys=[/Data,#1, /Data,#2, /Data,#3]
   245  		after: PutMultiWithoutTx #1, len(keys)=3, keys=[/Data,#1, /Data,#2, /Data,#3]
   246  		after: PutMultiWithoutTx #1, keys=[/Data,#1, /Data,#2, /Data,#3]
   247  		dsmiddleware/aememcache.SetMulti: incoming len=3
   248  		dsmiddleware/aememcache.SetMulti: len=3
   249  		before: PutMultiWithoutTx #1, keys=[/Data,#1, /Data,#2, /Data,#3]
   250  		before: Run #2, q=v1:Data&or=-Name
   251  		after: Run #2, q=v1:Data&or=-Name
   252  		before: Next #3, q=v1:Data&or=-Name
   253  		after: Next #3, q=v1:Data&or=-Name
   254  		after: Next #3, key=/Data,#3
   255  		before: Next #3, key=/Data,#3
   256  		before: Next #4, q=v1:Data&or=-Name
   257  		after: Next #4, q=v1:Data&or=-Name
   258  		after: Next #4, key=/Data,#2
   259  		before: Next #4, key=/Data,#2
   260  		before: Next #5, q=v1:Data&or=-Name
   261  		after: Next #5, q=v1:Data&or=-Name
   262  		after: Next #5, key=/Data,#1
   263  		before: Next #5, key=/Data,#1
   264  		before: Next #6, q=v1:Data&or=-Name
   265  		after: Next #6, q=v1:Data&or=-Name
   266  		after: Next #6, err=no more items in iterator
   267  		before: Next #6, err=no more items in iterator
   268  		before: GetAll #7, q=v1:Data&or=-Name
   269  		after: GetAll #7, q=v1:Data&or=-Name
   270  		after: GetAll #7, len(keys)=3, keys=[/Data,#3, /Data,#2, /Data,#1]
   271  		before: GetAll #7, len(keys)=3, keys=[/Data,#3, /Data,#2, /Data,#1]
   272  	`)
   273  
   274  	if v := strings.Join(logs, "\n") + "\n"; v != expected {
   275  		t.Errorf("unexpected: %v", v)
   276  	}
   277  }
   278  
   279  func TestAEMemcacheCache_Transaction(t *testing.T) {
   280  	ctx, client, cleanUp := testutils.SetupAEDatastore(t)
   281  	defer cleanUp()
   282  
   283  	var logs []string
   284  	logf := func(ctx context.Context, format string, args ...interface{}) {
   285  		t.Logf(format, args...)
   286  		logs = append(logs, fmt.Sprintf(format, args...))
   287  	}
   288  
   289  	// setup. strategies are first in - first apply.
   290  	bLog := dslog.NewLogger("before: ", logf)
   291  	client.AppendMiddleware(bLog)
   292  	defer func() {
   293  		// stop logging before cleanUp func called.
   294  		client.RemoveMiddleware(bLog)
   295  	}()
   296  
   297  	ch := New(
   298  		WithLogger(logf),
   299  	)
   300  	ch.(*cacheHandler).raiseMemcacheError = true
   301  	client.AppendMiddleware(ch)
   302  	defer func() {
   303  		// stop logging before cleanUp func called.
   304  		client.RemoveMiddleware(ch)
   305  	}()
   306  
   307  	aLog := dslog.NewLogger("after: ", logf)
   308  	client.AppendMiddleware(aLog)
   309  	defer func() {
   310  		// stop logging before cleanUp func called.
   311  		client.RemoveMiddleware(aLog)
   312  	}()
   313  
   314  	// exec.
   315  
   316  	stats, err := memcache.Stats(ctx)
   317  	if err != nil {
   318  		t.Fatal(err)
   319  	}
   320  	if v := stats.Items; v != 0 {
   321  		t.Fatalf("unexpected: %v", v)
   322  	}
   323  
   324  	type Data struct {
   325  		Name string
   326  	}
   327  
   328  	key := client.NameKey("Data", "a", nil)
   329  
   330  	// put to cache
   331  	_, err = client.Put(ctx, key, &Data{Name: "Before"})
   332  	if err != nil {
   333  		t.Fatal(err)
   334  	}
   335  	hit, err := inCache(ctx, ch, key)
   336  	if err != nil {
   337  		t.Fatal(err)
   338  	} else if v := hit; !v {
   339  		t.Fatalf("unexpected: %v", v)
   340  	}
   341  
   342  	{ // Rollback
   343  		tx, err := client.NewTransaction(ctx)
   344  		if err != nil {
   345  			t.Fatal(err)
   346  		}
   347  
   348  		// don't put to cache before commit
   349  		key2 := client.NameKey("Data", "b", nil)
   350  		_, err = tx.Put(key2, &Data{Name: "After"})
   351  		if err != nil {
   352  			t.Fatal(err)
   353  		}
   354  		hit, err = inCache(ctx, ch, key2)
   355  		if err != nil {
   356  			t.Fatal(err)
   357  		} else if v := hit; v {
   358  			t.Fatalf("unexpected: %v", v)
   359  		}
   360  
   361  		obj := &Data{}
   362  		err = tx.Get(key, obj)
   363  		if err != nil {
   364  			t.Fatal(err)
   365  		}
   366  
   367  		// don't delete from cache before commit
   368  		err = tx.Delete(key)
   369  		if err != nil {
   370  			t.Fatal(err)
   371  		}
   372  		hit, err = inCache(ctx, ch, key)
   373  		if err != nil {
   374  			t.Fatal(err)
   375  		} else if v := hit; !v {
   376  			t.Fatalf("unexpected: %v", v)
   377  		}
   378  
   379  		// rollback.
   380  		err = tx.Rollback()
   381  		if err != nil {
   382  			t.Fatal(err)
   383  		}
   384  		stats, err := memcache.Stats(ctx)
   385  		if err != nil {
   386  			t.Fatal(err)
   387  		}
   388  		if v := stats.Items; v != 1 {
   389  			t.Fatalf("unexpected: %v", v)
   390  		}
   391  	}
   392  
   393  	{ // Commit
   394  		tx, err := client.NewTransaction(ctx)
   395  		if err != nil {
   396  			t.Fatal(err)
   397  		}
   398  
   399  		// don't put to cache before commit
   400  		key2 := client.IncompleteKey("Data", nil)
   401  		pKey, err := tx.Put(key2, &Data{Name: "After"})
   402  		if err != nil {
   403  			t.Fatal(err)
   404  		}
   405  		stats, err := memcache.Stats(ctx)
   406  		if err != nil {
   407  			t.Fatal(err)
   408  		}
   409  		if v := stats.Items; v != 1 {
   410  			t.Fatalf("unexpected: %v", v)
   411  		}
   412  
   413  		obj := &Data{}
   414  		err = tx.Get(key, obj)
   415  		if err != nil {
   416  			t.Fatal(err)
   417  		}
   418  
   419  		// don't delete from cache before commit
   420  		err = tx.Delete(key)
   421  		if err != nil {
   422  			t.Fatal(err)
   423  		}
   424  		hit, err = inCache(ctx, ch, key)
   425  		if err != nil {
   426  			t.Fatal(err)
   427  		} else if v := hit; !v {
   428  			t.Fatalf("unexpected: %v", v)
   429  		}
   430  
   431  		// commit.
   432  		commit, err := tx.Commit()
   433  		if err != nil {
   434  			t.Fatal(err)
   435  		}
   436  
   437  		key3 := commit.Key(pKey)
   438  		if v := key3.Name(); v != key2.Name() {
   439  			t.Errorf("unexpected: %v", v)
   440  		}
   441  		// committed, but don't put to cache in tx.
   442  		hit, err = inCache(ctx, ch, key3)
   443  		if err != nil {
   444  			t.Fatal(err)
   445  		} else if v := hit; v {
   446  			t.Fatalf("unexpected: %v", v)
   447  		}
   448  
   449  		stats, err = memcache.Stats(ctx)
   450  		if err != nil {
   451  			t.Fatal(err)
   452  		}
   453  		if v := stats.Items; v != 0 {
   454  			t.Fatalf("unexpected: %v", v)
   455  		}
   456  	}
   457  
   458  	expectedPattern := heredoc.Doc(`
   459  		before: PutMultiWithoutTx #1, len(keys)=1, keys=[/Data,a]
   460  		after: PutMultiWithoutTx #1, len(keys)=1, keys=[/Data,a]
   461  		after: PutMultiWithoutTx #1, keys=[/Data,a]
   462  		dsmiddleware/aememcache.SetMulti: incoming len=1
   463  		dsmiddleware/aememcache.SetMulti: len=1
   464  		before: PutMultiWithoutTx #1, keys=[/Data,a]
   465  		dsmiddleware/aememcache.GetMulti: incoming len=1
   466  		dsmiddleware/aememcache.GetMulti: hit=1 miss=0
   467  		before: PutMultiWithTx #2, len(keys)=1, keys=[/Data,b]
   468  		after: PutMultiWithTx #2, len(keys)=1, keys=[/Data,b]
   469  		dsmiddleware/aememcache.GetMulti: incoming len=1
   470  		dsmiddleware/aememcache.GetMulti: hit=0 miss=1
   471  		before: GetMultiWithTx #3, len(keys)=1, keys=[/Data,a]
   472  		after: GetMultiWithTx #3, len(keys)=1, keys=[/Data,a]
   473  		before: DeleteMultiWithTx #4, len(keys)=1, keys=[/Data,a]
   474  		after: DeleteMultiWithTx #4, len(keys)=1, keys=[/Data,a]
   475  		dsmiddleware/aememcache.GetMulti: incoming len=1
   476  		dsmiddleware/aememcache.GetMulti: hit=1 miss=0
   477  		before: PostRollback #5
   478  		after: PostRollback #5
   479  		before: PutMultiWithTx #6, len(keys)=1, keys=[/Data,0]
   480  		after: PutMultiWithTx #6, len(keys)=1, keys=[/Data,0]
   481  		before: GetMultiWithTx #7, len(keys)=1, keys=[/Data,a]
   482  		after: GetMultiWithTx #7, len(keys)=1, keys=[/Data,a]
   483  		before: DeleteMultiWithTx #8, len(keys)=1, keys=[/Data,a]
   484  		after: DeleteMultiWithTx #8, len(keys)=1, keys=[/Data,a]
   485  		dsmiddleware/aememcache.GetMulti: incoming len=1
   486  		dsmiddleware/aememcache.GetMulti: hit=1 miss=0
   487  		before: PostCommit #9 Put keys=[/Data,@####@]
   488  		dsmiddleware/aememcache.DeleteMulti: incoming len=3
   489  		dsmiddleware/aememcache: error on memcache.DeleteMulti memcache: cache miss (and 1 other error)
   490  		after: PostCommit #9 Put keys=[/Data,@####@]
   491  		dsmiddleware/aememcache.GetMulti: incoming len=1
   492  		dsmiddleware/aememcache.GetMulti: hit=0 miss=1
   493  	`)
   494  	ss := strings.Split(expectedPattern, "@####@")
   495  	var buf bytes.Buffer
   496  	for idx, s := range ss {
   497  		buf.WriteString(regexp.QuoteMeta(s))
   498  		if idx != (len(ss) - 1) {
   499  			buf.WriteString("[0-9]+")
   500  		}
   501  	}
   502  	expected := regexp.MustCompile(buf.String())
   503  	if v := strings.Join(logs, "\n") + "\n"; !expected.MatchString(v) {
   504  		t.Errorf("unexpected: %v", v)
   505  	}
   506  }
   507  
   508  func TestAEMemcacheCache_MultiError(t *testing.T) {
   509  	ctx, client, cleanUp := testutils.SetupAEDatastore(t)
   510  	defer cleanUp()
   511  
   512  	var logs []string
   513  	logf := func(ctx context.Context, format string, args ...interface{}) {
   514  		t.Logf(format, args...)
   515  		logs = append(logs, fmt.Sprintf(format, args...))
   516  	}
   517  
   518  	// setup. strategies are first in - first apply.
   519  	bLog := dslog.NewLogger("before: ", logf)
   520  	client.AppendMiddleware(bLog)
   521  	defer func() {
   522  		// stop logging before cleanUp func called.
   523  		client.RemoveMiddleware(bLog)
   524  	}()
   525  
   526  	cacheKey := func(key datastore.Key) string {
   527  		return "mercari:aememcache:" + key.Encode()
   528  	}
   529  
   530  	ch := New(
   531  		WithLogger(logf),
   532  		WithCacheKey(cacheKey),
   533  	)
   534  	client.AppendMiddleware(ch)
   535  	defer func() {
   536  		// stop logging before cleanUp func called.
   537  		client.RemoveMiddleware(ch)
   538  	}()
   539  
   540  	aLog := dslog.NewLogger("after: ", logf)
   541  	client.AppendMiddleware(aLog)
   542  	defer func() {
   543  		// stop logging before cleanUp func called.
   544  		client.RemoveMiddleware(aLog)
   545  	}()
   546  
   547  	// exec.
   548  
   549  	type Data struct {
   550  		Name string
   551  	}
   552  
   553  	const size = 10
   554  
   555  	keys := make([]datastore.Key, 0, size)
   556  	list := make([]*Data, 0, size)
   557  	for i := 1; i <= size; i++ {
   558  		keys = append(keys, client.IDKey("Data", int64(i), nil))
   559  		list = append(list, &Data{
   560  			Name: fmt.Sprintf("#%d", i),
   561  		})
   562  	}
   563  
   564  	_, err := client.PutMulti(ctx, keys, list)
   565  	if err != nil {
   566  		t.Fatal(err)
   567  	}
   568  
   569  	for _, key := range keys {
   570  		if key.ID()%2 == 0 {
   571  			// delete cache id=2, 4, 6, 8, 10
   572  			err := memcache.Delete(ctx, cacheKey(key))
   573  			if err != nil {
   574  				t.Fatal(err)
   575  			}
   576  		}
   577  		if key.ID()%3 == 0 {
   578  			// Delete entity where out of aememcache scope
   579  			// delete entity id=3, 6, 9
   580  			client.RemoveMiddleware(ch)
   581  			err := client.Delete(ctx, key)
   582  			if err != nil {
   583  				t.Fatal(err)
   584  			}
   585  
   586  			client.RemoveMiddleware(aLog)
   587  			client.AppendMiddleware(ch)
   588  			client.AppendMiddleware(aLog)
   589  		}
   590  	}
   591  
   592  	list = make([]*Data, size)
   593  	err = client.GetMulti(ctx, keys, list)
   594  	merr, ok := err.(datastore.MultiError)
   595  	if !ok {
   596  		t.Fatal(err)
   597  	}
   598  
   599  	if v := len(merr); v != size {
   600  		t.Fatalf("unexpected: %v", v)
   601  	}
   602  	for idx, err := range merr {
   603  		key := keys[idx]
   604  		if key.ID()%2 == 0 && key.ID()%3 == 0 {
   605  			// not exists on memcache & datastore both
   606  			if err != datastore.ErrNoSuchEntity {
   607  				t.Error(err)
   608  			}
   609  		} else {
   610  			if v := list[idx].Name; v != fmt.Sprintf("#%d", idx+1) {
   611  				t.Errorf("unexpected: %v", v)
   612  			}
   613  		}
   614  	}
   615  
   616  	expected := heredoc.Doc(`
   617  		before: PutMultiWithoutTx #1, len(keys)=10, keys=[/Data,1, /Data,2, /Data,3, /Data,4, /Data,5, /Data,6, /Data,7, /Data,8, /Data,9, /Data,10]
   618  		after: PutMultiWithoutTx #1, len(keys)=10, keys=[/Data,1, /Data,2, /Data,3, /Data,4, /Data,5, /Data,6, /Data,7, /Data,8, /Data,9, /Data,10]
   619  		after: PutMultiWithoutTx #1, keys=[/Data,1, /Data,2, /Data,3, /Data,4, /Data,5, /Data,6, /Data,7, /Data,8, /Data,9, /Data,10]
   620  		dsmiddleware/aememcache.SetMulti: incoming len=10
   621  		dsmiddleware/aememcache.SetMulti: len=10
   622  		before: PutMultiWithoutTx #1, keys=[/Data,1, /Data,2, /Data,3, /Data,4, /Data,5, /Data,6, /Data,7, /Data,8, /Data,9, /Data,10]
   623  		before: DeleteMultiWithoutTx #2, len(keys)=1, keys=[/Data,3]
   624  		after: DeleteMultiWithoutTx #2, len(keys)=1, keys=[/Data,3]
   625  		before: DeleteMultiWithoutTx #3, len(keys)=1, keys=[/Data,6]
   626  		after: DeleteMultiWithoutTx #3, len(keys)=1, keys=[/Data,6]
   627  		before: DeleteMultiWithoutTx #4, len(keys)=1, keys=[/Data,9]
   628  		after: DeleteMultiWithoutTx #4, len(keys)=1, keys=[/Data,9]
   629  		before: GetMultiWithoutTx #5, len(keys)=10, keys=[/Data,1, /Data,2, /Data,3, /Data,4, /Data,5, /Data,6, /Data,7, /Data,8, /Data,9, /Data,10]
   630  		dsmiddleware/aememcache.GetMulti: incoming len=10
   631  		dsmiddleware/aememcache.GetMulti: hit=5 miss=5
   632  		after: GetMultiWithoutTx #5, len(keys)=5, keys=[/Data,2, /Data,4, /Data,6, /Data,8, /Data,10]
   633  		after: GetMultiWithoutTx #5, err=datastore: no such entity
   634  		dsmiddleware/aememcache.SetMulti: incoming len=4
   635  		dsmiddleware/aememcache.SetMulti: len=4
   636  		before: GetMultiWithoutTx #5, err=datastore: no such entity
   637  	`)
   638  
   639  	if v := strings.Join(logs, "\n") + "\n"; v != expected {
   640  		t.Errorf("unexpected: %v", v)
   641  	}
   642  }