gopass print password to console, even if not supposed to do so

[camillo]

Summary

If gpg-agent takes more time to start than gopass is willing to wait (first usage after reboot on my machine), clear text password is written into console even if forbidden by -c parameter or config file.

gopass show -c ******
⚠ Entry "" not found. Starting search...
✅ Found exact match in "//***"
gpg: can't connect to the gpg-agent: IPC "connect" Aufruf fehlgeschlagen
❌ Decryption failed: exit status 2
decrypted content including password printed here

Error: failed to retrieve secret "***//": failed to decrypt

gopass does not exit after printing "exit status 2".
gpg-agent ui pops up after this message.
Decrypted content is written into console after pgp-agent got correct password for pgp key.

Expected behavior

1. gopass should not print passwords to console, if forbidden by config or parameter.
2. gopass should exit if not able to connect to gpg-agent in time.

Environment

• OS: win10pro german
• gopass Version: 1.13.1 and 1.14.4 (happens in both versions)
• Installation method: 1.13.1: choco; 1.14.4: binary download from github

[dominikschulz]

Please run with GOPASS_DEBUG_LOG=some/log/file.log and provide the (redacted) output. Otherwise I can't reproduce what's happening. It sounds like this might be Windows specific.

[camillo]

Please run with GOPASS_DEBUG_LOG=some/log/file.log and provide the (redacted) output. Otherwise I can't reproduce what's happening. It sounds like this might be Windows specific.

Thx for looking into this. Sorry for late answer; missed your comment.
Here is the part of the log after the "pwrules.init.2 added rule for…" part and stripped from personal information.
Noteable that decrpyted content is also written to the logfile.

