sops frozen while decrypting and consumes a full CPU #665

davinkevin · 2020-04-25T16:25:58Z

Hi,

My problem is when I try to decrypt a file (env file for example), the first time the result is correctly shown, but if I run it
another time, the process will be stuck and will consume a full CPU.

I need to kill the gpg-agent process to be able to "run again" the command, but like before, only once. The second execution will be stuck and the process will consume one CPU again.

Λ\:/v/f/z/0/T/tmp.sKqd6J3qw4 kevin $ vim clear.env
Λ\:/v/f/z/0/T/tmp.sKqd6J3qw4 kevin $ cat clear.env
───────┬────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────
       │ File: clear.env
───────┼────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────
   1   │ FOO=BAR
───────┴────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────
Λ\:/v/f/z/0/T/tmp.sKqd6J3qw4 kevin $ sops -pgp 283191A5B089DED03883EB15B323BEBBC8EE667E,CE6444DB6F9508BA3353F76B950033659DC7EF98 -e clear.env > enc.env
Λ\:/v/f/z/0/T/tmp.sKqd6J3qw4 kevin $ cat enc.env
───────┬────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────
       │ File: enc.env
───────┼────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────
   1   │ FOO=ENC[AES256_GCM,data:zm1q,iv:HTYe4WhP+ZKsppZojKuIm5+YntyALL0cnKZiUcVY5J0=,tag:lXgRMo4PO2ZFjIFoBQ3iOA==,type:str]
   2   │ sops_pgp__list_1__map_enc=-----BEGIN PGP MESSAGE-----\n\nwcDMA7IrLTQCjcXKAQwAsVvjTjNIMplCN77RMdzunLZztpbFr0UW8EHKRBefh67o\nFxMhl/a7RLve6bL25L/3oLRr35FTM65/HL6Q4+NjFn6zkFwx05Z1sGk1JtrKScrq\nlvMcm8iHWvLb2K+NuIZEzREhTxBYFM
       │ kLpH92dqPvCb48uKH5aGmmeRz3Qnyzukau\ndUCGOVHQq2S2DQGlKj/ekTUg8LGjWTw/UA/wWBxZAv5onH9zTdhR2AWUWnEpfFlW\nfJUKbOB+1mtwpzCxQaLzSR4AWWwioYqbM91j7f1yDqhuJcnP4KJY99ZymRCvJwTQ\ndZNVEVKHKy9wO19jwJzDwHYcOKwwNisKEDlY3kfTeWYfinVc7n0
       │ AKc6hV+iGkYFI\ndiV2YS5pc1AQazOhVFdBkKIXny/Vb4ZLLWbc9flPnMxf4TjXq4zh3l+z0V+UB0Hy\nt+bOoPxJsgAolUxLMid5nG9o38ytXbcDyUsrr0cWbG3XKZK+Crs+CtTtGMKAwpfY\nvVONp7+F0CTgpTHpSO2a0uAB5E5cyGGoQw9UaP/jQFVjWKPhDFDgKuDJ4aiK4Ffi\no4gZiO
       │ BW5T3mmuStM925K/p32NxxFCV7LKwillL4t58DoyRKFxOC4JLkIdzQ+F5U\nwvGZ3B/nhwrz+OJfnrNw4UoQAA==\n=JsFY\n-----END PGP MESSAGE-----
   3   │ sops_pgp__list_0__map_fp=283191A5B089DED03883EB15B323BEBBC8EE667E
   4   │ sops_mac=ENC[AES256_GCM,data:IgiJZxeNEsMbwRmq/JXYqS9IiotGBSPQG6PZqvu8vgDnyKk5QYJ5Ytc/n3e4CQ/Oaf/rVjNtkMmEgCIuDGBU2AhxCtBj/qJFUSiZHyU8YJU5JC82Y7orW8LBaUarV75sBME8n9AeaVaNmZxv3XHCPYPH+yzEJbTArpDzzVkKsgc=,iv:X2n6Yn1feiCZOE
       │ x9MosqVXbNqiMRh+fOgGEhcNuVT58=,tag:pmUNpG4HztLP8qNx5w7xFA==,type:str]
   5   │ sops_pgp__list_0__map_created_at=2020-04-25T16:15:57Z
   6   │ sops_pgp__list_1__map_fp=CE6444DB6F9508BA3353F76B950033659DC7EF98
   7   │ sops_pgp__list_0__map_enc=-----BEGIN PGP MESSAGE-----\n\nwcFMA4RgP15yTZ/gARAAHLads+E/XF4KzPnuLIdlCw01tROqUSi9lAU7bJYJuZWw\n/0c0qazep4TM9PnvZ4oKLMx5vTlVStIk2FNqmytjvqglQVdx6heLczRHttc5bQi6\nGsFcU7l8PgplTZWF4nuqwdKrK9QFEv
       │ Xt8A6u8qA5pNMahgARviTVTN+dKIK58F/n\nxH8UG4FgoxKXWs8qJ2IjtCCp+ZXbQc6G0aa9RRo69l/lE6XxOQNSJgFxME5GjMK5\nvmYcT1xBMGOsu6xDwhSjfZ3VyQK7G17a7mS4JiDyE5qTnc9O7UAQqBdABSHalH5m\nlByNAqWrmNEI9NMbVF/CEzOypzlcGQ+6zBhhjPZkPMvDr8PUdP+
       │ kYXOUrVLQUDeq\nomvAk4xrYqqOoC7K1qqTVSgvx9Ou6d5y1BMElWDotqMiJv9TzGW5R9/IN2NO4Ud1\nUTuMz8DIBKHWg2kLvlTDA6+aK2cE7e5nreKeV26oiPtsSBJwNqC+ljAWNNNcd+XJ\n/8vEi8HjeIXFVkqEX5uRVn6Zg8Qhs1yCaL1jpaoNd9TcDQbVCPNASIB+H/nE/6VH\ni9fKUo
       │ 9katPCSvoJPLWAz/ps2H4e4248h7r4yOIYwPqF4qJmk7nilV1szZtFHNlZ\ng3f5JsCcYUg7TozIROIJ6Zvw/0zCikfFe6sIso9a263VJ0DBi29eWdfyGC62Gn7S\n4AHkdAI4PkPadEqxNm/jzRVg3uGMJOBm4LLhW9vgduKq7dEM4MLlJq5LCwaXS/7w\nxbw54tZk1VMqUBfpm9HwUfLcibm
       │ awPPgQ+SSaTl/o8hFf6P3978WSl0B4vv30KHh\nErQA\n=Mk8w\n-----END PGP MESSAGE-----
   8   │ sops_unencrypted_suffix=_unencrypted
   9   │ sops_version=3.5.0
  10   │ sops_lastmodified=2020-04-25T16:15:57Z
  11   │ sops_pgp__list_1__map_created_at=2020-04-25T16:15:57Z
