refactor log handling

vinegarhq · Oct 21, 2023 · a2cd685 · a2cd685
1 parent ad834db
commit a2cd685
Show file tree

Hide file tree

Showing 8 changed files with 152 additions and 137 deletions.
diff --git a/cmd/vinegar/binary.go b/cmd/vinegar/binary.go
@@ -1,7 +1,9 @@
 package main
 
 import (
+	"bufio"
 	"fmt"
+	"io"
 	"log"
 	"os"
 	"os/exec"
@@ -11,7 +13,6 @@ import (
 	"syscall"
 	"time"
 
-	"github.com/nxadm/tail"
 	bsrpc "github.com/vinegarhq/vinegar/bloxstraprpc"
 	"github.com/vinegarhq/vinegar/internal/config"
 	"github.com/vinegarhq/vinegar/internal/config/state"
@@ -25,6 +26,14 @@ import (
 	"github.com/vinegarhq/vinegar/wine/dxvk"
 )
 
+const (
+	DialogInternalBrowserBrokenTitle = "WebView/InternalBrowser is broken"
+	DialogUseBrowserMsg              = "Use the browser for whatever you were doing just now."
+	DialogQuickLoginMsg              = "Use Quick Log In to authenticate ('Log In With Another Device' button)"
+	RobloxLogShutdownEntry           = "[FLog::SingleSurfaceApp] shutDown:"
+	RobloxLogAbsoluteExitEntry       = "[FLog::SingleSurfaceApp] unregisterMemoryPrioritizationCallback"
+)
+
 type Binary struct {
 	Splash *splash.Splash
 
@@ -37,10 +46,15 @@ type Binary struct {
 	Prefix  *wine.Prefix
 	Type    roblox.BinaryType
 	Version version.Version
-	Started time.Time
+
+	// Logging
+	Auth     bool
+	Exited   chan bool
+	Activity bsrpc.Activity
+	Output   io.Writer
 }
 
-func NewBinary(bt roblox.BinaryType, cfg *config.Config, pfx *wine.Prefix) Binary {
+func NewBinary(bt roblox.BinaryType, out io.Writer, cfg *config.Config, pfx *wine.Prefix) Binary {
 	var bcfg config.Binary
 
 	switch bt {
@@ -60,170 +74,155 @@ func NewBinary(bt roblox.BinaryType, cfg *config.Config, pfx *wine.Prefix) Binar
 		Name:   bt.BinaryName(),
 		Type:   bt,
 		Prefix: pfx,
+
+		Output: out,
+		Exited: make(chan bool, 1),
 	}
 }
 
 func (b *Binary) Run(args ...string) error {
+	// REQUIRED for HandleRobloxLog to function.
+	os.Setenv("WINEDEBUG", os.Getenv("WINEDEBUG")+",warn+debugstr")
+
 	cmd, err := b.Command(args...)
 	if err != nil {
 		return err
 	}
+	o, err := cmd.OutputPipe()
+	if err != nil {
+		return err
+	}
 
 	log.Printf("Launching %s", b.Name)
 	b.Splash.Message("Launching " + b.Alias)
 
-
 	// Launches into foreground
-	b.Started = time.Now()
 	if err := cmd.Start(); err != nil {
 		return err
 	}
 
-	// act as the signal holder, as roblox/wine will not do anything
-	// with the INT signal.
+	// Act as the signal holder, as roblox/wine will not do anything with the INT signal.
+	// Additionally, if Vinegar got TERM, it will also immediately exit, but roblox
+	// continues running.
 	c := make(chan os.Signal, 1)
-	signal.Notify(c, syscall.SIGTERM, syscall.SIGINT)
+	signal.Notify(c, os.Interrupt, syscall.SIGTERM)
 
 	go func() {
 		<-c
-		// This way, cmd.Wait() will return and the wineprefix killer
-		// will be ran.
 		log.Println("Killing Roblox")
+		// This way, cmd.Wait() will return and the wineprefix killer will be ran.
 		cmd.Process.Kill()
+		// Don't handle INT after it was recieved, this way if another signal was sent,
+		// Vinegar will immediately exit.
 		signal.Stop(c)
 	}()
 
+	// This is for cases where Roblox itself does not exit by itself, which
+	// happens sometimes (#173).
+	go func() {
+		// Gets sent by the log handler
+		<-b.Exited
+		log.Println("Got Roblox shutdown")
+		// Give roblox two seconds to cleanup its garbage
+		time.Sleep(2 * time.Second)
+		// Send a signal to the signal holder to kill the wine process
+		c <- syscall.SIGINT
+	}()
+
 	if b.Config.DiscordRPC {
-		err := bsrpc.Login()
-		if err != nil {
+		if err := bsrpc.Login(); err != nil {
 			log.Printf("Failed to authenticate Discord RPC: %s, disabling RPC", err)
 			b.Config.DiscordRPC = false
 		}
+
 		// NOTE: This will panic if logout fails
 		defer bsrpc.Logout()
 	}
 
-	// after FindLog() fails to find a log, assume Roblox hasn't started.
-	// early. if it did, assume failure and jump to cmd.Wait(), which will give the
-	// returned error to the splash screen and output if wine returns one.
-	p, err := b.FindLog()
-	if err != nil {
-		log.Printf("%s, assuming roblox failure", err)
-	} else {
-		b.Splash.Close()
-
-		go func() {
-			rblxExited, err := b.TailLog(p)
-			if err != nil {
-				log.Printf("tail roblox log file: %s", err)
-				return
-			}
-
-			if rblxExited {
-				log.Println("Got Roblox shutdown")
-				// give roblox two seconds to cleanup its garbage
-				time.Sleep(2 * time.Second)
-				// force kill the process, causing cmd.Wait() to immediately return.
-				log.Println("Killing Roblox")
-				cmd.Process.Kill()
-				cmd.Process.Kill()
-				cmd.Process.Kill()
-				cmd.Process.Kill()
-				cmd.Process.Kill()
-				cmd.Process.Kill()
-				cmd.Process.Kill()
-			}
-		}()
+	// Log handler, this *should* return once the output reader of the
+	// Wine/Roblox process is closed, indicating that it has exited.
+	// r := io.TeeReader(o, b.Output)
+	// This ^ can alternatively be used to achieve both parsing of Wine+Roblox logs
+	// while also sending it to the log output, but debugstr from Wine
+	// should be ignored for a cleaner log output, which by itself should only
+	// be used for HandleRobloxLog(), which is also sent to the log output...
+	// Although, there may be some wine logs AFTER wine exits, which is why
+	// this function only returns once there is nothing to read. Only downside
+	// to that is this the command will take some time to flush and close the
+	// output pipes.
+	if err := b.HandleWineLog(o); err != nil {
+		return err
 	}
 
-	defer func() {
-		// If roblox is already running, don't kill wineprefix, even if
-		// auto kill prefix is enabled
-		if util.CommFound("Roblox") {
-			log.Println("Roblox is already running, not killing wineprefix after exit")
-			return
-		}
-
-		if b.Config.AutoKillPrefix {
-			b.Prefix.Kill()
-		}
-	}()
-
 	if err := cmd.Wait(); err != nil {
 		return fmt.Errorf("roblox process: %w", err)
 	}
 
-	return nil
-}
-
-func (b *Binary) FindLog() (string, error) {
-	appData, err := b.Prefix.AppDataDir()
-	if err != nil {
-		return "", err
+	if util.CommFound("Roblox") {
+		log.Println("Another Roblox instance is already running, not killing wineprefix")
+		return nil
 	}
 
-	dir := filepath.Join(appData, "Local", "Roblox", "logs")
-	// May not exist if roblox has its first run
-	if err := os.MkdirAll(dir, 0o755); err != nil {
-		return "", err
+	if b.Config.AutoKillPrefix {
+		b.Prefix.Kill()
 	}
 
-	log.Println("Polling for Roblox log file, 10 retries")
-	for i := 0; i < 10; i++ {
-		time.Sleep(1 * time.Second)
+	return nil
+}
+
+func (b *Binary) HandleWineLog(wr io.Reader) error {
+	s := bufio.NewScanner(wr)
+	for s.Scan() {
+		txt := s.Text()
 
-		name, err := util.FindTimeFile(dir, &b.Started)
-		if err == nil {
-			log.Printf("Found Roblox log file: %s", name)
-			return name, nil
+		// XXXX:channel:class OutputDebugStringA "[FLog::Foo] Message"
+		if len(txt) >= 39 && txt[19:37] == "OutputDebugStringA" {
+			// length of roblox Flog message
+			if len(txt) >= 90 {
+				b.HandleRobloxLog(txt[39 : len(txt)-1])
+			}
+			continue
 		}
+
+		fmt.Fprintln(b.Output, txt)
 	}
 
-	return "", fmt.Errorf("could not find roblox log file after time %s", b.Started)
+	return s.Err()
 }
 
-// Boolean returned is if Roblox had exited, detecting via logs
-func (b *Binary) TailLog(name string) (bool, error) {
-	var a bsrpc.Activity
-	const title = "WebView/InternalBrowser is broken"
-	auth := false
-
-	t, err := tail.TailFile(name, tail.Config{Follow: true, MustExist: true})
-	if err != nil {
-		return false, err
+func (b *Binary) HandleRobloxLog(line string) {
+	// As soon as a singular Roblox log has been hit, close the splash window
+	if !b.Splash.IsClosed() {
+		b.Splash.Close()
 	}
 
-	for line := range t.Lines {
-		fmt.Fprintln(b.Prefix.Output, line.Text)
+	fmt.Fprintln(b.Output, line)
 
-		// Easy way to figure out we are authenticated, to make a more
-		// babysit message to tell the user to use quick login
-		if strings.Contains(line.Text, "DID_LOG_IN") {
-			auth = true
-		}
+	if strings.Contains(line, "DID_LOG_IN") {
+		b.Auth = true
+		return
+	}
 
-		if strings.Contains(line.Text, "the local did not install any WebView2 runtime") {
-			if auth {
-				b.Splash.Dialog(title, "use the browser for whatever you were doing just now.")
-			} else {
-				b.Splash.Dialog(title, "Use Quick Log In to authenticate ('Log In With Another Device' button)")
-			}
+	if strings.Contains(line, "InternalBrowser") {
+		msg := DialogUseBrowserMsg
+		if !b.Auth {
+			msg = DialogQuickLoginMsg
 		}
 
-		// Best we've got to know if roblox had actually quit
-		if strings.Contains(line.Text, "[FLog::SingleSurfaceApp] shutDown:") {
-			return true, nil
-		}
+		b.Splash.Dialog(DialogInternalBrowserBrokenTitle, msg)
+		return
+	}
 
-		if b.Config.DiscordRPC {
-			if err := a.HandleLog(line.Text); err != nil {
-				log.Printf("Failed to handle Discord RPC: %s", err)
-			}
-		}
+	if strings.Contains(line, RobloxLogShutdownEntry) {
+		b.Exited <- true
+		return
 	}
 
-	// this is should be unreachable
-	return false, nil
+	if b.Config.DiscordRPC {
+		if err := b.Activity.HandleLog(line); err != nil {
+			log.Printf("Failed to handle Discord RPC: %s", err)
+		}
+	}
 }
 
 func (b *Binary) FetchVersion() (version.Version, error) {

diff --git a/cmd/vinegar/vinegar.go b/cmd/vinegar/vinegar.go
@@ -84,17 +84,16 @@ func main() {
 
 			logFile := logs.File(cmd)
 			logOutput := io.MultiWriter(logFile, os.Stderr)
-
-			pfx.Output = logOutput
+			b.Output = logOutput
 			log.SetOutput(logOutput)
 
 			defer logFile.Close()
 
 			switch cmd {
 			case "player":
-				b = NewBinary(roblox.Player, &cfg, &pfx)
+				b = NewBinary(roblox.Player, logOutput, &cfg, &pfx)
 			case "studio":
-				b = NewBinary(roblox.Studio, &cfg, &pfx)
+				b = NewBinary(roblox.Studio, logOutput, &cfg, &pfx)
 			}
 
 			go func() {
@@ -116,8 +115,8 @@ func main() {
 				select {} // wait for window to close
 			}
 
-			if _, err := os.Stat(filepath.Join(pfx.Dir, "drive_c", "windows")); err != nil {
-				log.Printf("Initializing wineprefix at %s", pfx.Dir)
+			if _, err := os.Stat(filepath.Join(pfx.Dir(), "drive_c", "windows")); err != nil {
+				log.Printf("Initializing wineprefix at %s", pfx.Dir())
 
 				b.Splash.Message("Initializing wineprefix")
 				if err := PrefixInit(&pfx); err != nil {

diff --git a/go.mod b/go.mod
@@ -13,21 +13,18 @@ require (
 	dario.cat/mergo v1.0.0
 	gioui.org v0.3.0
 	github.com/hugolgst/rich-go v0.0.0-20230917173849-4a4fb1d3c362
-	github.com/nxadm/tail v1.4.11
 	golang.org/x/sys v0.11.0
 )
 
 require (
 	gioui.org/cpu v0.0.0-20210817075930-8d6a761490d2 // indirect
 	gioui.org/shader v1.0.6 // indirect
-	github.com/fsnotify/fsnotify v1.6.0 // indirect
 	github.com/go-text/typesetting v0.0.0-20230803102845-24e03d8b5372 // indirect
 	golang.org/x/exp v0.0.0-20221012211006-4de253d81b95 // indirect
 	golang.org/x/exp/shiny v0.0.0-20220827204233-334a2380cb91 // indirect
 	golang.org/x/image v0.5.0 // indirect
 	golang.org/x/text v0.7.0 // indirect
 	gopkg.in/natefinch/npipe.v2 v2.0.0-20160621034901-c1b8fa8bdcce // indirect
-	gopkg.in/tomb.v1 v1.0.0-20141024135613-dd632973f1e7 // indirect
 )
 
 retract (

diff --git a/go.sum b/go.sum
@@ -14,15 +14,11 @@ github.com/adrg/xdg v0.4.0 h1:RzRqFcjH4nE5C6oTAxhBtoE2IRyjBSa62SCbyPidvls=
 github.com/adrg/xdg v0.4.0/go.mod h1:N6ag73EX4wyxeaoeHctc1mas01KZgsj5tYiAIwqJE/E=
 github.com/davecgh/go-spew v1.1.0 h1:ZDRjVQ15GmhC3fiQ8ni8+OwkZQO4DARzQgrnXU1Liz8=
 github.com/davecgh/go-spew v1.1.0/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38=
-github.com/fsnotify/fsnotify v1.6.0 h1:n+5WquG0fcWoWp6xPWfHdbskMCQaFnG6PfBrh1Ky4HY=
-github.com/fsnotify/fsnotify v1.6.0/go.mod h1:sl3t1tCWJFWoRz9R8WJCbQihKKwmorjAbSClcnxKAGw=
 github.com/go-text/typesetting v0.0.0-20230803102845-24e03d8b5372 h1:FQivqchis6bE2/9uF70M2gmmLpe82esEm2QadL0TEJo=
 github.com/go-text/typesetting v0.0.0-20230803102845-24e03d8b5372/go.mod h1:evDBbvNR/KaVFZ2ZlDSOWWXIUKq0wCOEtzLxRM8SG3k=
 github.com/go-text/typesetting-utils v0.0.0-20230616150549-2a7df14b6a22 h1:LBQTFxP2MfsyEDqSKmUBZaDuDHN1vpqDyOZjcqS7MYI=
 github.com/hugolgst/rich-go v0.0.0-20230917173849-4a4fb1d3c362 h1:Q8D2HP1l2mOoeRVLhHjDhK8MRb7LkjESWRtd2gbauws=
 github.com/hugolgst/rich-go v0.0.0-20230917173849-4a4fb1d3c362/go.mod h1:nGaW7CGfNZnhtiFxMpc4OZdqIexGXjUlBnlmpZmjEKA=
-github.com/nxadm/tail v1.4.11 h1:8feyoE3OzPrcshW5/MJ4sGESc5cqmGkGCWlco4l0bqY=
-github.com/nxadm/tail v1.4.11/go.mod h1:OTaG3NK980DZzxbRq6lEuzgU+mug70nY11sMd4JXXHc=
 github.com/otiai10/copy v1.12.0 h1:cLMgSQnXBs1eehF0Wy/FAGsgDTDmAqFR7rQylBb1nDY=
 github.com/otiai10/copy v1.12.0/go.mod h1:rSaLseMUsZFFbsFGc7wCJnnkTAvdc5L6VWxPE4308Ww=
 github.com/otiai10/mint v1.5.1 h1:XaPLeE+9vGbuyEHem1JNk3bYc7KKqyI/na0/mLd/Kks=
@@ -54,7 +50,6 @@ golang.org/x/sys v0.0.0-20210615035016-665e8c7367d1/go.mod h1:oPkhp1MJrh7nUepCBc
 golang.org/x/sys v0.0.0-20211025201205-69cdffdb9359/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/sys v0.0.0-20220520151302-bc2c85ada10a/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/sys v0.0.0-20220722155257-8c9f86f7a55f/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
-golang.org/x/sys v0.0.0-20220908164124-27713097b956/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/sys v0.11.0 h1:eG7RXZHdqOJ1i+0lgLgCpSXAp6M3LYlAo6osgSi0xOM=
 golang.org/x/sys v0.11.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/term v0.0.0-20201126162022-7de9c90e9dd1/go.mod h1:bj7SfCRtBDWHUb9snDiAeCFNEtKQo2Wmx5Cou7ajbmo=
@@ -71,8 +66,6 @@ golang.org/x/xerrors v0.0.0-20190717185122-a985d3407aa7/go.mod h1:I/5z698sn9Ka8T
 gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0=
 gopkg.in/natefinch/npipe.v2 v2.0.0-20160621034901-c1b8fa8bdcce h1:+JknDZhAj8YMt7GC73Ei8pv4MzjDUNPHgQWJdtMAaDU=
 gopkg.in/natefinch/npipe.v2 v2.0.0-20160621034901-c1b8fa8bdcce/go.mod h1:5AcXVHNjg+BDxry382+8OKon8SEWiKktQR07RKPsv1c=
-gopkg.in/tomb.v1 v1.0.0-20141024135613-dd632973f1e7 h1:uRGJdciOHaEIrze2W8Q3AKkepLTh2hOroT7a+7czfdQ=
-gopkg.in/tomb.v1 v1.0.0-20141024135613-dd632973f1e7/go.mod h1:dt/ZhP58zS4L8KSrWDmTeBkI65Dw0HsyUHuEVlX15mw=
 gopkg.in/yaml.v3 v3.0.0-20200313102051-9f266ea9e77c/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM=
 gopkg.in/yaml.v3 v3.0.1 h1:fxVm/GzAzEWqLHuvctI91KS9hhNmmWOoWu0XTYJS7CA=
 gopkg.in/yaml.v3 v3.0.1/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM=