onStop executed multi times

[coolyrat]

package main

import (
	"context"
	"fmt"
	"log"
	"os"
	"os/signal"
	"syscall"
	"time"

	"go.uber.org/fx"
)

func main() {
	server := fx.New(
		fx.Invoke(func(lc fx.Lifecycle) {
			fmt.Println("first invoke...")
			lc.Append(fx.Hook{
				OnStart: func(ctx context.Context) error {
					fmt.Println("#1 start")
					return nil
				},
				OnStop: func(ctx context.Context) error {
					fmt.Println("#1 stop")
					return nil
				},
			})
		}),

		fx.Invoke(func(lc fx.Lifecycle) {
			fmt.Println("last invoke...")
			lc.Append(fx.Hook{
				OnStart: func(ctx context.Context) error {
					fmt.Println("#2 start")
					return nil
				},
				OnStop: func(ctx context.Context) error {
					fmt.Println("#2 stop")
					return nil
				},
			})
		}),
	)

	go func() {
		server.Run()
	}()

	kill := make(chan os.Signal, 1)
	signal.Notify(kill, syscall.SIGINT, syscall.SIGTERM, syscall.SIGKILL, syscall.SIGQUIT)
	<-kill
	fmt.Println("killed")

	ctx, _ := context.WithTimeout(context.Background(), 10*time.Second)
	if err := server.Stop(ctx); err != nil {
		log.Printf("error stopping gracefully")
	}
}

When I give the stop signal, the log

...
killed
#2 stop
#1 stop
#2 stop

And I am expected to be

...
killed
#2 stop
#1 stop

Is there anything I'm doing wrong?

[sywhang]

Thanks for the report and detailed repro steps.

Which Go/Fx version are you on? I just tried to repro the issue using the code you posted but I'm seeing the expected output:

[Fx] PROVIDE    fx.Lifecycle <= go.uber.org/fx.New.func1()
[Fx] PROVIDE    fx.Shutdowner <= go.uber.org/fx.(*App).shutdowner-fm()
[Fx] PROVIDE    fx.DotGraph <= go.uber.org/fx.(*App).dotGraph-fm()
[Fx] INVOKE             main.main.func1()
first invoke
[Fx] INVOKE             main.main.func2()
last invoke...
[Fx] HOOK OnStart               main.main.func1.1() executing (caller: main.main.func1)
#1 start
[Fx] HOOK OnStart               main.main.func1.1() called by main.main.func1 ran successfully in 1.625µs
[Fx] HOOK OnStart               main.main.func2.1() executing (caller: main.main.func2)
#2 start
[Fx] HOOK OnStart               main.main.func2.1() called by main.main.func2 ran successfully in 625ns
[Fx] RUNNING
^Ckilled
[Fx] INTERRUPT
[Fx] HOOK OnStop                main.main.func2.2() executing (caller: main.main.func2)
#2 stop
[Fx] HOOK OnStop                main.main.func2.2() called by main.main.func2 ran successfully in 2.334µs
[Fx] HOOK OnStop                main.main.func1.2() executing (caller: main.main.func1)
#1 stop
[Fx] HOOK OnStop                main.main.func1.2() called by main.main.func1 ran successfully in 1.916µs

[coolyrat]

Go version: m1 1.19
Fx version: go.uber.org/fx v1.18.1

[coolyrat]

full log

[Fx] PROVIDE    fx.Lifecycle <= go.uber.org/fx.New.func1()
[Fx] PROVIDE    fx.Shutdowner <= go.uber.org/fx.(*App).shutdowner-fm()
[Fx] PROVIDE    fx.DotGraph <= go.uber.org/fx.(*App).dotGraph-fm()
[Fx] INVOKE             main.main.func1()
first invoke...
[Fx] INVOKE             main.main.func2()
last invoke...
[Fx] HOOK OnStart               main.main.func1.1() executing (caller: main.main.func1)
#1 start
[Fx] HOOK OnStart               main.main.func1.1() called by main.main.func1 ran successfully in 1.292µs
[Fx] HOOK OnStart               main.main.func2.1() executing (caller: main.main.func2)
#2 start
[Fx] HOOK OnStart               main.main.func2.1() called by main.main.func2 ran successfully in 1µs
[Fx] RUNNING
^C[Fx] INTERRUPT
killed
[Fx] HOOK OnStop                main.main.func2.2() executing (caller: main.main.func2)
#2 stop
[Fx] HOOK OnStop                main.main.func2.2() called by main.main.func2 ran successfully in 5.25µs
[Fx] HOOK OnStop                main.main.func1.2() executing (caller: main.main.func1)
#1 stop
[Fx] HOOK OnStop                main.main.func1.2() called by main.main.func1 ran successfully in 1.5µs
[Fx] HOOK OnStop                main.main.func2.2() executing (caller: main.main.func2)
#2 stop
[Fx] HOOK OnStop                main.main.func2.2() called by main.main.func2 ran successfully in 3.125µs

[sywhang]

Thanks. I can confirm that this is actually a bug. Filed #930 to track fixing this. We'll get to this shortly.

[sywhang]

Debugging it further, it looks like your code is triggering a race. while we fix this, you can avoid this problem by not invoking Stop manually by catching the SIGINT signal.

i.e. Instead of:

	go func() {
		server.Run()
	}()

	kill := make(chan os.Signal, 1)
	signal.Notify(kill, syscall.SIGINT, syscall.SIGTERM, syscall.SIGKILL, syscall.SIGQUIT)
	<-kill
	fmt.Println("killed")

	ctx, _ := context.WithTimeout(context.Background(), 10*time.Second)
	if err := server.Stop(ctx); err != nil {
		log.Printf("error stopping gracefully")
	}

Just the following code will already do what you were trying to hand-write.

	server.Run()

[coolyrat]

thanks for correcting me =)

[sywhang]

This was fixed with #931