GoogleKms encryption fails on 0.6.2.0 (0.6.1.0 works)

[lebenitza]

Describe the bug
Using version 0.6.2.0 with GoogleKms causes the encryptor to fail without an apparent reason when trying to encrypt values with kamus-cli. Same settings work with 0.6.1.0. Tested with 0.6.3.0 as well, same behavior. Feels like it's because of some changes between 0.6.1.0 and 0.6.2.0.

Note: 0.6.3.0 controller fails to start with the current version of the chart but that might be something for another issue :) I'll look more into it when I'll have time

Versions used
Kamus (API images): 0.6.2.0
Kamus CLI: 0.3.0
Chart version: 0.4.6
KMS provider: GoogleKms
Kubernetes flavour and version: v1.15.7-gke.23

To Reproduce
Steps to reproduce the behavior:

1. Install the chart with the above versions and with proper GoogleKms config
2. Port-forward into an encryptor pod
3. kamus-cli encrypt --service-account --namespace --kamus-url http://localhost:9999 --allow-insecure-url --secret ""

[info  kamus-cli]: Encryption started...
[info  kamus-cli]: service account: <sa>
[info  kamus-cli]: namespace: <ns>
[warn  kamus-cli]: Auth options were not provided, will try to encrypt without authentication to kamus
[error kamus-cli]: Error while trying to encrypt with kamus: socket hang up

5. encryptor pod exist with error code 139, events show liveness and readiness checks failing as well, no useful logs in the pod while this happening

Expected behavior
kamus-cli calls returns the encrypted value after creating the required key in the keyring (as it is working on 0.6.1.0)

If you need any help let me know, curious how C# is lately :)

[omerlh]

Thanks for filing the issue! Can you please share encryptor logs? Looking on the changelog, there is nothing significantly changed between 6.1.0 to 6.2.0, so I'll be curious to see why it crash :)

Also, if you could file an issue on the chart repo I'll be happy to look into that!

[drzero42]

I can provide some logs, since I am running into the same issue. I am experimenting with kamus for our clusters on GKE, and when I use the 0.6.1.0 tagged docker images, it works, but if I switch to 0.6.2.0 or 0.6.3.0 it will give the Error while trying to encrypt with kamus: socket hang up message.

Here are the logs from the encryptor container (v0.6.2.0):

