Go-micro: [BUG] Data races when using two services

Created on 23 Apr 2020 · 13Comments · Source: asim/go-micro

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

Source

PatrLind

Most helpful comment

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

vtolstov on 23 Apr 2020

👍2

All 13 comments

Please, provide race log

vtolstov on 23 Apr 2020

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/[email protected]/web/service.go:343 +0x458
  github.com/micro/cli/v2.(*App).RunContext()
      C:/Users/patrik/go/pkg/mod/github.com/micro/cli/[email protected]/app.go:312 +0xab0
  github.com/micro/cli/v2.(*App).Run()
      C:/Users/patrik/go/pkg/mod/github.com/micro/cli/[email protected]/app.go:210 +0xd1
  github.com/micro/cli/v2.(*App).RunAndExitOnError()
      C:/Users/patrik/go/pkg/mod/github.com/micro/cli/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/service.go:149 +0x114
  github.com/micro/go-micro/v2.(*service).Run()
      C:/Users/patrik/go/pkg/mod/github.com/micro/go-micro/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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
==================

PatrLind on 23 Apr 2020

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

asim on 23 Apr 2020

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)

PatrLind on 23 Apr 2020

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

vtolstov on 23 Apr 2020

👍2

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

vtolstov on 26 Apr 2020

❤1

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

PatrLind on 27 Apr 2020

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.

PatrLind on 28 Apr 2020

sorry and checks for test, can you check https://github.com/micro/go-micro/pull/1585 ?

vtolstov on 28 Apr 2020

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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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 on 28 Apr 2020

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 on 29 Apr 2020

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?

PatrLind on 5 May 2020

@PatrLind make sense, can you provide pr ?

vtolstov on 18 May 2020

Was this page helpful?

0 / 5 - 0 ratings