2023/01/29 10:57:35.531317 config/io.go:44	config.loadConfig	Trying to load config from C:\Users\xxxxxx\AppData\Roaming\gopass\config.yml
2023/01/29 10:57:35.531852 config/io.go:135	config.decode	Trying to unmarshal config into *config.Config
2023/01/29 10:57:35.532386 config/io.go:158	config.decode	Loaded config: *config.Config: &config.Config{AutoClip:false, AutoImport:true, ClipTimeout:45, ExportKeys:true, NoPager:false, Notifications:true, Parsing:true, Path:"C:\\Users\\xxxxxx\\AppData\\Local\\gopass\\stores\\root", SafeContent:false, Mounts:map[string]string{"xxxxxx":"C:\\Users\\xxxxxx\\AppData\\Local\\gopass\\stores\\xxxxxx"}, ConfigPath:"", XXX:map[string]interface {}(nil)}
2023/01/29 10:57:35.532386 config/io.go:52	config.loadConfig	Loaded config from C:\Users\xxxxxx\AppData\Roaming\gopass\config.yml: &config.Config{AutoClip:false, AutoImport:true, ClipTimeout:45, ExportKeys:true, NoPager:false, Notifications:true, Parsing:true, Path:"C:\\Users\\xxxxxx\\AppData\\Local\\gopass\\stores\\root", SafeContent:false, Mounts:map[string]string{"xxxxxx":"C:\\Users\\xxxxxx\\AppData\\Local\\gopass\\stores\\xxxxxx"}, ConfigPath:"C:\\Users\\xxxxxx\\AppData\\Roaming\\gopass\\config.yml", XXX:map[string]interface {}(nil)}
2023/01/29 10:57:35.532386 cache/disk.go:29	cache.NewOnDisk	New on disk cache reminder created at C:\Users\xxxxxx\AppData\Local\gopass\gopass\reminder
2023/01/29 10:57:35.532921 root/init.go:17	root.(*Store).IsInitialized	initializing store and possible sub-stores
2023/01/29 10:57:35.532921 root/init.go:66	root.(*Store).initialize	initialize - C:\Users\xxxxxx\AppData\Local\gopass\stores\root
2023/01/29 10:57:35.532921 leaf/store.go:49	leaf.New	Instantiating  at C:\Users\xxxxxx\AppData\Local\gopass\stores\root
2023/01/29 10:57:35.532921 backend/storage.go:77	backend.DetectStorage	Trying gitfs for C:\Users\xxxxxx\AppData\Local\gopass\stores\root
2023/01/29 10:57:35.532921 backend/storage.go:82	backend.DetectStorage	Using gitfs for C:\Users\xxxxxx\AppData\Local\gopass\stores\root
2023/01/29 10:57:35.533454 leaf/store.go:60	leaf.New	Storage initialized
2023/01/29 10:57:35.533454 backend/crypto.go:91	backend.DetectCrypto	Trying gpgcli for gitfs(v0.1.0,path:C:\Users\xxxxxx\AppData\Local\gopass\stores\root)
2023/01/29 10:57:35.533454 fs/store.go:109	fs.(*Store).Exists	Checking if .gpg-id exists at C:\Users\xxxxxx\AppData\Local\gopass\stores\root\.gpg-id: true
2023/01/29 10:57:35.533454 backend/crypto.go:96	backend.DetectCrypto	Using gpgcli for gitfs(v0.1.0,path:C:\Users\xxxxxx\AppData\Local\gopass\stores\root)
2023/01/29 10:57:35.533454 cli/loader.go:25	cli.loader.New	Using Crypto Backend: gpgcli
2023/01/29 10:57:35.533988 cli/gpg.go:55	cli.New	failed to read GPG config: open C:\Users\xxxxxx\.gnupg\gpg.conf: Das System kann den angegebenen Pfad nicht finden.
2023/01/29 10:57:35.533988 cli/gpg.go:65	cli.New	initializing LRU cache
2023/01/29 10:57:35.533988 cli/gpg.go:71	cli.New	LRU cache initialized
2023/01/29 10:57:35.533988 cli/gpg.go:73	cli.New	detecting binary
2023/01/29 10:57:35.552102 cli/binary_windows.go:25	cli.detectBinary	Looking for "C:\\Program Files (x86)\\GnuPG\\bin\\gpg.exe" ...
2023/01/29 10:57:35.589554 cli/binary_windows.go:31	cli.detectBinary	Found "C:\\Program Files (x86)\\GnuPG\\bin\\gpg.exe" at "C:\\Program Files (x86)\\GnuPG\\bin\\gpg.exe" (2.3.7)
2023/01/29 10:57:35.589554 cli/binary_windows.go:25	cli.detectBinary	Looking for "C:\\Program Files (x86)\\GnuPG\\bin\\gpg.exe" ...
2023/01/29 10:57:35.626205 cli/binary_windows.go:31	cli.detectBinary	Found "C:\\Program Files (x86)\\GnuPG\\bin\\gpg.exe" at "C:\\Program Files (x86)\\GnuPG\\bin\\gpg.exe" (2.3.7)
2023/01/29 10:57:35.626205 cli/binary_windows.go:39	cli.detectBinary	using "C:\\Program Files (x86)\\GnuPG\\bin\\gpg.exe"
2023/01/29 10:57:35.626205 cli/gpg.go:79	cli.New	binary detected
2023/01/29 10:57:35.626205 leaf/store.go:66	leaf.New	Crypto initialized
2023/01/29 10:57:35.626205 leaf/store.go:68	leaf.New	Instantiated  at C:\Users\xxxxxx\AppData\Local\gopass\stores\root - storage: &gitfs.Git{fs:(*fs.Store)(0xc0002bd420)} - crypto: &cli.GPG{binary:"C:\\Program Files (x86)\\GnuPG\\bin\\gpg.exe", args:[]string{"--quiet", "--yes", "--compress-algo=none", "--no-encrypt-to", "--no-auto-check-trustdb"}, pubKeys:gpg.KeyList(nil), privKeys:gpg.KeyList(nil), listCache:(*lru.TwoQueueCache)(0xc00009c780), throwKids:false}
2023/01/29 10:57:35.626205 root/init.go:71	root.(*Store).initialize	Root Store initialized at C:\Users\xxxxxx\AppData\Local\gopass\stores\root
2023/01/29 10:57:35.626205 root/mount.go:40	root.(*Store).addMount	addMount - Path: C:\Users\xxxxxx\AppData\Local\gopass\stores\xxxxxx - Full: C:\Users\xxxxxx\AppData\Local\gopass\stores\xxxxxx
2023/01/29 10:57:35.626205 leaf/store.go:49	leaf.New	Instantiating xxxxxx at C:\Users\xxxxxx\AppData\Local\gopass\stores\xxxxxx
2023/01/29 10:57:35.626205 backend/storage.go:77	backend.DetectStorage	Trying gitfs for C:\Users\xxxxxx\AppData\Local\gopass\stores\xxxxxx
2023/01/29 10:57:35.626205 backend/storage.go:82	backend.DetectStorage	Using gitfs for C:\Users\xxxxxx\AppData\Local\gopass\stores\xxxxxx
2023/01/29 10:57:35.627304 leaf/store.go:60	leaf.New	Storage initialized
2023/01/29 10:57:35.627304 backend/crypto.go:91	backend.DetectCrypto	Trying gpgcli for gitfs(v0.1.0,path:C:\Users\xxxxxx\AppData\Local\gopass\stores\xxxxxx)
2023/01/29 10:57:35.627304 fs/store.go:109	fs.(*Store).Exists	Checking if .gpg-id exists at C:\Users\xxxxxx\AppData\Local\gopass\stores\xxxxxx\.gpg-id: true
2023/01/29 10:57:35.627304 backend/crypto.go:96	backend.DetectCrypto	Using gpgcli for gitfs(v0.1.0,path:C:\Users\xxxxxx\AppData\Local\gopass\stores\xxxxxx)
2023/01/29 10:57:35.627304 cli/loader.go:25	cli.loader.New	Using Crypto Backend: gpgcli
2023/01/29 10:57:35.627845 cli/gpg.go:55	cli.New	failed to read GPG config: open C:\Users\xxxxxx\.gnupg\gpg.conf: Das System kann den angegebenen Pfad nicht finden.
2023/01/29 10:57:35.627845 cli/gpg.go:65	cli.New	initializing LRU cache
2023/01/29 10:57:35.627845 cli/gpg.go:71	cli.New	LRU cache initialized
2023/01/29 10:57:35.627845 cli/gpg.go:73	cli.New	detecting binary
2023/01/29 10:57:35.645950 cli/binary_windows.go:25	cli.detectBinary	Looking for "C:\\Program Files (x86)\\GnuPG\\bin\\gpg.exe" ...
2023/01/29 10:57:35.682654 cli/binary_windows.go:31	cli.detectBinary	Found "C:\\Program Files (x86)\\GnuPG\\bin\\gpg.exe" at "C:\\Program Files (x86)\\GnuPG\\bin\\gpg.exe" (2.3.7)
2023/01/29 10:57:35.682654 cli/binary_windows.go:25	cli.detectBinary	Looking for "C:\\Program Files (x86)\\GnuPG\\bin\\gpg.exe" ...
2023/01/29 10:57:35.719966 cli/binary_windows.go:31	cli.detectBinary	Found "C:\\Program Files (x86)\\GnuPG\\bin\\gpg.exe" at "C:\\Program Files (x86)\\GnuPG\\bin\\gpg.exe" (2.3.7)
2023/01/29 10:57:35.719966 cli/binary_windows.go:39	cli.detectBinary	using "C:\\Program Files (x86)\\GnuPG\\bin\\gpg.exe"
2023/01/29 10:57:35.719966 cli/gpg.go:79	cli.New	binary detected
2023/01/29 10:57:35.719966 leaf/store.go:66	leaf.New	Crypto initialized
2023/01/29 10:57:35.719966 leaf/store.go:68	leaf.New	Instantiated xxxxxx at C:\Users\xxxxxx\AppData\Local\gopass\stores\xxxxxx - storage: &gitfs.Git{fs:(*fs.Store)(0xc0003706f0)} - crypto: &cli.GPG{binary:"C:\\Program Files (x86)\\GnuPG\\bin\\gpg.exe", args:[]string{"--quiet", "--yes", "--compress-algo=none", "--no-encrypt-to", "--no-auto-check-trustdb"}, pubKeys:gpg.KeyList(nil), privKeys:gpg.KeyList(nil), listCache:(*lru.TwoQueueCache)(0xc00066a180), throwKids:false}
2023/01/29 10:57:35.719966 fs/store.go:109	fs.(*Store).Exists	Checking if .gpg-id exists at C:\Users\xxxxxx\AppData\Local\gopass\stores\xxxxxx\.gpg-id: true
2023/01/29 10:57:35.719966 root/mount.go:54	root.(*Store).addMount	Added mount xxxxxx -> C:\Users\xxxxxx\AppData\Local\gopass\stores\xxxxxx (C:\Users\xxxxxx\AppData\Local\gopass\stores\xxxxxx)
2023/01/29 10:57:35.719966 root/init.go:81	root.(*Store).initialize	Sub-Store mounted at xxxxxx from C:\Users\xxxxxx\AppData\Local\gopass\stores\xxxxxx
2023/01/29 10:57:35.719966 fs/store.go:109	fs.(*Store).Exists	Checking if .gpg-id exists at C:\Users\xxxxxx\AppData\Local\gopass\stores\root\.gpg-id: true
2023/01/29 10:57:35.719966 action/init.go:36	action.(*Action).IsInitialized	Store is fully initialized and ready to go