───────┴────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────
Λ\:/v/f/z/0/T/tmp.sKqd6J3qw4 kevin $ sops -d enc.env
FOO=BAR
Λ\:/v/f/z/0/T/tmp.sKqd6J3qw4 kevin $ sops -d enc.env
^C⏎
Λ\:/v/f/z/0/T/tmp.sKqd6J3qw4 kevin $ pkill gpg-agent
Λ\:/v/f/z/0/T/tmp.sKqd6J3qw4 kevin $ sops -d enc.env
FOO=BAR

For information:

$ gpg --version
gpg (GnuPG/MacGPG2) 2.2.17
libgcrypt 1.8.5
Copyright (C) 2019 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <https://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.

Home: /Users/kevin/.gnupg
Supported algorithms:
Pubkey: RSA, ELG, DSA, ECDH, ECDSA, EDDSA
Cipher: IDEA, 3DES, CAST5, BLOWFISH, AES, AES192, AES256, TWOFISH,
        CAMELLIA128, CAMELLIA192, CAMELLIA256
Hash: SHA1, RIPEMD160, SHA256, SHA384, SHA512, SHA224
Compression: Uncompressed, ZIP, ZLIB, BZIP2
$ sops --version
sops 3.5.0 (latest)
$ gpg-agent --version
gpg-agent (GnuPG/MacGPG2) 2.2.17
libgcrypt 1.8.5
Copyright (C) 2019 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <https://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.

