Memory leak when keybase status times out

[vladionescu]

In my GCP Cloud Run logs I have a string of the following

2020-02-20 17:00:00.639 PST2020/02/21 01:00:00 Listen: failed to auth: unable to run Keybase command
2020-02-20 17:00:29.641 PST2020/02/21 01:00:29 Listen: failed to auth: unable to run Keybase command
2020-02-20 17:01:17.639 PST2020/02/21 01:01:17 Listen: failed to auth: unable to run Keybase command
2020-02-20 17:02:27.939 PST2020/02/21 01:02:27 Listen: failed to auth: unable to run Keybase command
2020-02-20 17:02:54.638 PST2020/02/21 01:02:54 Listen: failed to auth: unable to run Keybase command
2020-02-20 17:03:18.541 PST2020/02/21 01:03:18 Listen: failed to auth: unable to run Keybase command
2020-02-20 17:03:43.739 PST2020/02/21 01:03:43 Listen: failed to auth: unable to run Keybase command
2020-02-20 17:04:03.739 PST2020/02/21 01:04:03 Listen: failed to auth: unable to run Keybase command
2020-02-20 17:04:42.038 PST2020/02/21 01:04:42 Listen: failed to auth: unable to run Keybase command
2020-02-20 17:05:09.139 PST2020/02/21 01:05:09 Listen: failed to auth: unable to run Keybase command
2020-02-20 17:05:33.239 PST2020/02/21 01:05:33 Listen: failed to auth: unable to run Keybase command
2020-02-20 17:06:11.238 PST2020/02/21 01:06:11 Listen: failed to auth: unable to run Keybase command
2020-02-20 17:07:00.939 PST2020/02/21 01:07:00 Listen: failed to auth: unable to run Keybase command

Which finally ends in a

2020-02-20 17:18:31.241 PSTMemory limit of 1024M exceeded with 1024M used. Consider increasing the memory limit, see https://cloud.google.com/run/docs/configuring/memory-limits

All of them are Listen: failed to auth: unable to run Keybase command, which comes from

go-keybase-chat-bot/kbchat/kbchat.go

Lines 63 to 65 in 1ce2a64

	case <-time.After(5 * time.Second):
	return "", errors.New("unable to run Keybase command")
	}

The reason why getUsername() is failing is unclear (and probably unrelated), but it doesn't seem that memory usage should increase as it keeps retrying.

[vladionescu]

Adding time keybase status to the entrypoint shell script right before my bot gets executed shows that it returns kinda slowly but still faster than 5 seconds. The 'failed to auth' error persists. Why this is happening is likely a separate issue but I wanted to have this context here.

2020-02-21T01:59:47.814485Z real	0m1.311s A 
2020-02-21T01:59:47.814497Z user	0m0.150s A 
2020-02-21T01:59:47.814509Z sys	0m0.080s A 

[joshblum]

@vladionescu thanks for the report, we have a ticket internally to investigate this

[vladionescu]

@malware-unicorn fixed the OOM by adding a <-doneCh in the timeout case:
https://github.com/malware-unicorn/go-keybase-chat-bot/blob/master/kbchat/kbchat.go#L64

[vladionescu]

On another note, I suspect the reason Command("status") fails on Cloud Run is because Cloud Run captures STDOUT and STDERR for logging.

https://cloud.google.com/run/docs/logging#container-logs

They probably neglected to duplicate those file descriptors. @malware-unicorn doesn't see this fmt.Errorf() printed, so something's going on with process output.

https://github.com/malware-unicorn/go-keybase-chat-bot/blob/master/kbchat/kbchat.go#L65

If that's the case, then p.StdoutPipe() wouldn't be getting the expected output from status.

The fix for this is either

1. Send Command() output to an FD we control, and read from that.
2. Use an API instead of shelling out to the keybase binary.

[joshblum]

@vladionescu #57 should address the memory leak, let's open a new issue for running on google cloud

[vladionescu]

Opened #58 for the Cloud Run shenanigans.