search

phase2 / rig

Outrigger command line tool
MIT License
11 stars 8 forks source link

Race condition in file sync w/ spinner #160

Open grayside opened 6 years ago

grayside commented 6 years ago

Problem

A race condition in the spinner logging around the rig sync initialization is causing a panic. I've seen this once during rig development where I'd been triggering sync dozens of times, and there has been one other reported case.

panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x0 pc=0x1075db2]

goroutine 1 [running]:
time.(*Ticker).Stop(0x0)
        /usr/local/go/src/time/tick.go:46 +0x22
github.com/phase2/rig/vendor/github.com/slok/gospinner.(*Spinner).Stop(0xc4200883c0, 0x0, 0x0)
        /go/src/github.com/phase2/rig/vendor/github.com/slok/gospinner/spinner.go:197 +0x103
github.com/phase2/rig/vendor/github.com/slok/gospinner.(*Spinner).FinishWithMessage(0xc4200883c0, 0xc420013ea0, 0xc, 0xc420018c00, 0x23, 0x3, 0xc420107840)
        /go/src/github.com/phase2/rig/vendor/github.com/slok/gospinner/spinner.go:240 +0x40
github.com/phase2/rig/vendor/github.com/slok/gospinner.(*Spinner).FinishWithSymbol(0xc4200883c0, 0xc420013ea0, 0xc, 0x0, 0x0)
        /go/src/github.com/phase2/rig/vendor/github.com/slok/gospinner/spinner.go:235 +0x51
github.com/phase2/rig/vendor/github.com/slok/gospinner.(*Spinner).Warn(0xc4200883c0, 0xc420018c00, 0x23)
        /go/src/github.com/phase2/rig/vendor/github.com/slok/gospinner/spinner.go:220 +0x94
github.com/phase2/rig/util.(*RigLogger).Warning(0xc4200758c0, 0x13fe190, 0x23, 0x0, 0x0, 0x0)
        /go/src/github.com/phase2/rig/util/logger.go:101 +0x186
github.com/phase2/rig/util.(*RigLogger).PrivilegeEscallationPrompt(0xc4200758c0)
        /go/src/github.com/phase2/rig/util/logger.go:149 +0xc0
github.com/phase2/rig/util.Executor.CombinedOutput(0xc4200c4840, 0x0, 0x0, 0x0, 0x0, 0x0)
        /go/src/github.com/phase2/rig/util/shell_exec.go:103 +0xf9
github.com/phase2/rig/commands.(*Machine).SetSysctl(0xc42000ebf8, 0x13fa03b, 0x1b, 0x13f1f07, 0x6, 0x0, 0x0)
        /go/src/github.com/phase2/rig/commands/machine.go:277 +0x27b
github.com/phase2/rig/commands.(*ProjectSync).StartUnisonSync(0xc42000ebe0, 0xc4200c46e0, 0xc42016e0c0, 0x11, 0xc420166120, 0xc4200186f0, 0x20, 0x0, 0xc420107860)
        /go/src/github.com/phase2/rig/commands/project_sync.go:123 +0x73
github.com/phase2/rig/commands.(*ProjectSync).RunStart(0xc42000ebe0, 0xc4200c46e0, 0xc420140ef0, 0xc42009ebb0)
        /go/src/github.com/phase2/rig/commands/project_sync.go:116 +0x277
github.com/phase2/rig/commands.(*ProjectSync).RunStart-fm(0xc4200c46e0, 0x0, 0x0)
        /go/src/github.com/phase2/rig/commands/project_sync.go:72 +0x34
github.com/phase2/rig/vendor/github.com/urfave/cli.HandleAction(0x1379ce0, 0xc420140000, 0xc4200c46e0, 0xc420166000, 0x0)
        /go/src/github.com/phase2/rig/vendor/github.com/urfave/cli/app.go:490 +0xd2
github.com/phase2/rig/vendor/github.com/urfave/cli.Command.Run(0x13f3419, 0xa, 0x0, 0x0, 0xc420140010, 0x1, 0x1, 0x1402a0d, 0x2f, 0x0, ...)
        /go/src/github.com/phase2/rig/vendor/github.com/urfave/cli/command.go:210 +0xa95