I've updated GPGSuite and sops to the last version to check if this could fix the bug... but without success

The text was updated successfully, but these errors were encountered:

davinkevin · 2020-05-08T09:30:19Z

For information, I switch to a simple version of gpg tooling, without the GPGSuite (following installation guide from https://dev.to/wes/how2-using-gpg-on-macos-without-gpgtools-428f)

The behavior is the same...

I've set the gpg-agent in verbose mode. If I run the echo "test" | gpg --clearsign command (twice, to be sure...), I have the following logs from the gpg-agent:

2020-05-08 11:24:37 gpg-agent[18111] handler 0x700007a92000 for fd 8 started
2020-05-08 11:24:37 gpg-agent[18111] no running SCdaemon - starting it
2020-05-08 11:24:37 gpg-agent[18111] DBG: first connection to SCdaemon established
2020-05-08 11:24:37 gpg-agent[18111] handler 0x700007a92000 for fd 8 terminated
2020-05-08 11:24:56 gpg-agent[18111] handler 0x700007b15000 for fd 11 started
2020-05-08 11:24:56 gpg-agent[18111] handler 0x700007b15000 for fd 11 terminated

2020-05-08 11:25:37 gpg-agent[18111] handler 0x700007a92000 for fd 8 started
2020-05-08 11:25:37 gpg-agent[18111] new connection to SCdaemon established (reusing)
2020-05-08 11:25:37 gpg-agent[18111] handler 0x700007a92000 for fd 8 terminated

I've add a line break to separate logs from each execution

If I run a sops -d command, twice again, I have the following result:

2020-05-08 11:26:34 gpg-agent[20567] listening on socket '/Users/kevin/.gnupg/S.gpg-agent'
2020-05-08 11:26:34 gpg-agent[20567] listening on socket '/Users/kevin/.gnupg/S.gpg-agent.extra'
2020-05-08 11:26:34 gpg-agent[20567] listening on socket '/Users/kevin/.gnupg/S.gpg-agent.browser'
2020-05-08 11:26:34 gpg-agent[20567] listening on socket '/Users/kevin/.gnupg/S.gpg-agent.ssh'
2020-05-08 11:26:34 gpg-agent[20568] gpg-agent (GnuPG) 2.2.20 started
2020-05-08 11:26:34 gpg-agent[20568] handler 0x700003a08000 for fd 8 started
2020-05-08 11:26:34 gpg-agent[20568] starting a new PIN Entry
2020-05-08 11:26:34 gpg-agent[20568] handler 0x700003a08000 for fd 8 terminated

2020-05-08 11:26:54 gpg-agent[20568] handler 0x700003a08000 for fd 8 started
2020-05-08 11:26:54 gpg-agent[20568] starting a new PIN Entry
2020-05-08 11:26:54 gpg-agent[20568] handler 0x700003a08000 for fd 8 terminated
2020-05-08 11:26:54 gpg-agent[20568] handler 0x700003a8b000 for fd 8 started
2020-05-08 11:26:55 gpg-agent[20568] handler 0x700003a8b000 for fd 8 terminated
2020-05-08 11:26:55 gpg-agent[20568] handler 0x700003a08000 for fd 8 started
2020-05-08 11:26:55 gpg-agent[20568] handler 0x700003a08000 for fd 8 terminated
2020-05-08 11:26:55 gpg-agent[20568] handler 0x700003a8b000 for fd 8 started
2020-05-08 11:26:55 gpg-agent[20568] handler 0x700003a8b000 for fd 8 terminated
2020-05-08 11:26:55 gpg-agent[20568] handler 0x700003a08000 for fd 8 started
2020-05-08 11:26:55 gpg-agent[20568] handler 0x700003a08000 for fd 8 terminated
2020-05-08 11:26:55 gpg-agent[20568] handler 0x700003a8b000 for fd 8 started
2020-05-08 11:26:55 gpg-agent[20568] handler 0x700003a8b000 for fd 8 terminated
2020-05-08 11:26:55 gpg-agent[20568] handler 0x700003a08000 for fd 8 started
2020-05-08 11:26:55 gpg-agent[20568] handler 0x700003a08000 for fd 8 terminated
2020-05-08 11:26:55 gpg-agent[20568] handler 0x700003a8b000 for fd 8 started
2020-05-08 11:26:55 gpg-agent[20568] handler 0x700003a8b000 for fd 8 terminated
2020-05-08 11:26:55 gpg-agent[20568] handler 0x700003a08000 for fd 8 started
2020-05-08 11:26:55 gpg-agent[20568] handler 0x700003a08000 for fd 8 terminated
2020-05-08 11:26:55 gpg-agent[20568] handler 0x700003a8b000 for fd 8 started
2020-05-08 11:26:55 gpg-agent[20568] handler 0x700003a8b000 for fd 8 terminated
2020-05-08 11:26:55 gpg-agent[20568] handler 0x700003a08000 for fd 8 started
2020-05-08 11:26:55 gpg-agent[20568] handler 0x700003a08000 for fd 8 terminated
2020-05-08 11:26:55 gpg-agent[20568] handler 0x700003a8b000 for fd 8 started
2020-05-08 11:26:55 gpg-agent[20568] handler 0x700003a8b000 for fd 8 terminated
...again and again...

I've add a line break to separate logs from each execution

This has been made with following versions of software:

$ gpg --version
gpg (GnuPG) 2.2.20
libgcrypt 1.8.5
Copyright (C) 2020 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <https://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.

Home: /Users/kevin/.gnupg
Supported algorithms:
Pubkey: RSA, ELG, DSA, ECDH, ECDSA, EDDSA
Cipher: IDEA, 3DES, CAST5, BLOWFISH, AES, AES192, AES256, TWOFISH,
        CAMELLIA128, CAMELLIA192, CAMELLIA256
Hash: SHA1, RIPEMD160, SHA256, SHA384, SHA512, SHA224
Compression: Uncompressed, ZIP, ZLIB, BZIP2
$ sops --version
sops 3.5.0 (latest)
$ gpg-agent --version
gpg-agent (GnuPG) 2.2.20
libgcrypt 1.8.5
Copyright (C) 2020 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <https://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.

autrilla · 2020-05-08T15:27:06Z

Sorry it took so long to respond, I missed this originally.

That does not look right. Since it looks like it's SOPS that's stuck at 100% CPU, could you run it under a debugger or a profiler and see what's using that much CPU? I've never seen this happen myself, so no idea how to reproduce it.

Maybe even a simple profile with Instruments would work, since you're on macOS. See https://help.apple.com/instruments/mac/current/#/dev147557f7 for launching instruments, then select Time Profiler and on the top left, where it says All Processes, narrow it down to only sops. Record a sample and share it here. Any other profiler works for me as well.

davinkevin · 2020-05-09T10:53:16Z

To be sure, I need to install Xcode (the heavy one) or I can install just part of it to do that?
Or maybe some solution by using dtrace or something else?

autrilla · 2020-05-09T11:39:38Z

I think you need the full Xcode.

Alternatively, you could use pprof: https://golang.org/pkg/runtime/pprof/. Xcode is probably easier, except for the download times.

davinkevin · 2020-05-10T00:57:11Z

I've followed the solution with Xcode:

sops.trace.zip

autrilla · 2020-05-12T17:04:18Z

Interesting. All the time seems to be spent repeatedly trying to decypt the private key:

Based on https://godoc.org/golang.org/x/crypto/openpgp#PromptFunction:

If the decrypted private key or given passphrase isn't correct, the function will be called again, forever.

Our prompt function is here:
https://github.com/mozilla/sops/blob/afd073a5be0fe2232d7cd345b9b30edc70ccb962/pgp/keysource.go#L321-L354

And it calls Decrypt on the private key, so that seems like the possible culprit for 100% CPU usage. I'm not sure why the key would fail to unlock from the second time onwards, though. We could fix the 100% CPU usage issue by only allowing the prompt function to be called once, but that won't fix the other issue.

davinkevin · 2020-05-12T17:51:13Z

You are talking about the Decrypt function on line 332 or 350?

In my case, I have a gpg-agent, so I think this should be 350, but don't understand why if the agent is already "ready", the Decrypt phase ends up on error 😓.

autrilla · 2020-05-12T17:58:06Z

It should be the one in 350, yeah (unless you're being prompted for your passphrase, which you're not). I'm guessing decrypting with the gpg binary works? If so, fixing the 100% CPU usage issue would fix yours as well, since even though decrypting with Go's implementation will fail, it'll fall through to the gpg binary, which sould work.

Somewhat unrelatedly, I doubt the Go PGP implementation is used successfully most of the time. Maybe we should change the default to the GPG binary.

uwehdaub · 2020-07-07T14:53:33Z

I just stumbling upon this issue and I think it's related to #338 and a known issue in x/crypto/openpgp:
golang/go#28786

What's about tackling this issue by throwing an error in

https://github.com/mozilla/sops/blob/4bc27f6eb72b1b4090753e9f3dba1d094544e1c3/pgp/keysource.go#L321

when it's called twice. Should this not address that problem?
Or do I miss something?

BR Uwe

uwehdaub · 2020-07-07T14:56:29Z

Hi @autrilla
if my above assumption is correct, I can provide a fix for this.

autrilla · 2020-07-07T16:50:37Z

Maybe not limit it to once, to give people a chance to retry in case they input the wrong passphrase. But yes, limiting the number of attempts sounds good. I would be happy to review a PR for this :)