kamus-encryptor-864bcc889d-5dphl encryptor-api {"Timestamp":"2020-03-04T13:33:06.1720154+00:00","Level":"Information","MessageTemplate":"Executing endpoint '{EndpointName}'","Properties":{"EndpointName":"Kamus.Controllers.MonitoringController.IsAlive (encrypt-api)","EventId":{"Name":"ExecutingEndpoint"},"SourceContext":"Microsoft.AspNetCore.Routing.EndpointMiddleware"}}
kamus-encryptor-864bcc889d-5dphl encryptor-api {"Timestamp":"2020-03-04T13:33:06.1729306+00:00","Level":"Information","MessageTemplate":"Route matched with {RouteData}. Executing controller action with signature {MethodInfo} on controller {Controller} ({AssemblyName}).","Properties":{"RouteData":"{action = \"IsAlive\", controller = \"Monitoring\"}","MethodInfo":"Boolean IsAlive()","Controller":"Kamus.Controllers.MonitoringController","AssemblyName":"encrypt-api","EventId":{"Id":3,"Name":"ControllerActionExecuting"},"SourceContext":"Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker","ActionId":"dc670f94-ef00-401a-8856-5b99d7bc3942","ActionName":"Kamus.Controllers.MonitoringController.IsAlive (encrypt-api)"}}
kamus-encryptor-864bcc889d-5dphl encryptor-api {"Timestamp":"2020-03-04T13:33:06.1730383+00:00","Level":"Information","MessageTemplate":"Executing ObjectResult, writing value of type '{Type}'.","Properties":{"Type":"System.Boolean","EventId":{"Id":1,"Name":"ObjectResultExecuting"},"SourceContext":"Microsoft.AspNetCore.Mvc.Infrastructure.ObjectResultExecutor","ActionId":"dc670f94-ef00-401a-8856-5b99d7bc3942","ActionName":"Kamus.Controllers.MonitoringController.IsAlive (encrypt-api)"}}
kamus-encryptor-864bcc889d-5dphl encryptor-api {"Timestamp":"2020-03-04T13:33:06.1731169+00:00","Level":"Information","MessageTemplate":"Executed action {ActionName} in {ElapsedMilliseconds}ms","Properties":{"ActionName":"Kamus.Controllers.MonitoringController.IsAlive (encrypt-api)","ElapsedMilliseconds":0.0964,"EventId":{"Id":2,"Name":"ActionExecuted"},"SourceContext":"Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker","ActionId":"dc670f94-ef00-401a-8856-5b99d7bc3942"}}
kamus-encryptor-864bcc889d-5dphl encryptor-api {"Timestamp":"2020-03-04T13:33:06.1731407+00:00","Level":"Information","MessageTemplate":"Executed endpoint '{EndpointName}'","Properties":{"EndpointName":"Kamus.Controllers.MonitoringController.IsAlive (encrypt-api)","EventId":{"Id":1,"Name":"ExecutedEndpoint"},"SourceContext":"Microsoft.AspNetCore.Routing.EndpointMiddleware"}}
kamus-encryptor-864bcc889d-5dphl encryptor-api {"Timestamp":"2020-03-04T13:33:06.4739140+00:00","Level":"Information","MessageTemplate":"Executing endpoint '{EndpointName}'","Properties":{"EndpointName":"Kamus.Controllers.MonitoringController.IsAlive (encrypt-api)","EventId":{"Name":"ExecutingEndpoint"},"SourceContext":"Microsoft.AspNetCore.Routing.EndpointMiddleware"}}
kamus-encryptor-864bcc889d-5dphl encryptor-api {"Timestamp":"2020-03-04T13:33:06.4740232+00:00","Level":"Information","MessageTemplate":"Route matched with {RouteData}. Executing controller action with signature {MethodInfo} on controller {Controller} ({AssemblyName}).","Properties":{"RouteData":"{action = \"IsAlive\", controller = \"Monitoring\"}","MethodInfo":"Boolean IsAlive()","Controller":"Kamus.Controllers.MonitoringController","AssemblyName":"encrypt-api","EventId":{"Id":3,"Name":"ControllerActionExecuting"},"SourceContext":"Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker","ActionId":"dc670f94-ef00-401a-8856-5b99d7bc3942","ActionName":"Kamus.Controllers.MonitoringController.IsAlive (encrypt-api)"}}
kamus-encryptor-864bcc889d-5dphl encryptor-api {"Timestamp":"2020-03-04T13:33:06.4741214+00:00","Level":"Information","MessageTemplate":"Executing ObjectResult, writing value of type '{Type}'.","Properties":{"Type":"System.Boolean","EventId":{"Id":1,"Name":"ObjectResultExecuting"},"SourceContext":"Microsoft.AspNetCore.Mvc.Infrastructure.ObjectResultExecutor","ActionId":"dc670f94-ef00-401a-8856-5b99d7bc3942","ActionName":"Kamus.Controllers.MonitoringController.IsAlive (encrypt-api)"}}
kamus-encryptor-864bcc889d-5dphl encryptor-api {"Timestamp":"2020-03-04T13:33:06.4741922+00:00","Level":"Information","MessageTemplate":"Executed action {ActionName} in {ElapsedMilliseconds}ms","Properties":{"ActionName":"Kamus.Controllers.MonitoringController.IsAlive (encrypt-api)","ElapsedMilliseconds":0.095,"EventId":{"Id":2,"Name":"ActionExecuted"},"SourceContext":"Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker","ActionId":"dc670f94-ef00-401a-8856-5b99d7bc3942"}}
kamus-encryptor-864bcc889d-5dphl encryptor-api {"Timestamp":"2020-03-04T13:33:06.4742132+00:00","Level":"Information","MessageTemplate":"Executed endpoint '{EndpointName}'","Properties":{"EndpointName":"Kamus.Controllers.MonitoringController.IsAlive (encrypt-api)","EventId":{"Id":1,"Name":"ExecutedEndpoint"},"SourceContext":"Microsoft.AspNetCore.Routing.EndpointMiddleware"}}

[omerlh]

That's interesting, look like a timeout - but no errors on the controller. Are you using ingress to access the encryptor? Can you try using port forward?

[drzero42]

I am using port-forward. Don't have airbag deployed, and obviously don't want to expose the encryptor without auth ;)

[omerlh]

Can you try reaching the liveness endpoint? Also, can you please try with default (AES) KMS?

[drzero42]

Liveness endpoint works:

abo@bofh42:~/sandbox/k8s$ http http://127.0.0.1:9999/api/v1/isAlive
HTTP/1.1 200 OK
Content-Length: 4
Content-Type: application/json; charset=utf-8
Date: Wed, 04 Mar 2020 15:25:16 GMT
Server: Kestrel

true

I will try with AES and get back to you with the results.

[lebenitza]

Hey @omerlh. Sorry for the late reply. AES works, I've tried it when I was looking for a working alternative to GKE KMS. I am trying to bump the version back to 0.6.2.0 in order to reproduce the problem and provide more information but the controller won't start. I think the problem is that I already have two KamusSecrets created with 0.6.1.0:

{"Timestamp":"2020-03-04T21:53:29.2917387+00:00","Level":"Information","MessageTemplate":"Starting watch for KamusSecret V1Alpha2 events","Properties":{"SourceContext":"CustomResourceDescriptorController.HostedServices.V1Alpha2Controller"}}
Hosting environment: Production
Content root path: /home/dotnet/app
Now listening on: https://0.0.0.0:8888
Now listening on: http://0.0.0.0:9999
Application started. Press Ctrl+C to shut down.
{"Timestamp":"2020-03-04T21:53:32.3880760+00:00","Level":"Information","MessageTemplate":"Handling event of type {type}. KamusSecret {name} in namespace {namespace}","Properties":{"type":"Added","name":"<redacted>","namespace":"<redacted>","SourceContext":"CustomResourceDescriptorController.HostedServices.V1Alpha2Controller"}}

