Investigate Password Hash failure and memory usage

[tegefaulkes]

Specification

At this stage the docker image has been deployed to the test net and we have running nodes. But the nodes are crashing during startup due to an error with the password hash.

{
  "data": {
    "message": "",
    "timestamp": "2023-10-13T05:43:56.111Z",
    "data": {},
    "cause": {},
    "stack": "ErrorPasswordHash\n at hashPassword (/lib/node_modules/polykey-cli/node_modules/polykey/dist/keys/utils/password.js:89:15)\n at Object.wrapWithPassword (/lib/node_modules/polykey-cli/node_modules/polykey/dist/keys/utils/symmetric.js:161:53)\n at constructor_.writeKeyPair (/lib/node_modules/polykey-cli/node_modules/polykey/dist/keys/KeyRing.js:545:38)\n at constructor_.setupKeyPair (/lib/node_modules/polykey-cli/node_modules/polykey/dist/keys/KeyRing.js:376:28)\n at async constructor_.start (/lib/node_modules/polykey-cli/node_modules/polykey/dist/keys/KeyRing.js:106:41)\n at async /lib/node_modules/polykey-cli/node_modules/@matrixai/async-init/dist/CreateDestroyStartStop.js:88:34\n at async withF (/lib/node_modules/polykey-cli/node_modules/@matrixai/resources/dist/utils.js:17:16)\n at async KeyRing.createKeyRing (/lib/node_modules/polykey-cli/node_modules/polykey/dist/keys/KeyRing.js:59:9)\n at async PolykeyAgent.createPolykeyAgent (/lib/node_modules/polykey-cli/node_modules/polykey/dist/PolykeyAgent.js:170:23)\n at async /lib/node_modules/polykey-cli/dist/agent/CommandStart.js:190:31",
    "description": "Failed to hash password",
    "exitCode": 69
  },
  "type": "ErrorPasswordHash"
}

The running theory right now is that this process is running out of memory. Even after updating the task to run the agent with minimum ops and memory for password hashing.

I'll need to investigate memory usage and work out the root cause of this problem. I can try the following steps.

1. Run the docker image with limited memory to try and trigger the problem.
2. If I can trigger the problem, find an estimate of the amount of memory required to run a node.
3. Sanity check the problem by spinning up a larger EC2 instance and manually testing it.

Additional context

• Related: Bundling and pkg fixes #26

Tasks

1. Investigate the root cause of the password hashing failure
2. Investigate memory usage of the PolykeyAgent.
3. Possibly apply memory optimisations.

[tegefaulkes]

Ok, first stage testing results. I'm attempting to run a PolykeyAgent locally with docker. I can limit the avaliable memory with the --memory 512m parameter. The results are as follows.

1. Running with 512mb has no issues, I see that the PolykeyAgent only uses at most 400mb then starting up and generating keys.
2. Running with 200mb of memory still works but slower. The password has does not fail in this case but it's redlining the 200mb the whole time. I noticed that the block I/O jumps to 2gb after hashing and generating keys. I presume it's offloading the memory to disk to keep functioning.

[tegefaulkes]

Having a look at the running EC2 instance.

The agent seems to be using VERY little memory right now, In fact it's not doing much at all.

CONTAINER ID   NAME                                                                                                               CPU %     MEM USAGE / LIMIT     MEM %     NET I/O   BLOCK I/O        PIDS
2d8bc8be71a4   ecs-polykey-testnet-vg9a9e957878s2qgtbdmu2atvli8ms7muukb1dk4dpbm4llkki3h0-6-polykey-testnet-c0c4e18aee81abaf7800   0.00%     1.203MiB / 460.2MiB   0.26%     0B / 0B   7GB / 1.8MB      0
25e74ae7beef   ecs-agent                                                                                                          0.04%     46.61MiB / 460.2MiB   10.13%    0B / 0B   75.9GB / 939MB   11

Looking at it's logs, it's moving at a snails pace, but it seems to have passed the keys stage. But it's taking a very long time to make any progress.

