Log location is not reversible

[nghia-nguyen-ts]

What version of Garble and Go are you using?

$ garble version
mvdan.cc/garble v0.10.0

Build settings:
      -buildmode exe
       -compiler gc
     CGO_ENABLED 1
          GOARCH arm64
            GOOS darwin
$ go version
go version go1.20.3 darwin/arm64

What environment are you running Garble on?

go env Output

$ go env
GO111MODULE=""
GOARCH="arm64"
GOBIN=""
GOCACHE="/Users/XXX/Library/Caches/go-build"
GOENV="/Users/XXX/Library/Application Support/go/env"
GOEXE=""
GOEXPERIMENT=""
GOFLAGS=""
GOHOSTARCH="arm64"
GOHOSTOS="darwin"
GOINSECURE=""
GOMODCACHE="/Users/XXX/go/pkg/mod"
GONOPROXY="github.com/XXX/*"
GONOSUMDB="github.com/XXX/*"
GOOS="darwin"
GOPATH="/Users/XXX/go"
GOPRIVATE="github.com/XXX/*"
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/opt/homebrew/Cellar/go/1.20.3/libexec"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/opt/homebrew/Cellar/go/1.20.3/libexec/pkg/tool/darwin_arm64"
GOVCS=""
GOVERSION="go1.20.3"
GCCGO="gccgo"
AR="ar"
CC="cc"
CXX="c++"
CGO_ENABLED="1"
GOMOD="/Users/XXX/Desktop/tsworkspace/garble_demo/go.mod"
GOWORK=""
CGO_CFLAGS="-O2 -g"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-O2 -g"
CGO_FFLAGS="-O2 -g"
CGO_LDFLAGS="-O2 -g"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -arch arm64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/26/qs1y2gzs5xl1sslkyxvbzv_80000gr/T/go-build3810339200=/tmp/go-build -gno-record-gcc-switches -fno-common"

What did you do?

I have a simple program that mainly deals with logging.

main.go

package main

import (
	"context"
	"fmt"
	"log"
)

func doSomething(ctx context.Context) {
	lg := &Logger{}
	lg.Fields(ctx, "marker", "[request]").Info(ctx, "first")
	lg.Info(ctx, "second")
}

type Logger struct{}

func (l *Logger) Info(ctx context.Context, args ...interface{}) {
	s := fmt.Sprintln(args...)
	log.Output(2, s)
}

func (l *Logger) Fields(ctx context.Context, args ...interface{}) *Logger {
	return l
}

func main() {
	log.SetFlags(log.LstdFlags | log.Lshortfile)
	ctx := context.Background()
	doSomething(ctx)
}

When I ran without obfuscation, the output was:

$ go run main.go
2023/06/15 14:44:04 main.go:11: first
2023/06/15 14:44:04 main.go:12: second

Next, I ran with obfuscation, the output was as below.

$ garble -literals -seed=HIWdLC75Auohff+IPbtLUA== build -o server main.go && ./server
2023/06/15 14:43:54 fNaaZg_6.go:2: first
2023/06/15 14:43:54 Aev09U6PaKmX.go:1: second

There was a weird log location: fNaaZg_6.go:2, which ends with .go:2. AFAIK, every obfuscated log locations should end with .go:1.

Next, I tried to reverse the output by copying/pasting the whole output above to a log.txt file and ran garble reverse:

$ echo '2023/06/15 14:43:54 fNaaZg_6.go:2: first
2023/06/15 14:43:54 Aev09U6PaKmX.go:1: second' > log.txt

$ garble -literals -seed=HIWdLC75Auohff+IPbtLUA== reverse main.go log.txt
2023/06/15 14:43:54 fNaaZg_6.go:2: first
2023/06/15 14:43:54 command-line-arguments/main.go:12: second

As you can see, Aev09U6PaKmX.go:1 is reversible but fNaaZg_6.go:2 is irreversible!

What did you expect to see?

The output of $ garble -literals -seed=HIWdLC75Auohff+IPbtLUA== reverse main.go log.txt should be:

2023/06/15 14:43:54 command-line-arguments/main.go:11: first
2023/06/15 14:43:54 command-line-arguments/main.go:12: second

What did you see instead?

The output of $ garble -literals -seed=HIWdLC75Auohff+IPbtLUA== reverse main.go log.txt was:

2023/06/15 14:43:54 fNaaZg_6.go:2: first
2023/06/15 14:43:54 command-line-arguments/main.go:12: second

[nghia-nguyen-ts]

One more weird thing is that when I modified the program as below and repeated the same process, I received the expected output.

main.go

package main

import (
	"context"
	"fmt"
	"log"
)

func doSomething(ctx context.Context) {
	lg := &Logger{}
	lg.Fields(ctx).Info(ctx, "first") // <- Only this line is modified
	lg.Info(ctx, "second")
}

type Logger struct{}

func (l *Logger) Info(ctx context.Context, args ...interface{}) {
	s := fmt.Sprintln(args...)
	log.Output(2, s)
}

func (l *Logger) Fields(ctx context.Context, args ...interface{}) *Logger {
	return l
}

func main() {
	log.SetFlags(log.LstdFlags | log.Lshortfile)
	ctx := context.Background()
	doSomething(ctx)
}