I had to delete the secrets to test (fyi, I removed the healthcheck, they were creating too much noise in logs):
Encryptor:

Kamus Encryptor API 0.6.2.0 starting
Hosting environment: Production
Content root path: /home/dotnet/app
Now listening on: http://[::]:9999
Application started. Press Ctrl+C to shut down.
{"Timestamp":"2020-03-04T22:20:57.9039212+00:00","Level":"Information","MessageTemplate":"Executing endpoint '{EndpointName}'","Properties":{"EndpointName":"Kamus.Controllers.EncryptController.Encrypt (encrypt-api)","EventId":{"Name":"ExecutingEndpoint"},"SourceContext":"Microsoft.AspNetCore.Routing.EndpointMiddleware"}}
{"Timestamp":"2020-03-04T22:20:58.5028858+00:00","Level":"Information","MessageTemplate":"Route matched with {RouteData}. Executing controller action with signature {MethodInfo} on controller {Controller} ({AssemblyName}).","Properties":{"RouteData":"{action = \"Encrypt\", controller = \"Encrypt\"}","MethodInfo":"System.Threading.Tasks.Task`1[Microsoft.AspNetCore.Mvc.ActionResult] Encrypt(Kamus.Models.EncryptRequest)","Controller":"Kamus.Controllers.EncryptController","AssemblyName":"encrypt-api","EventId":{"Id":3,"Name":"ControllerActionExecuting"},"SourceContext":"Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker","ActionId":"ffc1edf2-bff1-471a-965a-f900e0a652ba","ActionName":"Kamus.Controllers.EncryptController.Encrypt (encrypt-api)"}}
{"Timestamp":"2020-03-04T22:21:01.8020728+00:00","Level":"Information","MessageTemplate":"Encryption request started, SourceIP: {sourceIp}, ServiceAccount: {sa}, Namespace: {namespace}","Properties":{"sourceIp":"::ffff:127.0.0.1","sa":"<redacted>","namespace":"<redacted>","log_type":"audit","SourceContext":"Kamus.Controllers.EncryptController","ActionId":"ffc1edf2-bff1-471a-965a-f900e0a652ba","ActionName":"Kamus.Controllers.EncryptController.Encrypt (encrypt-api)"}}

Last State:     Terminated
   Reason:       Error
   Exit Code:    139

Nothing interesting in controller:

{"Timestamp":"2020-03-04T22:19:17.9834690+00:00","Level":"Information","MessageTemplate":"Starting watch for KamusSecret V1Alpha2 events","Properties":{"SourceContext":"CustomResourceDescriptorController.HostedServices.V1Alpha2Controller"}}
Hosting environment: Production
Content root path: /home/dotnet/app
Now listening on: https://0.0.0.0:8888
Now listening on: http://0.0.0.0:9999
Application started. Press Ctrl+C to shut down.

[omerlh]

Wait, I'm not sure we're talking about the same issue here - does the issue with the controller or the encryptor? I just tested the latest encryptor version locally on my mac and it's working, so it's either docker-related issue (which will not surprise me) or something else.

[fallard84]

I have the same issue on 6.2.0 with Google Cloud KMS. Going back to 6.1.0 is working for me as well.

[lebenitza]

Wait, I'm not sure we're talking about the same issue here - does the issue with the controller or the encryptor? I just tested the latest encryptor version locally on my mac and it's working, so it's either docker-related issue (which will not surprise me) or something else.

Sorry for the confusion. Is the same issue as I described in the beginning. Controller might fail because of the encryptor. I will test encryptor with latest version to check that as well.

[omerlh]

I was able to reproduce the issue and fix it, there is something bad happening with alpine - switch to buster seems to fix it. We'll release the new version tomorrow, stay tuned!
Apparently - the container was crashing with exit code 139 (seg fault), not sure why - see the linked issue on Google SDK.

[lebenitza]

Thanks for solving this @omerlh . Really interesting issue.

[omerlh]

You welcome! Can you please confirm the issue is resolved? Get Outlook for iOS<https://aka.ms/o0ukef>

…

________________________________ From: lebenitza <notifications@github.com> Sent: Sunday, March 8, 2020 12:39:15 PM To: Soluto/kamus <kamus@noreply.github.com> Cc: Omer Levi Hevroni <omerl@soluto.com>; Mention <mention@noreply.github.com> Subject: Re: [Soluto/kamus] GoogleKms encryption fails on 0.6.2.0 (0.6.1.0 works) (#455) Thanks for solving this @omerlh<https://github.com/omerlh> . Really interesting issue. — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub<#455?email_source=notifications&email_token=ABTLGWFX5MDZFZ25O6GHC63RGNYVHA5CNFSM4K4MHLKKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOEOESL4A#issuecomment-596190704>, or unsubscribe<https://github.com/notifications/unsubscribe-auth/ABTLGWBYVTMS5OSQHG27O73RGNYVHANCNFSM4K4MHLKA>.

[lebenitza]

Is indeed fixed, I upgraded last night to 0.6.4.0.

[omerlh]

Happy to hear so!