[ec2-user@ip-10-1-1-179 ~]$ docker logs 2d8bc8be71a4
{"level":"INFO","keys":"polykey.PolykeyAgent","msg":"Creating PolykeyAgent"}
{"level":"INFO","keys":"polykey.PolykeyAgent","msg":"Setting umask to 077"}
{"level":"INFO","keys":"polykey.PolykeyAgent","msg":"Setting node path to /srv"}
{"level":"INFO","keys":"polykey.PolykeyAgent.Status","msg":"Starting Status"}
{"level":"INFO","keys":"polykey.PolykeyAgent.Status","msg":"Writing Status to /srv/status.json"}
{"level":"INFO","keys":"polykey.PolykeyAgent.Status","msg":"Status is STARTING"}
{"level":"INFO","keys":"polykey.PolykeyAgent.Schema","msg":"Creating Schema"}
{"level":"INFO","keys":"polykey.PolykeyAgent.Schema","msg":"Starting Schema"}
{"level":"INFO","keys":"polykey.PolykeyAgent.Schema","msg":"Setting state path to /srv/state"}
{"level":"INFO","keys":"polykey.PolykeyAgent.Schema","msg":"Started Schema"}
{"level":"INFO","keys":"polykey.PolykeyAgent.Schema","msg":"Created Schema"}
{"level":"INFO","keys":"polykey.PolykeyAgent.KeyRing","msg":"Creating KeyRing"}
{"level":"INFO","keys":"polykey.PolykeyAgent.KeyRing","msg":"Setting keys path to /srv/state/keys"}
{"level":"INFO","keys":"polykey.PolykeyAgent.KeyRing","msg":"Starting KeyRing"}
{"level":"INFO","keys":"polykey.PolykeyAgent.KeyRing","msg":"Checking /srv/state/keys/private.jwk"}
{"level":"INFO","keys":"polykey.PolykeyAgent.KeyRing","msg":"Generating root key pair from recovery code"}
{"level":"INFO","keys":"polykey.PolykeyAgent.KeyRing","msg":"Checking /srv/state/keys/db.jwk"}
{"level":"INFO","keys":"polykey.PolykeyAgent.KeyRing","msg":"Generating db key"}
{"level":"INFO","keys":"polykey.PolykeyAgent.KeyRing","msg":"Started KeyRing"}
{"level":"INFO","keys":"polykey.PolykeyAgent.KeyRing","msg":"Created KeyRing"}
{"level":"INFO","keys":"polykey.PolykeyAgent.DB","msg":"Creating DB"}
{"level":"INFO","keys":"polykey.PolykeyAgent.DB","msg":"Starting DB"}
{"level":"INFO","keys":"polykey.PolykeyAgent.DB","msg":"Setting DB path to /srv/state/db"}
{"level":"INFO","keys":"polykey.PolykeyAgent.DB","msg":"Started DB"}
{"level":"INFO","keys":"polykey.PolykeyAgent.DB","msg":"Created DB"}
{"level":"INFO","keys":"polykey.PolykeyAgent","msg":"Creating TaskManager"}
{"level":"INFO","keys":"polykey.PolykeyAgent","msg":"Starting TaskManager in Lazy Mode"}
{"level":"INFO","keys":"polykey.PolykeyAgent","msg":"Begin Tasks Repair"}
{"level":"INFO","keys":"polykey.PolykeyAgent","msg":"Finish Tasks Repair"}
{"level":"INFO","keys":"polykey.PolykeyAgent","msg":"Started TaskManager"}
{"level":"INFO","keys":"polykey.PolykeyAgent","msg":"Created TaskManager"}
{"level":"INFO","keys":"polykey.PolykeyAgent.CertManager","msg":"Creating CertManager"}
{"level":"INFO","keys":"polykey.PolykeyAgent.CertManager","msg":"Starting CertManager"}
{"level":"INFO","keys":"polykey.PolykeyAgent.CertManager","msg":"Begin current certificate setup"}
{"level":"INFO","keys":"polykey.PolykeyAgent.CertManager","msg":"Generating new current certificate"}
{"level":"INFO","keys":"polykey.PolykeyAgent.CertManager","msg":"Garbage collecting certificates"}
{"level":"INFO","keys":"polykey.PolykeyAgent.CertManager","msg":"Garbage collected certificates"}
{"level":"INFO","keys":"polykey.PolykeyAgent.CertManager","msg":"Finish current certificate setup"}
{"level":"INFO","keys":"polykey.PolykeyAgent.CertManager","msg":"Registering handler CertManager.renewCurrentCert"}
{"level":"INFO","keys":"polykey.PolykeyAgent.CertManager","msg":"Started CertManager"}
{"level":"INFO","keys":"polykey.PolykeyAgent.CertManager","msg":"Created CertManager"}
{"level":"INFO","keys":"polykey.PolykeyAgent.Sigchain","msg":"Creating Sigchain"}
{"level":"INFO","keys":"polykey.PolykeyAgent.Sigchain","msg":"Starting Sigchain"}
{"level":"INFO","keys":"polykey.PolykeyAgent.Sigchain","msg":"Started Sigchain"}
{"level":"INFO","keys":"polykey.PolykeyAgent.Sigchain","msg":"Created Sigchain"}
{"level":"INFO","keys":"polykey.PolykeyAgent.ACL","msg":"Creating ACL"}
{"level":"INFO","keys":"polykey.PolykeyAgent.ACL","msg":"Starting ACL"}
{"level":"INFO","keys":"polykey.PolykeyAgent.ACL","msg":"Started ACL"}
{"level":"INFO","keys":"polykey.PolykeyAgent.ACL","msg":"Created ACL"}
{"level":"INFO","keys":"polykey.PolykeyAgent.GestaltGraph","msg":"Creating GestaltGraph"}
{"level":"INFO","keys":"polykey.PolykeyAgent.GestaltGraph","msg":"Starting GestaltGraph"}
{"level":"INFO","keys":"polykey.PolykeyAgent.GestaltGraph","msg":"Started GestaltGraph"}
{"level":"INFO","keys":"polykey.PolykeyAgent.GestaltGraph","msg":"Created GestaltGraph"}
{"level":"INFO","keys":"polykey.PolykeyAgent.IdentitiesManager","msg":"Creating IdentitiesManager"}
{"level":"INFO","keys":"polykey.PolykeyAgent.IdentitiesManager","msg":"Starting IdentitiesManager"}
{"level":"INFO","keys":"polykey.PolykeyAgent.IdentitiesManager","msg":"Started IdentitiesManager"}
{"level":"INFO","keys":"polykey.PolykeyAgent.IdentitiesManager","msg":"Created IdentitiesManager"}
{"level":"INFO","keys":"polykey.PolykeyAgent.NodeGraph","msg":"Creating NodeGraph"}
{"level":"INFO","keys":"polykey.PolykeyAgent.NodeGraph","msg":"Starting NodeGraph"}
{"level":"INFO","keys":"polykey.PolykeyAgent.NodeGraph","msg":"Started NodeGraph"}
{"level":"INFO","keys":"polykey.PolykeyAgent.NodeGraph","msg":"Created NodeGraph"}
{"level":"INFO","keys":"polykey.PolykeyAgent.NodeManager","msg":"Starting NodeManager"}
{"level":"INFO","keys":"polykey.PolykeyAgent.NodeManager","msg":"Registering handler for setNode"}
{"level":"INFO","keys":"polykey.PolykeyAgent.NodeManager","msg":"Setting up refreshBucket tasks"}
{"level":"INFO","keys":"polykey.PolykeyAgent.NodeManager","msg":"Set up refreshBucket tasks"}
{"level":"INFO","keys":"polykey.PolykeyAgent.NodeManager","msg":"Started NodeManager"}
{"level":"INFO","keys":"polykey.PolykeyAgent.Discovery","msg":"Creating Discovery"}
{"level":"INFO","keys":"polykey.PolykeyAgent.Discovery","msg":"Starting Discovery"}
{"level":"INFO","keys":"polykey.PolykeyAgent.Discovery","msg":"Started Discovery"}
{"level":"INFO","keys":"polykey.PolykeyAgent.Discovery","msg":"Created Discovery"}
{"level":"INFO","keys":"polykey.PolykeyAgent.NotificationsManager","msg":"Creating NotificationsManager"}
{"level":"INFO","keys":"polykey.PolykeyAgent.NotificationsManager","msg":"Starting NotificationsManager"}
{"level":"INFO","keys":"polykey.PolykeyAgent.NotificationsManager","msg":"Started NotificationsManager"}
{"level":"INFO","keys":"polykey.PolykeyAgent.NotificationsManager","msg":"Created NotificationsManager"}
{"level":"INFO","keys":"polykey.PolykeyAgent.VaultManager","msg":"Creating VaultManager"}
{"level":"INFO","keys":"polykey.PolykeyAgent.VaultManager","msg":"Setting vaults path to /srv/state/vaults"}
{"level":"INFO","keys":"polykey.PolykeyAgent.VaultManager","msg":"Starting VaultManager"}
{"level":"INFO","keys":"polykey.PolykeyAgent.VaultManager","msg":"Generating vaults key"}
{"level":"INFO","keys":"polykey.PolykeyAgent.VaultManager.EFS Database","msg":"Creating DB"}
{"level":"INFO","keys":"polykey.PolykeyAgent.VaultManager.EFS Database","msg":"Starting DB"}
{"level":"INFO","keys":"polykey.PolykeyAgent.VaultManager.EFS Database","msg":"Setting DB path to /srv/state/vaults/efs"}
{"level":"INFO","keys":"polykey.PolykeyAgent.VaultManager.EFS Database","msg":"Started DB"}
{"level":"INFO","keys":"polykey.PolykeyAgent.VaultManager.EFS Database","msg":"Created DB"}