github.com/phase2/rig/vendor/github.com/urfave/cli.(*App).RunAsSubcommand(0xc4200116c0, 0xc4200c4420, 0x0, 0x0)
        /go/src/github.com/phase2/rig/vendor/github.com/urfave/cli/app.go:379 +0xa7b
github.com/phase2/rig/vendor/github.com/urfave/cli.Command.startApp(0x13f259d, 0x7, 0x0, 0x0, 0xc420047fc0, 0x1, 0x1, 0x13fb8b2, 0x1e, 0x0, ...)
        /go/src/github.com/phase2/rig/vendor/github.com/urfave/cli/command.go:298 +0x944
github.com/phase2/rig/vendor/github.com/urfave/cli.Command.Run(0x13f259d, 0x7, 0x0, 0x0, 0xc420047fc0, 0x1, 0x1, 0x13fb8b2, 0x1e, 0x0, ...)
        /go/src/github.com/phase2/rig/vendor/github.com/urfave/cli/command.go:98 +0x1319
github.com/phase2/rig/vendor/github.com/urfave/cli.(*App).Run(0xc4200111e0, 0xc42000e140, 0x5, 0x5, 0x0, 0x0)
        /go/src/github.com/phase2/rig/vendor/github.com/urfave/cli/app.go:255 +0x6f8
main.main()
        /go/src/github.com/phase2/rig/cmd/main.go:64 +0x12b1

Solution

Figure out why this is happening and fix that? Failing this, find the right spot to drop a recover statement to re-start the sync since most runs don't hit this problem.

tekante commented 6 years ago

Note that simply re-running the desired command is usually ok and avoids this issue since it is a race condition.

tjheffner commented 6 years ago

I am able to semi-reliably reproduce this error with these steps:

panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x0 pc=0x1072502]

goroutine 1 [running]:
time.(*Ticker).Stop(0x0)
    /usr/local/go/src/time/tick.go:46 +0x22
github.com/phase2/rig/vendor/github.com/slok/gospinner.(*Spinner).Stop(0xc4200a83c0, 0x0, 0x0)
    /go/src/github.com/phase2/rig/vendor/github.com/slok/gospinner/spinner.go:197 +0xe6
github.com/phase2/rig/vendor/github.com/slok/gospinner.(*Spinner).FinishWithMessage(0xc4200a83c0, 0xc420089b60, 0xc, 0xc420086c60, 0x23, 0x3, 0xc4201336e0)
    /go/src/github.com/phase2/rig/vendor/github.com/slok/gospinner/spinner.go:240 +0x40
github.com/phase2/rig/vendor/github.com/slok/gospinner.(*Spinner).FinishWithSymbol(0xc4200a83c0, 0xc420089b60, 0xc, 0x0, 0x0)
    /go/src/github.com/phase2/rig/vendor/github.com/slok/gospinner/spinner.go:235 +0x51
github.com/phase2/rig/vendor/github.com/slok/gospinner.(*Spinner).Warn(0xc4200a83c0, 0xc420086c60, 0x23)
    /go/src/github.com/phase2/rig/vendor/github.com/slok/gospinner/spinner.go:220 +0x8a
github.com/phase2/rig/util.(*RigLogger).Warning(0xc420083980, 0x13f71c1, 0x23, 0x0, 0x0, 0x0)
    /go/src/github.com/phase2/rig/util/logger.go:126 +0x17c
github.com/phase2/rig/util.(*RigLogger).PrivilegeEscallationPrompt(0xc420083980)
    /go/src/github.com/phase2/rig/util/logger.go:176 +0xb6
github.com/phase2/rig/util.Executor.CombinedOutput(0xc4200f0c60, 0x0, 0x0, 0x0, 0x0, 0x0)
    /go/src/github.com/phase2/rig/util/shell_exec.go:103 +0xe2
github.com/phase2/rig/commands.(*Machine).SetSysctl(0xc420096b58, 0x13f2dbc, 0x1b, 0x13ea825, 0x6, 0x1362b60, 0xc42016ee70)
    /go/src/github.com/phase2/rig/commands/machine.go:277 +0x254
github.com/phase2/rig/commands.(*ProjectSync).StartUnisonSync(0xc420096b40, 0xc4200f0b00, 0xc4201a3740, 0x11, 0xc420157a40, 0xc4200eea80, 0x27, 0x0, 0xc420133700)
    /go/src/github.com/phase2/rig/commands/project_sync.go:125 +0x9b
