Conversion from gpg/gitfs to age/fs failed

[gautaz]

Summary

I wanted to test the convert command (from gpg to age).
So I tested it with my already existing pass repo.
It failed (see below).

Steps To Reproduce

Reproducing might prove hard as I cannot obviously send my own password repository with all the credentials to reproduce the issue.
Here is the current output of gopass during the conversion:

❯ gopass convert --crypto age --storage fs
🚥 Syncing with all remotes ...
[<root>] 
   gitfs pull and push ... OK (no changes)
   done
✅ All done
Enter your PIN:
Crypto "age" has private keys
⚠ Converting "". Crypto: "gpg" -> "age", Storage: "gitfs" -> "fs"
Continue? [y/N/q]: y
Enter your PIN:
✅ Wrote recipients to .age-recipients
Converting store ...
]  70 / 279 [Gooooooooooooooooooooooooooooooooooooooooooooooooopass                                                                                                                                                                  ]  25.09%
2023/01/16 22:41:17 failed to convert "": failed to convert "": failed to get ciphertext of "www/accounts.eclipse.org/id"@"1a9aa4b12427ef0b087b8dd8f2a7a51055381f07": exit status 128

I was wondering if the www/accounts.eclipse.org/id secret was corrupted but I can access it with pass and gopass.

Expected behavior

The conversion to finish without any error.

Environment

• OS: Linux (NixOS)
• OS version: Linux nixos 5.15.79 #1-NixOS SMP Wed Nov 16 08:58:31 UTC 2022 x86_64 GNU/Linux
• gopass Version: gopass 1.15.3 go1.19.4 linux amd64
• Installation method: Nix package manager

Additional context

As I cannot detail a way to reproduce the issue, feel free to provide me with instructions on how to help diagnose the problem.

[gautaz]

EDIT: ⚠️ I just found out that I was misinterpreting the debugger's output, see my next comment, sorry.

Hello @dominikschulz,

I have started to debug the issue with delve and I found out something strange that might explain what is happening.
Here is an exerpt of the debugging output:

(dlv)
> github.com/gopasspw/gopass/internal/backend/storage/gitfs.(*Git).captureCmd() ./internal/backend/storage/gitfs/git.go:138 (PC: 0xa872d6)
Warning: debugging optimized function
   133:
   134: func (g *Git) captureCmd(ctx context.Context, name string, args ...string) ([]byte, []byte, error) {
   135:         bufOut := &bytes.Buffer{}
   136:         bufErr := &bytes.Buffer{}
   137:
=> 138:         cmd := exec.CommandContext(ctx, "git", args[0:]...)
   139:         cmd.Dir = getPathOverride(ctx, g.fs.Path())
   140:         cmd.Stdout = bufOut
   141:         cmd.Stderr = bufErr
   142:
   143:         debug.Log("store.%s: %s %+v (%s)", name, cmd.Path, cmd.Args, g.fs.Path())
(dlv) print ctx
context.Context(*context.valueCtx) *{
        Context: context.Context(*context.valueCtx) *{
                Context: context.Context(*context.valueCtx) ...,
                key: interface {}(github.com/gopasspw/gopass/internal/queue.contextKey) *(*interface {})(0xc000110610),
                val: interface {}(*github.com/gopasspw/gopass/internal/queue.Queue) ...,},
        key: interface {}(github.com/gopasspw/gopass/pkg/ctxutil.contextKey) ctxKeyNoNetwork (10),
        val: interface {}(bool) true,}
(dlv) print args
[]string len: 2, cap: 2, [
        "show",
        "1a9aa4b12427ef0b087b8dd8f2a7a51055381f07:www/accounts.eclipse.or...+8 more",
]

As you can see, the git command that will be executed by gopass on line 138 will be:
git show "1a9aa4b12427ef0b087b8dd8f2a7a51055381f07:www/accounts.eclipse.or...+8 more"

Which will obviously fail.
I have not dig enough in the gopass source code for now to understand why this is happening but perhaps you already have an idea of what might cause this behavior?

Here is also the stack trace:

(dlv) stack
 0  0x0000000000a872d6 in github.com/gopasspw/gopass/internal/backend/storage/gitfs.(*Git).captureCmd
    at ./internal/backend/storage/gitfs/git.go:138
 1  0x0000000000a8a194 in github.com/gopasspw/gopass/internal/backend/storage/gitfs.(*Git).GetRevision
    at ./internal/backend/storage/gitfs/git.go:434
 2  0x00000000008d7b72 in github.com/gopasspw/gopass/internal/store/leaf.(*Store).GetRevision
    at ./internal/store/leaf/rcs.go:36
 3  0x00000000008cec34 in github.com/gopasspw/gopass/internal/store/leaf.(*Store).Convert
    at ./internal/store/leaf/convert.go:104
 4  0x00000000008e1125 in github.com/gopasspw/gopass/internal/store/root.(*Store).Convert
    at ./internal/store/root/convert.go:21
 5  0x0000000000a51efb in github.com/gopasspw/gopass/internal/action.(*Action).Convert
    at ./internal/action/convert.go:84
 6  0x0000000000a7760c in github.com/gopasspw/gopass/internal/action.(*Action).Convert-fm
    at <autogenerated>:1
 7  0x00000000006092e2 in github.com/urfave/cli/v2.(*Command).Run
    at /home/del/go/pkg/mod/github.com/urfave/cli/v2@v2.23.7/command.go:271
 8  0x0000000000609537 in github.com/urfave/cli/v2.(*Command).Run
    at /home/del/go/pkg/mod/github.com/urfave/cli/v2@v2.23.7/command.go:264
 9  0x0000000000606025 in github.com/urfave/cli/v2.(*App).RunContext
    at /home/del/go/pkg/mod/github.com/urfave/cli/v2@v2.23.7/app.go:333
10  0x0000000000a8c00a in main.main
    at ./main.go:90
11  0x000000000043ae72 in runtime.main
    at /nix/store/x4p5yg47ai209jin1phhj4fc2iw3b5ix-go-1.19.4/share/go/src/runtime/proc.go:250
12  0x000000000046a401 in runtime.goexit
    at /nix/store/x4p5yg47ai209jin1phhj4fc2iw3b5ix-go-1.19.4/share/go/src/runtime/asm_amd64.s:1594

[gautaz]

Argh, sorry, my bad, I didn't realize immediately that the debugger was truncating the argument (just found the config max-string-len option of delve).
Do not take into account my latest comment, I will continue my debugging session.

[gautaz]

I just found out that debugging output can be enabled by setting the GOPASS_DEBUG_LOG environment variable.
It is described in docs/features.md but adding this in the issue template might trigger the "aha" moment faster.

Here is what I got from the debug output:

 tail -n 5 gopass.log
2023/01/18 18:28:11.318915 leaf/convert.go:103  leaf.(*Store).Convert   converting www/accounts.eclipse.org/id@1a9aa4b12427ef0b087b8dd8f2a7a51055381f07
2023/01/18 18:28:11.318980 gitfs/git.go:143     gitfs.(*Git).captureCmd store.GetRevision: /nix/store/gcf3grrbaj81ccx5jk7gdgmz4r7as6w5-git-2.36.2/bin/git [git show 1a9aa4b12427ef0b087b8dd8f2a7a51055381f07:www/accounts.eclipse.org/id.gpg] (/home/del/dev/github.com/gautaz/password-store)
2023/01/18 18:28:11.320350 gitfs/git.go:436     gitfs.(*Git).GetRevision        Command failed: fatal: path 'www/accounts.eclipse.org/id.gpg' exists on disk, but not in '1a9aa4b12427ef0b087b8dd8f2a7a51055381f07'

2023/01/18 18:28:11.320372 gitconfig/configs.go:196     gitconfig.(*Configs).Get        no value for core.post-hook found

[gautaz]

Looking at the commit 1a9aa4b12427ef0b087b8dd8f2a7a51055381f07 on my password repo, I found out that at this time I did move the secret somewhere else:

❯ git show 1a9aa4b12427ef0b087b8dd8f2a7a51055381f07
commit 1a9aa4b12427ef0b087b8dd8f2a7a51055381f07
Author: gautaz <11046232+gautaz@users.noreply.github.com>
Date:   Sun Apr 10 18:47:08 2022 +0200

    Rename www/accounts.eclipse.org to www/_/accounts.eclipse.org.

diff --git a/www/accounts.eclipse.org/id.gpg b/www/_/accounts.eclipse.org/id.gpg
similarity index 100%
rename from www/accounts.eclipse.org/id.gpg
rename to www/_/accounts.eclipse.org/id.gpg
diff --git a/www/accounts.eclipse.org/pw.gpg b/www/_/accounts.eclipse.org/pw.gpg
similarity index 100%
rename from www/accounts.eclipse.org/pw.gpg
rename to www/_/accounts.eclipse.org/pw.gpg

And I guess that I moved things again later on, so the path www/accounts.eclipse.org/id.gpg in fact does not exist on this particular commit.
Why is gopass trying to git show this file on this particular commit is still a mystery to me.

[dominikschulz]

Thanks for digging in so deep.
This might be a case the conversion doesn't support.

Not quite sure what to do about it.

[dominikschulz]

I couldn't exactly reproduce the issue (even with renamed secrets), but at least I want to improve error handling and reporting here.