Just a thought, the seed nodes don't need the vaults functionality. We can add a flag to skip starting that functionality. It may save us some resources.

It seems weird that it's spending so long at the created DB message. There shouldn't be much happening between that and the next start/create logger message.

[tegefaulkes]

I'm going to spin up a t3a.small instance for testing. This will have 2 gigs of memory.

[tegefaulkes]

Progress update.

I managed to spin up a t3a.small EC2 instance and manually run a Polykey node in it. Seems to work just fine. I'm going to spin up a t3a.nano instance, same as the normal nodes and use that for comparison.

[CMCDragonkai]

What is causing it to move very slowly? Is it the CPU? Is it swapping to disk? Is it compute time or IO time causing problems?

[CMCDragonkai]

Use this https://www.nearform.com/blog/tracking-memory-allocation-node-js/

[CMCDragonkai]

And https://trackjs.com/blog/monitoring-javascript-memory/

Let's get some detailed metrics with different options so we fully understand the issue.

[CMCDragonkai]

And if diagrams can be generated for each option variant, that would be great.

[CMCDragonkai]

We'll keep reference to it for future deployments and our docs.

[CMCDragonkai]

Ok, first stage testing results. I'm attempting to run a PolykeyAgent locally with docker. I can limit the avaliable memory with the --memory 512m parameter. The results are as follows.