github.com/phase2/rig/commands.(*ProjectSync).RunStart(0xc420096b40, 0xc4200f0b00, 0xc42016ed20, 0xc4200c0bb0)
    /go/src/github.com/phase2/rig/commands/project_sync.go:116 +0x264
github.com/phase2/rig/commands.(*ProjectSync).RunStart-fm(0xc4200f0b00, 0x0, 0x0)
    /go/src/github.com/phase2/rig/commands/project_sync.go:72 +0x34
github.com/phase2/rig/vendor/github.com/urfave/cli.HandleAction(0x136ec00, 0xc42007fe80, 0xc4200f0b00, 0xc420157900, 0x0)
    /go/src/github.com/phase2/rig/vendor/github.com/urfave/cli/app.go:490 +0xc8
github.com/phase2/rig/vendor/github.com/urfave/cli.Command.Run(0x13ebdd9, 0xa, 0x0, 0x0, 0xc42007fe90, 0x1, 0x1, 0x13fbfc8, 0x2f, 0x0, ...)
    /go/src/github.com/phase2/rig/vendor/github.com/urfave/cli/command.go:210 +0xa36
github.com/phase2/rig/vendor/github.com/urfave/cli.(*App).RunAsSubcommand(0xc42008d380, 0xc4200f0840, 0x0, 0x0)
    /go/src/github.com/phase2/rig/vendor/github.com/urfave/cli/app.go:379 +0xa10
github.com/phase2/rig/vendor/github.com/urfave/cli.Command.startApp(0x13eaf10, 0x7, 0x0, 0x0, 0xc42007fe40, 0x1, 0x1, 0x13f46de, 0x1e, 0x0, ...)
    /go/src/github.com/phase2/rig/vendor/github.com/urfave/cli/command.go:298 +0x8d9
github.com/phase2/rig/vendor/github.com/urfave/cli.Command.Run(0x13eaf10, 0x7, 0x0, 0x0, 0xc42007fe40, 0x1, 0x1, 0x13f46de, 0x1e, 0x0, ...)
    /go/src/github.com/phase2/rig/vendor/github.com/urfave/cli/command.go:98 +0x1246
github.com/phase2/rig/vendor/github.com/urfave/cli.(*App).Run(0xc42008cea0, 0xc420082090, 0x3, 0x3, 0x0, 0x0)
    /go/src/github.com/phase2/rig/vendor/github.com/urfave/cli/app.go:255 +0x6a0
main.main()
    /go/src/github.com/phase2/rig/cmd/main.go:70 +0x13df
Error [COMMAND-ERROR]

i generally then run rig stop, rig start, eval "$(rig config)" and everything works just fine

dnmurray commented 6 years ago

I think I found it: https://github.com/slok/gospinner/pull/3

tekante commented 6 years ago

Believe this fixed with #173 which should be out with the 2.2.0 release which is now available as an RC

tekante commented 6 years ago

Looks like the firx with gospinner hasn't been completely successful in resolving this issue. I just received the following on a rig project sync:start command with version 2.2.20-rc2


panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x0 pc=0x1071712]

goroutine 1 [running]:
time.(*Ticker).Stop(0x0)
    /usr/local/go/src/time/tick.go:46 +0x22
github.com/phase2/rig/vendor/github.com/slok/gospinner.(*Spinner).Stop(0xc4200923c0, 0x0, 0x0)
    /go/src/github.com/phase2/rig/vendor/github.com/slok/gospinner/spinner.go:197 +0xe6
github.com/phase2/rig/vendor/github.com/slok/gospinner.(*Spinner).FinishWithMessage(0xc4200923c0, 0xc4200197e0, 0xc, 0xc4200166f0, 0x23, 0x3, 0xc4201194c0)
    /go/src/github.com/phase2/rig/vendor/github.com/slok/gospinner/spinner.go:240 +0x40
github.com/phase2/rig/vendor/github.com/slok/gospinner.(*Spinner).FinishWithSymbol(0xc4200923c0, 0xc4200197e0, 0xc, 0x0, 0x0)
    /go/src/github.com/phase2/rig/vendor/github.com/slok/gospinner/spinner.go:235 +0x51