All systems go. 🚀
2023/01/29 10:57:35.720561 fs/store.go:156	fs.(*Store).IsDir	xxxSecretNamexxx at C:\Users\xxxxxx\AppData\Local\gopass\stores\root\xxxSecretNamexxx is a directory? false
2023/01/29 10:57:35.720561 fs/store.go:156	fs.(*Store).IsDir	xxxSecretNamexxx at C:\Users\xxxxxx\AppData\Local\gopass\stores\root\xxxSecretNamexxx is a directory? false
2023/01/29 10:57:35.720561 fs/store.go:41	fs.(*Store).Get	Reading xxxSecretNamexxx.gpg from C:\Users\xxxxxx\AppData\Local\gopass\stores\root\xxxSecretNamexxx.gpg
2023/01/29 10:57:35.721096 leaf/read.go:22	leaf.(*Store).Get	File xxxSecretNamexxx.gpg not found: open C:\Users\xxxxxx\AppData\Local\gopass\stores\root\xxxSecretNamexxx.gpg: Das System kann die angegebene Datei nicht finden.
2023/01/29 10:57:35.725327 action/show.go:306	action.(*Action).showHandleError	WARNING: Entry "xxxSecretNamexxx" not found. Starting search...
2023/01/29 10:57:35.725327 fs/store.go:118	fs.(*Store).List	Listing 
2023/01/29 10:57:35.740985 leaf/list.go:25	leaf.(*Store).List	Listing : [.gpg-id xxxxxx]
2023/01/29 10:57:35.740985 fs/store.go:118	fs.(*Store).List	Listing 
2023/01/29 10:57:35.754220 fs/store.go:118	fs.(*Store).List	Listing 
2023/01/29 10:57:35.759780 leaf/list.go:25	leaf.(*Store).List	Listing : [.gitattributes .gpg-id xxxxxx]
2023/01/29 10:57:35.759980 fs/store.go:118	fs.(*Store).List	Listing 
2023/01/29 10:57:35.759980 action/find.go:68	action.(*Action).find	OK: Found exact match in "games/xxxxxx/xxxSecretNamexxx"
2023/01/29 10:57:35.759980 fs/store.go:156	fs.(*Store).IsDir	games\xxxxxx\xxxSecretNamexxx at C:\Users\xxxxxx\AppData\Local\gopass\stores\root\games\xxxxxx\xxxSecretNamexxx is a directory? false
2023/01/29 10:57:35.759980 fs/store.go:156	fs.(*Store).IsDir	games\xxxxxx\xxxSecretNamexxx at C:\Users\xxxxxx\AppData\Local\gopass\stores\root\games\xxxxxx\xxxSecretNamexxx is a directory? false
2023/01/29 10:57:35.759980 fs/store.go:41	fs.(*Store).Get	Reading games\xxxxxx\xxxSecretNamexxx.gpg from C:\Users\xxxxxx\AppData\Local\gopass\stores\root\games\xxxxxx\xxxSecretNamexxx.gpg
2023/01/29 10:57:35.759980 cli/decrypt.go:22	cli.(*GPG).Decrypt	C:\Program Files (x86)\GnuPG\bin\gpg.exe [C:\Program Files (x86)\GnuPG\bin\gpg.exe --quiet --yes --compress-algo=none --no-encrypt-to --no-auto-check-trustdb --decrypt]
2023/01/29 10:58:30.838299 leaf/read.go:28	leaf.(*Store).Get	ERROR: Decryption failed: exit status 2
DECRYPTED PASSWORD HERE
DECRYPTED ADDITONAL COMMENT HERE
2023/01/29 10:58:30.845224 action/show.go:295	action.(*Action).showHandleError	failed to retrieve secret "games/xxxxxx/xxxSecretNamexxx": failed to decrypt - stacktrace: failed to decrypt
2023/01/29 10:58:30.851071 action/show.go:312	action.(*Action).showHandleError	failed to retrieve secret "games/xxxxxx/xxxSecretNamexxx": failed to decrypt - stacktrace: failed to retrieve secret "games/xxxxxx/xxxSecretNamexxx": failed to decrypt
2023/01/29 10:58:30.851071 action/show.go:63	action.(*Action).Show	failed to retrieve secret "games/xxxxxx/xxxSecretNamexxx": failed to decrypt - stacktrace: failed to retrieve secret "games/xxxxxx/xxxSecretNamexxx": failed to decrypt