[BUG] Data races when using two services

[PatrLind]

I am trying to run a micro.Service together with a web.Service. Sometimes I get data race errors in different places inside the code. Usually around the logging or option handling.
Perhaps I am not using the framework correctly, in that case I would like to know an alternative way to have a micro.Service together with a web.Service.

I am using: github.com/micro/go-micro/v2 v2.4.0

This code usually reproduces the issue:

package main

import (
	"context"
	"fmt"
	"sync"
	"time"

	"github.com/micro/go-micro/v2"
	"github.com/micro/go-micro/v2/logger"
	"github.com/micro/go-micro/v2/web"
)

func main() {
	for i := 0; i < 10; i++ {
		fmt.Println("Test nr", i)
		testFunc()
	}
}

func testFunc() {
	ctx, cancel := context.WithTimeout(context.Background(), time.Millisecond*250)
	defer cancel()
	s := micro.NewService(
		micro.Name("test"),
		micro.Context(ctx),
		micro.HandleSignal(false),
	)
	w := web.NewService(
		web.MicroService(s),
		web.Context(ctx),
		web.HandleSignal(false),
	)
	s.Init()
	w.Init()

	var wg sync.WaitGroup
	wg.Add(2)
	go func() {
		defer wg.Done()
		err := s.Run()
		if err != nil {
			logger.Errorf("micro run error: %v", err)
		}
	}()
	go func() {
		defer wg.Done()
		err := w.Run()
		if err != nil {
			logger.Errorf("web run error: %v", err)
		}
	}()

	wg.Wait()
}

Environment:
go version go1.14 windows/amd64

[vtolstov]

Please, provide race log

[PatrLind]

It is a bit random, but here are two:

==================
WARNING: DATA RACE
Write at 0x00c000073400 by main goroutine:
  github.com/micro/go-micro/v2/web.(*service).Init.func1()
      C:/Users/patrik/go/pkg/mod/github.com/micro/go-micro/v2@v2.4.0/web/service.go:343 +0x458
  github.com/micro/cli/v2.(*App).RunContext()
      C:/Users/patrik/go/pkg/mod/github.com/micro/cli/v2@v2.1.2/app.go:312 +0xab0
  github.com/micro/cli/v2.(*App).Run()
      C:/Users/patrik/go/pkg/mod/github.com/micro/cli/v2@v2.1.2/app.go:210 +0xd1
  github.com/micro/cli/v2.(*App).RunAndExitOnError()
      C:/Users/patrik/go/pkg/mod/github.com/micro/cli/v2@v2.1.2/app.go:324 +0x47
  github.com/micro/go-micro/v2/config/cmd.(*cmd).Init()
      C:/Users/patrik/go/pkg/mod/github.com/micro/go-micro/v2@v2.4.0/config/cmd/cmd.go:759 +0x1d1
  github.com/micro/go-micro/v2.(*service).Init.func1()
      C:/Users/patrik/go/pkg/mod/github.com/micro/go-micro/v2@v2.4.0/service.go:96 +0x4a8
  sync.(*Once).doSlow()
      C:/Go/src/sync/once.go:66 +0x10a
  sync.(*Once).Do()
      C:/Go/src/sync/once.go:57 +0x6f
  github.com/micro/go-micro/v2.(*service).Init()
      C:/Users/patrik/go/pkg/mod/github.com/micro/go-micro/v2@v2.4.0/service.go:71 +0xbc
  main.testFunc()
      [*REDACTED*]/datarace.go:34 +0x284
  main.main()
      [*REDACTED*]/datarace.go:17 +0xd2

Previous read at 0x00c000073400 by goroutine 47:
  github.com/micro/go-micro/v2/web.(*service).run()
      C:/Users/patrik/go/pkg/mod/github.com/micro/go-micro/v2@v2.4.0/web/service.go:93 +0x65

Goroutine 47 (finished) created at:
  github.com/micro/go-micro/v2/web.(*service).Run()
      C:/Users/patrik/go/pkg/mod/github.com/micro/go-micro/v2@v2.4.0/web/service.go:392 +0xde
  main.testFunc.func2()
      [*REDACTED*]/datarace.go:48 +0x9a
==================

==================
WARNING: DATA RACE
Read at 0x00c000106110 by goroutine 18:
  github.com/micro/go-micro/v2/logger.(*defaultLogger).Options()
      C:/Users/patrik/go/pkg/mod/github.com/micro/go-micro/v2@v2.4.0/logger/default.go:130 +0x60    
  github.com/micro/go-micro/v2/logger.(*Helper).Options()
      <autogenerated>:1 +0x7f
  github.com/micro/go-micro/v2/logger.V()
      C:/Users/patrik/go/pkg/mod/github.com/micro/go-micro/v2@v2.4.0/logger/level.go:125 +0x1fda    
  github.com/micro/go-micro/v2/server/grpc.(*grpcServer).Register()
      C:/Users/patrik/go/pkg/mod/github.com/micro/go-micro/v2@v2.4.0/server/grpc/grpc.go:654 +0x1f6c
  github.com/micro/go-micro/v2/server/grpc.(*grpcServer).Start()
      C:/Users/patrik/go/pkg/mod/github.com/micro/go-micro/v2@v2.4.0/server/grpc/grpc.go:831 +0x397 
  github.com/micro/go-micro/v2.(*service).Start()
      C:/Users/patrik/go/pkg/mod/github.com/micro/go-micro/v2@v2.4.0/service.go:149 +0x114
  github.com/micro/go-micro/v2.(*service).Run()
      C:/Users/patrik/go/pkg/mod/github.com/micro/go-micro/v2@v2.4.0/service.go:210 +0x412
  main.testFunc.func1()
      [*REDACTED*]datarace.go:41 +0x9a