github.com/phase2/rig/vendor/github.com/slok/gospinner.(*Spinner).Warn(0xc4200923c0, 0xc4200166f0, 0x23)
    /go/src/github.com/phase2/rig/vendor/github.com/slok/gospinner/spinner.go:220 +0x8a
github.com/phase2/rig/util.(*RigLogger).Warning(0xc42000f9e0, 0x13fb44f, 0x23, 0x0, 0x0, 0x0)
    /go/src/github.com/phase2/rig/util/logger.go:126 +0x17c
github.com/phase2/rig/util.(*RigLogger).PrivilegeEscalationPrompt(0xc42000f9e0)
    /go/src/github.com/phase2/rig/util/logger.go:176 +0xb6
github.com/phase2/rig/util.Executor.CombinedOutput(0xc4200d69a0, 0x0, 0x0, 0x0, 0x0, 0x0)
    /go/src/github.com/phase2/rig/util/shell_exec.go:134 +0xe2
github.com/phase2/rig/commands.(*Machine).SetSysctl(0xc420086dd8, 0x13f6f44, 0x1b, 0x13ee7cf, 0x6, 0x4, 0x3)
    /go/src/github.com/phase2/rig/commands/machine.go:277 +0x254
github.com/phase2/rig/commands.(*ProjectSync).StartUnisonSync(0xc420086dc0, 0xc4200d6840, 0xc42017a820, 0x11, 0xc42013ec60, 0xc42001c870, 0x39, 0x0, 0x0)
    /go/src/github.com/phase2/rig/commands/project_sync.go:316 +0x9b
github.com/phase2/rig/commands.(*ProjectSync).RunStart(0xc420086dc0, 0xc4200d6840, 0xc42016a8c0, 0xc4200aaba8)
    /go/src/github.com/phase2/rig/commands/project_sync.go:167 +0x1ee
github.com/phase2/rig/commands.(*ProjectSync).RunStart-fm(0xc4200d6840, 0x0, 0x0)
    /go/src/github.com/phase2/rig/commands/project_sync.go:71 +0x34
github.com/phase2/rig/vendor/github.com/urfave/cli.HandleAction(0x1372720, 0xc42004fb70, 0xc4200d6840, 0xc42013eb00, 0x0)
    /go/src/github.com/phase2/rig/vendor/github.com/urfave/cli/app.go:490 +0xc8
github.com/phase2/rig/vendor/github.com/urfave/cli.Command.Run(0x13efdbd, 0xa, 0x0, 0x0, 0xc42004fb80, 0x1, 0x1, 0x1400395, 0x2f, 0x0, ...)
    /go/src/github.com/phase2/rig/vendor/github.com/urfave/cli/command.go:210 +0xa36
github.com/phase2/rig/vendor/github.com/urfave/cli.(*App).RunAsSubcommand(0xc42007f1e0, 0xc4200d6580, 0x0, 0x0)
    /go/src/github.com/phase2/rig/vendor/github.com/urfave/cli/app.go:379 +0xa10
github.com/phase2/rig/vendor/github.com/urfave/cli.Command.startApp(0x13eeeb3, 0x7, 0x0, 0x0, 0xc42004fb30, 0x1, 0x1, 0x13f892b, 0x1e, 0x0, ...)
    /go/src/github.com/phase2/rig/vendor/github.com/urfave/cli/command.go:298 +0x8d9
github.com/phase2/rig/vendor/github.com/urfave/cli.Command.Run(0x13eeeb3, 0x7, 0x0, 0x0, 0xc42004fb30, 0x1, 0x1, 0x13f892b, 0x1e, 0x0, ...)
    /go/src/github.com/phase2/rig/vendor/github.com/urfave/cli/command.go:98 +0x1246
github.com/phase2/rig/vendor/github.com/urfave/cli.(*App).Run(0xc42007eea0, 0xc42000e0c0, 0x3, 0x3, 0x0, 0x0)
    /go/src/github.com/phase2/rig/vendor/github.com/urfave/cli/app.go:255 +0x6a0
main.main()
    /go/src/github.com/phase2/rig/cmd/main.go:71 +0x1545
mike-potter commented 6 years ago

Just to add...I have also gotten this seg fault in the rc2 version.