This fixes getsops#665 See also golang/go#28786 In some strange situations it can happen, that openpgp.ReadMessage() runs into a endless loop. This seems to be triggered by a slightly inconsistency in key settings. It happened to me, but I wasn't able to reproduce it with a fresh key. A proposed solution from the x/crypto community was, to break this loop in the callback passphrasePrompt.

uwehdaub · 2020-07-08T11:54:24Z

@autrilla #690

* Fix tests * Fix endless loop in x/crypto/openpgp func ReadMessage This fixes getsops#665 See also golang/go#28786 In some strange situations it can happen, that openpgp.ReadMessage() runs into a endless loop. This seems to be triggered by a slightly inconsistency in key settings. It happened to me, but I wasn't able to reproduce it with a fresh key. A proposed solution from the x/crypto community was, to break this loop in the callback passphrasePrompt. * Revert "Fix tests" This reverts commit 285f4dc. * Improve error description getsops#690 (comment)

davinkevin changed the title ~~sops frozen while decrypting and consume a full CPU~~ sops frozen while decrypting and consumes a full CPU Apr 25, 2020

ajvb closed this as completed in 4f06780 Jul 15, 2020

ursuad mentioned this issue Jul 16, 2020

Using SOPS Sync to Apply takes over 600 seconds to run fluxcd/flux#3186

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