Previous write at 0x00c000106110 by goroutine 19:
  github.com/micro/go-micro/v2/logger.(*defaultLogger).Fields()
      C:/Users/patrik/go/pkg/mod/github.com/micro/go-micro/v2@v2.4.0/logger/default.go:42 +0x74
  github.com/micro/go-micro/v2/logger.(*Helper).Fields()
      <autogenerated>:1 +0x77
  github.com/micro/go-micro/v2/logger.(*Helper).Infof()
      C:/Users/patrik/go/pkg/mod/github.com/micro/go-micro/v2@v2.4.0/logger/helper.go:27 +0xe9
  github.com/micro/go-micro/v2/web.(*service).start()
      C:/Users/patrik/go/pkg/mod/github.com/micro/go-micro/v2@v2.4.0/web/service.go:230 +0x7ce
  github.com/micro/go-micro/v2/web.(*service).Run()
      C:/Users/patrik/go/pkg/mod/github.com/micro/go-micro/v2@v2.4.0/web/service.go:382 +0x5a
  main.testFunc.func2()
      [*REDACTED*]datarace.go:48 +0x9a

Goroutine 18 (running) created at:
  main.testFunc()
      [*REDACTED*]datarace.go:39 +0x348
  main.main()
      [*REDACTED*]datarace.go:17 +0xd2

Goroutine 19 (running) created at:
  main.testFunc()
      [*REDACTED*]datarace.go:46 +0x384
  main.main()
      [*REDACTED*]datarace.go:17 +0xd2
==================

[asim]

This was not designed to run in a single process hence the data race.

[PatrLind]

Yes, I can understand that, so there is no way to run a go micro web service together with a micro service client then? I want to make an API gateway for my backend services as well as a few services that run RPC and Web endpoints at the same time (for file upload/download)

[vtolstov]

I'll take a look, i think that web api and rpc service is useful combination

[vtolstov]

can you try master branch and replay test? ( fix in #1576 )

[PatrLind]

So far it looks very promising, I will do more tests during the day

[PatrLind]

Unfortunately I spoke too soon, I had actually failed to update to the latest master version and was still running the old version, I just happened to not get the data race whenever I quickly looked at it.
The new code now hangs on a lock here:
https://github.com/unistack-org/go-micro/blob/7a343b5a04f2eeadae5a3a26e84ab0a6046c5cb9/web/service.go#L351

Here is the call stack, it seems the app.RunContext() calls back into the web.service.Init() and tries to lock the lock again before it is released.

[vtolstov]

sorry and checks for test, can you check #1585 ?

[PatrLind]

Yes, it seems to start correctly now. Thanks!
However, I got another data race on shutdown. Here is the log:
note that the package path name is not exactly matching the version since I had to jump thru a few hoops to get the updated code into the module

==================
WARNING: DATA RACE
Read at 0x00c00025a308 by main goroutine:
  github.com/micro/go-micro/v2/web.(*service).deregister()
      C:/Users/patrik/go/pkg/mod/github.com/micro/go-micro/v2@v2.5.1-0.20200428085139-b875868a395d/web/service.go:147 +0xd9
  github.com/micro/go-micro/v2/web.(*service).Run()
      C:/Users/patrik/go/pkg/mod/github.com/micro/go-micro/v2@v2.5.1-0.20200428085139-b875868a395d/web/service.go:457 +0x318
  main.run()
      [*REDACTED*]/main.go:220 +0x875
  main.main()
      [*REDACTED*]/main.go:230 +0x3a

Previous write at 0x00c00025a308 by goroutine 50:
  github.com/micro/go-micro/v2/web.(*service).register()
      C:/Users/patrik/go/pkg/mod/github.com/micro/go-micro/v2@v2.5.1-0.20200428085139-b875868a395d/web/service.go:130 +0x2ab
  github.com/micro/go-micro/v2/web.(*service).run()
      C:/Users/patrik/go/pkg/mod/github.com/micro/go-micro/v2@v2.5.1-0.20200428085139-b875868a395d/web/service.go:105 +0xe9

Goroutine 50 (finished) created at:
  github.com/micro/go-micro/v2/web.(*service).Run()
      C:/Users/patrik/go/pkg/mod/github.com/micro/go-micro/v2@v2.5.1-0.20200428085139-b875868a395d/web/service.go:434 +0xe1
  main.run()
      [*REDACTED*]/main.go:220 +0x875
  main.main()
      [*REDACTED*]/main.go:230 +0x3a
==================

If I change the s.RLock()/s.RUnlock() to s.Lock()/s.Unlock() it seems to work better.

[PatrLind]

I have also found a related issue.
When the server is registering to the service registry, it registers the gRPC service with the same service name as the web service. This causes issues with the roundTripper in the HTTP client. It will randomly get the gRPC address or the web address and depending on what address it gets will either fail or succeed.

Here is a list of my service registry:

The first item is the web service and the second is the gRPC service.
I am setting a different name to my micro.Service, but it is overwritten by web.Service during the options init.

Perhaps to have the same name is actually what we want, but in that case the registry.Registry needs to be modified to allow for filtering by protocol type, and that change seems difficult.

[PatrLind]

A solution to the related issue I found could be to not set the micro service name to the web service name unless it is empty.
So instead of:

	// pass in own name and version
	serviceOpts = append(serviceOpts, micro.Name(s.opts.Name))
	serviceOpts = append(serviceOpts, micro.Version(s.opts.Version))

we can do:

	// pass in own name and version
	if s.opts.Service.Name() == "" {
		serviceOpts = append(serviceOpts, micro.Name(s.opts.Name))
	}
	serviceOpts = append(serviceOpts, micro.Version(s.opts.Version))

What do you think about that @vtolstov?

[vtolstov]

@PatrLind make sense, can you provide pr ?