1. Running with 512mb has no issues, I see that the PolykeyAgent only uses at most 400mb then starting up and generating keys.
2. Running with 200mb of memory still works but slower. The password has does not fail in this case but it's redlining the 200mb the whole time. I noticed that the block I/O jumps to 2gb after hashing and generating keys. I presume it's offloading the memory to disk to keep functioning.

Offloading implies swapping. You said there's no swap available?

[tegefaulkes]

For reference, steps for manual testing.

1. Select the AMI image we're using for the testnet. As of now it's ami-0ace32fdb211c83e0
2. Select Launch instance from AMI.
3. Fill in the details. For reference we're using a t3a.small and t3a.nano instance for testing. Relevant config is. AIM: ami-0ace32fdb211c83e0, t3a.nano, Key pair: what ever you use to login, network: Edit it and select all the polykey-testnet options, Storage: 30gb of gp2 (default). We're launching only 1 of these.
4. Once the instance is created, log into it through SSH with the keys you configured it with.
5. We need to pull the image we're testing with.
6. Get the ECR password with aws ecr get-login-password You'll need your tokens in your .env for this to work smoothly.
7. Copy the password and run the following command. docker login -u AWS -p <password> 015248367786.dkr.ecr.ap-southeast-2.amazonaws.com
8. Pull the image with docker pull 015248367786.dkr.ecr.ap-southeast-2.amazonaws.com/polykey:testnet
9. check the image with docker image ls, note the image ID.
10. Run any commands like docker run -it <imageId> agent start -np ./srv -v
11. You can check running stats with docker stats.
12. You can check logs with docker logs <containerId>

[tegefaulkes]

I only see it running slowly on the current testnet node. I can't tell why, it's using very little CPU and memory right now and seems to be stuck. Testing locally with limited memeory, or even on the manual EC2 instances I created it seems to run fast.

I can trigger the password hash error on the manual t3a.nano instance if I don't set the password hash options to min. If I set it to min it runs fine.

If I run it with limited memory, even as low as 64mb, it passes the keys stage just fine but crashes without output setting up the DB. Running with about 200Mb seems to run fine. So 200mb seems to be the lower limit on memory needed. But note that at 200mb limit it's slamming the BLOCK I/O stat

Also note, the manual EC2 instances doesn't have any other services running. I think the instances running the nodes have some extra services that the ECS needs to function properly. For example, docker has a ecs-agent running that's using a further 40-70mb of memory out of the already very limited memory.

CONTAINER ID   NAME                                                                                                               CPU %     MEM USAGE / LIMIT     MEM %     NET I/O   BLOCK I/O        PIDS
2d8bc8be71a4   ecs-polykey-testnet-vg9a9e957878s2qgtbdmu2atvli8ms7muukb1dk4dpbm4llkki3h0-6-polykey-testnet-c0c4e18aee81abaf7800   0.00%     1.203MiB / 460.2MiB   0.26%     0B / 0B   7GB / 1.8MB      0
25e74ae7beef   ecs-agent                                                                                                          0.05%     47.81MiB / 460.2MiB   10.39%    0B / 0B   75.9GB / 939MB   11

Also note that the EC2 instance doesn't seem to have any swap available.

$ free -m
              total        used        free      shared  buff/cache   available
Mem:            460         259          34           0         166         188
Swap:             0           0           0