sops frozen while decrypting and consumes a full CPU #665

sops frozen while decrypting and consumes a full CPU #665

davinkevin commented Apr 25, 2020

davinkevin commented May 8, 2020

autrilla commented May 8, 2020

davinkevin commented May 9, 2020 •

edited

autrilla commented May 9, 2020

davinkevin commented May 10, 2020

autrilla commented May 12, 2020 •

edited

davinkevin commented May 12, 2020

autrilla commented May 12, 2020

uwehdaub commented Jul 7, 2020

uwehdaub commented Jul 7, 2020

autrilla commented Jul 7, 2020

uwehdaub commented Jul 8, 2020

sops frozen while decrypting and consumes a full CPU #665

sops frozen while decrypting and consumes a full CPU #665

Comments

davinkevin commented Apr 25, 2020

davinkevin commented May 8, 2020

autrilla commented May 8, 2020

davinkevin commented May 9, 2020 • edited

autrilla commented May 9, 2020

davinkevin commented May 10, 2020

autrilla commented May 12, 2020 • edited

davinkevin commented May 12, 2020

autrilla commented May 12, 2020

uwehdaub commented Jul 7, 2020

uwehdaub commented Jul 7, 2020

autrilla commented Jul 7, 2020

uwehdaub commented Jul 8, 2020

davinkevin commented May 9, 2020 •

edited

autrilla commented May 12, 2020 •

edited