Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Changing getConnectionToNode structure, removing ForwardProxy.openConnection from NodeConnection #284

Merged
merged 1 commit into from
Nov 9, 2021

Conversation

joshuakarp
Copy link
Contributor

@joshuakarp joshuakarp commented Nov 1, 2021

Description

Change getConnectionToNode over to the correct ObjectMap pattern from https://gist.github.com/CMCDragonkai/f58f08e7eaab0430ed4467ca35527a42

Based on our sprint meeting today, I'll also remove the openConnection call from ForwardProxy when we established a NodeConnection and ensure we don't run into any issues.

Issues Fixed

Tasks

  1. 1. Change getConnectionToNode to match ObjectMap
  2. 2. Re-run NodeManager tests
  3. 3. Remove ForwardProxy.openConnection call from NodeConnection.start
  4. 4. Re-run NodeManager + NodeConnecton tests
  5. 5. Update ObjectMap diagram with new structure

Final checklist

  • Domain specific tests
  • Full tests
  • Updated inline-comment documentation
  • Lint fixed
  • Squash and rebased
  • Sanity check the final build

@joshuakarp
Copy link
Contributor Author

Changed getConnectionToNode over. NodeManager tests still seem to work:

[nix-shell:~/Documents/MatrixAI/js-polykey]$ npm test -- tests/nodes/NodeManager.test.ts  

> @matrixai/[email protected] test /home/josh/Documents/MatrixAI/js-polykey
> jest "tests/nodes/NodeManager.test.ts"

Determining test suites to run...
GLOBAL SETUP
WARN:Connection 127.0.0.1:44997:Connection Error: Error: This socket has been ended by the other party
WARN:Connection 0.0.0.0:35857:Connection Error: Error [ERR_STREAM_WRITE_AFTER_END]: write after end
WARN:Connection 127.0.0.1:51835:Connection Error: Error: This socket has been ended by the other party
WARN:Connection 0.0.0.0:57618:Connection Error: Error [ERR_STREAM_WRITE_AFTER_END]: write after end
WARN:Connection 127.0.0.1:35156:Connection Error: Error: This socket has been ended by the other party
WARN:Connection 0.0.0.0:40037:Connection Error: Error [ERR_STREAM_WRITE_AFTER_END]: write after end
WARN:Connection 0.0.0.0:35215:Connection Error: ErrorConnectionTimeout
WARN:Connection 0.0.0.0:33078:Connection Error: Error [ERR_STREAM_WRITE_AFTER_END]: write after end
 PASS  tests/nodes/NodeManager.test.ts (157.788 s)
  NodeManager
    ✓ pings node (83164 ms)
    ✓ finds node (local) (3317 ms)
    ✓ finds node (contacts remote node) (7497 ms)
    ✓ cannot find node (contacts remote node) (28639 ms)
    ✓ knows node (true and false case) (3445 ms)
    getConnectionToNode
      ✓ creates new connection to node (5553 ms)
      ✓ gets existing connection to node (5300 ms)
      ✓ concurrent connection creation to same target results in 1 connection (5504 ms)
    Cross signing claims
      ✓ can successfully cross sign a claim (4256 ms)

Test Suites: 1 passed, 1 total
Tests:       9 passed, 9 total
Snapshots:   0 total
Time:        157.843 s, estimated 160 s
Ran all test suites matching /tests\/nodes\/NodeManager.test.ts/i.
GLOBAL TEARDOWN

However, the warnings:

WARN:Connection 127.0.0.1:44997:Connection Error: Error: This socket has been ended by the other party
WARN:Connection 0.0.0.0:35857:Connection Error: Error [ERR_STREAM_WRITE_AFTER_END]: write after end

These are new to me - I don't remember seeing these before. I also ran the tests on the commit before my changes, and the warnings persisted at that commit too.

Anyway, it just means that the warnings weren't from these changes.

@joshuakarp
Copy link
Contributor Author

So after removing ForwardProxy.openConnection, I'm getting some odd ECONNREFUSED errors, exclusively with one specific test:

[nix-shell:~/Documents/MatrixAI/js-polykey]$ npm test -- tests/nodes/NodeManager.test.ts 

> @matrixai/[email protected] test /home/josh/Documents/MatrixAI/js-polykey
> jest "tests/nodes/NodeManager.test.ts"

Determining test suites to run...
GLOBAL SETUP
WARN:Connection 0.0.0.0:48000:Connection Error: ErrorConnectionTimeout
ERROR:NodeManagerTest:Failed CONNECT to 127.0.0.2:22222 - ErrorConnectionStartTimeout
  console.error
    Failed to connect to 127.0.0.2:22222/?nodeId=vi3et1hrpv2m2lrplcm7cu913kr45v51cak54vm68anlbvuf83ra0 through proxy :::45611 with status 400

      at Object.<anonymous>.exports.log (node_modules/@grpc/grpc-js/src/logging.ts:57:13)
      at ClientRequest.<anonymous> (node_modules/@grpc/grpc-js/src/http_proxy.ts:269:9)

ERROR:NodeManagerTest:Failed CONNECT to 127.0.0.2:22222 - ErrorConnectionStartTimeout
  console.error
    Failed to connect to 127.0.0.2:22222/?nodeId=vi3et1hrpv2m2lrplcm7cu913kr45v51cak54vm68anlbvuf83ra0 through proxy :::45611 with status 400

      at Object.<anonymous>.exports.log (node_modules/@grpc/grpc-js/src/logging.ts:57:13)
      at ClientRequest.<anonymous> (node_modules/@grpc/grpc-js/src/http_proxy.ts:269:9)

ERROR:NodeManagerTest:Failed CONNECT to 127.0.0.2:22222 - ErrorConnectionStartTimeout
  console.error
    Failed to connect to 127.0.0.2:22222/?nodeId=vi3et1hrpv2m2lrplcm7cu913kr45v51cak54vm68anlbvuf83ra0 through proxy :::45611 with status 400

      at Object.<anonymous>.exports.log (node_modules/@grpc/grpc-js/src/logging.ts:57:13)
      at ClientRequest.<anonymous> (node_modules/@grpc/grpc-js/src/http_proxy.ts:269:9)

  console.error
    Failed to connect to proxy :::45611 with error connect ECONNREFUSED :::45611

      at Object.<anonymous>.exports.log (node_modules/@grpc/grpc-js/src/logging.ts:57:13)
      at ClientRequest.<anonymous> (node_modules/@grpc/grpc-js/src/http_proxy.ts:283:7)

  console.error
    Failed to connect to proxy :::45611 with error connect ECONNREFUSED :::45611

      at Object.<anonymous>.exports.log (node_modules/@grpc/grpc-js/src/logging.ts:57:13)
      at ClientRequest.<anonymous> (node_modules/@grpc/grpc-js/src/http_proxy.ts:283:7)

  console.error
    Failed to connect to proxy :::45611 with error connect ECONNREFUSED :::45611

      at Object.<anonymous>.exports.log (node_modules/@grpc/grpc-js/src/logging.ts:57:13)
      at ClientRequest.<anonymous> (node_modules/@grpc/grpc-js/src/http_proxy.ts:283:7)

 FAIL  tests/nodes/NodeManager.test.ts (196.353 s)
  NodeManager
    ✓ pings node (82516 ms)
    ✓ finds node (local) (2936 ms)
    ✓ finds node (contacts remote node) (6900 ms)
    ✕ cannot find node (contacts remote node) (65863 ms)
    ✓ knows node (true and false case) (3778 ms)
    getConnectionToNode
      ✓ creates new connection to node (5532 ms)
      ✓ gets existing connection to node (5486 ms)
      ✓ concurrent connection creation to same target results in 1 connection (5798 ms)
    Cross signing claims
      ✓ can successfully cross sign a claim (4617 ms)

  ● NodeManager › cannot find node (contacts remote node)

    : Timeout - Async callback was not invoked within the 50000 ms timeout specified by jest.setTimeout.Timeout - Async callback was not invoked within the 50000 ms timeout specified by jest.setTimeout.Error:

      289 |     global.polykeyStartupTimeout,
      290 |   );
    > 291 |   test(
          |   ^
      292 |     'cannot find node (contacts remote node)',
      293 |     async () => {
      294 |       // Case 3: node exhausts all contacts and cannot find node

      at new Spec (node_modules/jest-jasmine2/build/jasmine/Spec.js:116:22)
      at Suite.<anonymous> (tests/nodes/NodeManager.test.ts:291:3)

Test Suites: 1 failed, 1 total
Tests:       1 failed, 8 passed, 9 total
Snapshots:   0 total
Time:        196.402 s
Ran all test suites matching /tests\/nodes\/NodeManager.test.ts/i.
GLOBAL TEARDOWN
Jest did not exit one second after the test run has completed.

This usually means that there are asynchronous operations that weren't stopped in your tests. Consider running Jest with `--detectOpenHandles` to troubleshoot this issue.
  console.error
    Failed to connect to proxy :::45611 with error connect ECONNREFUSED :::45611

      at Object.<anonymous>.exports.log (node_modules/@grpc/grpc-js/src/logging.ts:57:13)
      at ClientRequest.<anonymous> (node_modules/@grpc/grpc-js/src/http_proxy.ts:283:7)

  console.error
    Failed to connect to proxy :::45611 with error connect ECONNREFUSED :::45611

      at Object.<anonymous>.exports.log (node_modules/@grpc/grpc-js/src/logging.ts:57:13)
      at ClientRequest.<anonymous> (node_modules/@grpc/grpc-js/src/http_proxy.ts:283:7)

^C


@joshuakarp
Copy link
Contributor Author

Rebased on master. Tests all passing after the rebase (reverted the ForwardProxy changes from previous comment to make sure that it was all fine):

[nix-shell:~/Documents/MatrixAI/js-polykey]$ npm test -- tests/nodes

> @matrixai/[email protected] test /home/josh/Documents/MatrixAI/js-polykey
> jest "tests/nodes"

Determining test suites to run...
GLOBAL SETUP
 PASS  tests/nodes/utils.test.ts (6.376 s)
  Nodes utils
    ✓ basic distance calculation (2 ms)
    ✓ calculates correct first bucket (bucket 0) (2 ms)
    ✓ calculates correct arbitrary bucket (bucket 63) (1 ms)
    ✓ calculates correct last bucket (bucket 255) (1 ms)
    ✓ testing type guard. (1 ms)

WARN:Connection 127.0.0.1:57351:Connection Error: Error: This socket has been ended by the other party
WARN:Connection 0.0.0.0:39384:Connection Error: Error [ERR_STREAM_WRITE_AFTER_END]: write after end
 PASS  tests/nodes/NodeGraph.test.ts (26.738 s)
  NodeGraph
    ✓ finds correct node address (21 ms)
    ✓ unable to find node address (8 ms)
    ✓ adds a single node into a bucket (7 ms)
    ✓ adds multiple nodes into the same bucket (27 ms)
    ✓ adds a single node into different buckets (15 ms)
    ✓ deletes a single node (and removes bucket) (16 ms)
    ✓ deletes a single node (and retains remainder of bucket) (32 ms)
    ✓ enforces k-bucket size, removing least active node when a new node is discovered (181 ms)
    ✓ retrieves all buckets (in expected lexicographic order) (36 ms)
    ✓ refreshes buckets (3677 ms)
    ✓ finds a single closest node (4 ms)
    ✓ finds 3 closest nodes (15 ms)
    ✓ finds the 20 closest nodes (119 ms)
    ✓ updates node (7 ms)

WARN:Connection 127.0.0.1:57581:Connection Error: Error: This socket has been ended by the other party
WARN:Connection 0.0.0.0:48997:Connection Error: Error [ERR_STREAM_WRITE_AFTER_END]: write after end
 PASS  tests/nodes/NodeConnection.test.ts (31.169 s)
  NodeConnection
    ✓ connects to its target (via direct connection) (3741 ms)
    ✓ receives 20 closest local nodes from connected target (2907 ms)
    ✓ sends hole punch message to connected target (expected to be broker, to relay further) (2849 ms)
    ○ skipped scans the servers vaults

WARN:Connection 127.0.0.1:41799:Connection Error: Error: This socket has been ended by the other party
WARN:Connection 0.0.0.0:34610:Connection Error: Error [ERR_STREAM_WRITE_AFTER_END]: write after end
WARN:Connection 0.0.0.0:59077:Connection Error: ErrorConnectionTimeout
 PASS  tests/nodes/NodeManager.test.ts (175.583 s)
  NodeManager
    ✓ pings node (82191 ms)
    ✓ finds node (local) (3145 ms)
    ✓ finds node (contacts remote node) (7523 ms)
    ✓ cannot find node (contacts remote node) (28335 ms)
    ✓ knows node (true and false case) (2979 ms)
    getConnectionToNode
      ✓ creates new connection to node (6180 ms)
      ✓ gets existing connection to node (5501 ms)
      ✓ concurrent connection creation to same target results in 1 connection (5233 ms)
    Cross signing claims
      ✓ can successfully cross sign a claim (4054 ms)

Test Suites: 4 passed, 4 total
Tests:       1 skipped, 31 passed, 32 total
Snapshots:   0 total
Time:        175.985 s
Ran all test suites matching /tests\/nodes/i.
GLOBAL TEARDOWN

@joshuakarp
Copy link
Contributor Author

The prior issues here #284 (comment) are all related to attempting to connect to an "offline" node (or rather, an IP:port that can't be connected to for some reason).

It wasn't immediately clear why the errors were arising in only this test, so in the process of fixing this, I'm also adding an unable to create new connection to offline node test to test the case when we attempt to connect to an offline node.

@joshuakarp
Copy link
Contributor Author

Some logging output:

[nix-shell:~/Documents/MatrixAI/js-polykey]$ npm test -- tests/nodes/NodeManager.test.ts 

> @matrixai/[email protected] test /home/josh/Documents/MatrixAI/js-polykey
> jest "tests/nodes/NodeManager.test.ts"

Determining test suites to run...
GLOBAL SETUP
INFO:NodeManagerTest:Creating Forward Proxy
INFO:NodeManagerTest:Created Forward Proxy
INFO:NodeManagerTest:Creating Reverse Proxy
INFO:NodeManagerTest:Created Reverse Proxy
INFO:NodeManagerTest:Setting umask to 077
INFO:NodeManagerTest:Setting node path to /run/user/1000/polykey-test-remote-yKSsq8
INFO:NodeManagerTest:Failed to open version file: ENOENT: no such file or directory, open '/run/user/1000/polykey-test-remote-yKSsq8/versionFile'
INFO:NodeManagerTest:Creating Forward Proxy
INFO:NodeManagerTest:Created Forward Proxy
INFO:NodeManagerTest:Creating Reverse Proxy
INFO:NodeManagerTest:Created Reverse Proxy
INFO:KeyManager:Creating Key Manager
INFO:KeyManager:Setting keys path to /run/user/1000/polykey-test-remote-yKSsq8/keys
INFO:KeyManager:Checking /run/user/1000/polykey-test-remote-yKSsq8/keys/root.pub and /run/user/1000/polykey-test-remote-yKSsq8/keys/root.key
INFO:KeyManager:Generating root key pair
INFO:KeyManager:Writing /run/user/1000/polykey-test-remote-yKSsq8/keys/root.pub and /run/user/1000/polykey-test-remote-yKSsq8/keys/root.key
INFO:KeyManager:Checking /run/user/1000/polykey-test-remote-yKSsq8/keys/root.crt
INFO:KeyManager:Generating root certificate
INFO:KeyManager:Writing /run/user/1000/polykey-test-remote-yKSsq8/keys/root.crt
INFO:KeyManager:Checking /run/user/1000/polykey-test-remote-yKSsq8/keys/db.key
INFO:KeyManager:Generating keys db key
INFO:KeyManager:Writing /run/user/1000/polykey-test-remote-yKSsq8/keys/db.key
INFO:KeyManager:Checking /run/user/1000/polykey-test-remote-yKSsq8/keys/vault.key
INFO:KeyManager:Generating keys db key
INFO:KeyManager:Writing /run/user/1000/polykey-test-remote-yKSsq8/keys/vault.key
INFO:KeyManager:Created Key Manager
INFO:NodeManagerTest:Starting DB
INFO:NodeManagerTest:Setting DB path to /run/user/1000/polykey-test-remote-yKSsq8/db
INFO:NodeManagerTest:Started DB
INFO:Sigchain:Creating Sigchain
INFO:Sigchain:Created Sigchain
INFO:ACL:Starting ACL
INFO:ACL:Started ACL
INFO:GestaltGraph:Starting Gestalt Graph
INFO:GestaltGraph:Started Gestalts Graph
INFO:NodeManager:Creating Node Manager
INFO:NodeManager:Created Node Manager
INFO:VaultManager:Creating Vault Manager
INFO:DB:Starting DB
INFO:DB:Setting DB path to /run/user/1000/polykey-test-remote-yKSsq8/vaults
INFO:DB:Started DB
INFO:VaultManager:Starting EncryptedFS
INFO:VaultManager:Started EncryptedFS
INFO:VaultManager:Created Vault Manager
INFO:IdentitiesManager:Starting Identities Manager
INFO:IdentitiesManager:Started Identities Manager
INFO:Discovery:Creating Discovery
INFO:Discovery:Created Discovery
INFO:NotificationsManager:Starting Notifications Manager
INFO:NotificationsManager:Started Notifications Manager
INFO:NodeManagerTest:Starting SessionManager
INFO:NodeManagerTest:Putting keypair into DB
INFO:NodeManagerTest:Started SessionManager
INFO:ClientServer:Creating GRPC Server
INFO:ClientServer:Created GRPC Server
INFO:AgentServer:Creating GRPC Server
INFO:AgentServer:Created GRPC Server
INFO:NodeManagerTest:Starting Polykey
INFO:NodeManager:Starting Node Manager
INFO:NodeManager:Starting Node Graph
INFO:NodeManager:Started Node Graph
INFO:NodeManager:Started Node Manager
INFO:ClientServer:Starting GRPC Server on 127.0.0.1:0
INFO:ClientServer:Started GRPC Server on 127.0.0.1:43491
INFO:AgentServer:Starting GRPC Server on 127.0.0.1:0
INFO:AgentServer:Started GRPC Server on 127.0.0.1:36259
INFO:NodeManagerTest:Starting Forward Proxy from [::]:0 to 0.0.0.0:0
INFO:NodeManagerTest:Started Forward Proxy from [::]:42231 to 0.0.0.0:40988
INFO:NodeManagerTest:Starting Reverse Proxy from 0.0.0.0:0 to 127.0.0.1:36259
INFO:NodeManagerTest:Started Reverse Proxy from 0.0.0.0:37105 to 127.0.0.1:36259
INFO:Lockfile:Writing lockfile to /run/user/1000/polykey-test-remote-yKSsq8/agent-lock.json
INFO:Lockfile:Writing lockfile to /run/user/1000/polykey-test-remote-yKSsq8/agent-lock.json
INFO:Lockfile:Writing lockfile to /run/user/1000/polykey-test-remote-yKSsq8/agent-lock.json
INFO:Lockfile:Writing lockfile to /run/user/1000/polykey-test-remote-yKSsq8/agent-lock.json
INFO:Lockfile:Writing lockfile to /run/user/1000/polykey-test-remote-yKSsq8/agent-lock.json
INFO:NodeManagerTest:Started Polykey
INFO:NodeManagerTest:Creating Key Manager
INFO:NodeManagerTest:Setting keys path to /run/user/1000/polykey-test-hChRh8/keys
INFO:NodeManagerTest:Checking /run/user/1000/polykey-test-hChRh8/keys/root.pub and /run/user/1000/polykey-test-hChRh8/keys/root.key
INFO:NodeManagerTest:Generating root key pair
INFO:NodeManagerTest:Writing /run/user/1000/polykey-test-hChRh8/keys/root.pub and /run/user/1000/polykey-test-hChRh8/keys/root.key
INFO:NodeManagerTest:Checking /run/user/1000/polykey-test-hChRh8/keys/root.crt
INFO:NodeManagerTest:Generating root certificate
INFO:NodeManagerTest:Writing /run/user/1000/polykey-test-hChRh8/keys/root.crt
INFO:NodeManagerTest:Checking /run/user/1000/polykey-test-hChRh8/keys/db.key
INFO:NodeManagerTest:Generating keys db key
INFO:NodeManagerTest:Writing /run/user/1000/polykey-test-hChRh8/keys/db.key
INFO:NodeManagerTest:Checking /run/user/1000/polykey-test-hChRh8/keys/vault.key
INFO:NodeManagerTest:Generating keys db key
INFO:NodeManagerTest:Writing /run/user/1000/polykey-test-hChRh8/keys/vault.key
INFO:NodeManagerTest:Created Key Manager
INFO:NodeManagerTest:Starting Forward Proxy from [::]:0 to 0.0.0.0:0
INFO:NodeManagerTest:Started Forward Proxy from [::]:43265 to 0.0.0.0:39233
INFO:NodeManagerTest:Starting Reverse Proxy from 0.0.0.0:0 to [::1]:1
INFO:NodeManagerTest:Started Reverse Proxy from 0.0.0.0:56941 to [::1]:1
INFO:NodeManagerTest:Starting DB
INFO:NodeManagerTest:Setting DB path to /run/user/1000/polykey-test-hChRh8/db
INFO:NodeManagerTest:Started DB
INFO:NodeManagerTest:Creating Sigchain
INFO:NodeManagerTest:Created Sigchain
INFO:NodeManagerTest:Creating Node Manager
INFO:NodeManagerTest:Created Node Manager
INFO:NodeManagerTest:Starting Node Manager
INFO:NodeManagerTest:Starting Node Graph
INFO:NodeManagerTest:Started Node Graph
INFO:NodeManagerTest:Started Node Manager
INFO:NodeManagerTest:Creating GRPCClientAgent
INFO:NodeManagerTest:Created GRPCClientAgent
INFO:NodeManagerTest:Creating NodeConnection
INFO:NodeManagerTest:Created NodeConnection
INFO:NodeManagerTest:Starting NodeConnection
INFO:NodeManagerTest:Starting GRPC Client connecting to 125.0.0.1:55555
INFO:NodeManagerTest:Handling CONNECT to 125.0.0.1:55555
INFO:Connection 125.0.0.1:55555:Starting Connection Forward
INFO:Connection 125.0.0.1:55555:before race
INFO:NodeManagerTest:Stopping Polykey
INFO:ClientServer:Stopping GRPC Server
INFO:ClientServer:Stopped GRPC Server
INFO:AgentServer:Stopping GRPC Server
INFO:AgentServer:Stopped GRPC Server
INFO:Lockfile:Deleting lockfile from /run/user/1000/polykey-test-remote-yKSsq8/agent-lock.json
INFO:NodeManager:Stopping Node Manager
INFO:NodeManager:Stopping Node Graph
INFO:NodeManager:Stopped Node Graph
INFO:NodeManager:Stopped Node Manager
INFO:NodeManagerTest:Stopping Reverse Proxy
INFO:Connection 125.0.0.1:55555:after race
INFO:Connection 125.0.0.1:55555:Stopping Connection Forward
INFO:Connection 125.0.0.1:55555:Stopped Connection Forward
INFO:Connection 125.0.0.1:55555:catching e at endErrorConnectionStartTimeout
INFO:NodeManagerTest:caught e in forwardProxy ErrorConnectionStartTimeout
INFO:NodeManagerTest:e instanceof ErrorConnection
ERROR:NodeManagerTest:Failed CONNECT to 125.0.0.1:55555 - ErrorConnectionStartTimeout
INFO:NodeManagerTest:Handling CONNECT to 125.0.0.1:55555
INFO:Connection 125.0.0.1:55555:Starting Connection Forward
INFO:Connection 125.0.0.1:55555:before race
  console.error
    Failed to connect to 125.0.0.1:55555/?nodeId=vi3et1hrpv2m2lrplcm7cu913kr45v51cak54vm68anlbvuf83ra0 through proxy :::43265 with status 400

      at Object.<anonymous>.exports.log (node_modules/@grpc/grpc-js/src/logging.ts:57:13)
      at ClientRequest.<anonymous> (node_modules/@grpc/grpc-js/src/http_proxy.ts:269:9)

INFO:NodeManagerTest:Stopped Reverse Proxy
INFO:NodeManagerTest:Stopping Forward Proxy Server
INFO:NodeManagerTest:Stopped Forward Proxy Server
INFO:NodeManagerTest:Stopping DB
INFO:NodeManagerTest:Stopped DB
INFO:NodeManagerTest:Stopped Polykey
INFO:NodeManagerTest:Stopping Node Manager
INFO:NodeManagerTest:Stopping Node Graph
INFO:NodeManagerTest:Stopped Node Graph
INFO:NodeManagerTest:Stopped Node Manager
INFO:NodeManagerTest:Destroyed Sigchain
INFO:NodeManagerTest:Stopping DB
INFO:NodeManagerTest:Stopped DB
INFO:NodeManagerTest:Destroying DB
INFO:NodeManagerTest:Destroyed DB
INFO:NodeManagerTest:Destroyed Key Manager
INFO:NodeManagerTest:Stopping Forward Proxy Server
INFO:Connection 125.0.0.1:55555:after race
INFO:Connection 125.0.0.1:55555:Stopping Connection Forward
INFO:Connection 125.0.0.1:55555:Stopped Connection Forward
INFO:Connection 125.0.0.1:55555:catching e at endErrorConnectionStartTimeout
INFO:NodeManagerTest:caught e in forwardProxy ErrorConnectionStartTimeout
INFO:NodeManagerTest:e instanceof ErrorConnection
ERROR:NodeManagerTest:Failed CONNECT to 125.0.0.1:55555 - ErrorConnectionStartTimeout
  console.error
    Failed to connect to 125.0.0.1:55555/?nodeId=vi3et1hrpv2m2lrplcm7cu913kr45v51cak54vm68anlbvuf83ra0 through proxy :::43265 with status 400

      at Object.<anonymous>.exports.log (node_modules/@grpc/grpc-js/src/logging.ts:57:13)
      at ClientRequest.<anonymous> (node_modules/@grpc/grpc-js/src/http_proxy.ts:269:9)

  console.error
    Failed to connect to proxy :::43265 with error connect ECONNREFUSED :::43265

      at Object.<anonymous>.exports.log (node_modules/@grpc/grpc-js/src/logging.ts:57:13)
      at ClientRequest.<anonymous> (node_modules/@grpc/grpc-js/src/http_proxy.ts:283:7)

INFO:NodeManagerTest:Stopped Forward Proxy Server
INFO:NodeManagerTest:Stopping Reverse Proxy
INFO:NodeManagerTest:Destroying Polykey
INFO:AgentServer:Destroyed GRPC server
INFO:ClientServer:Destroyed GRPC server
INFO:NodeManagerTest:Destroyed SessionManager
INFO:NotificationsManager:Destroyed Notifications Manager
INFO:Discovery:Destroyed Discovery
INFO:IdentitiesManager:Destroyed Identities Manager
INFO:VaultManager:Destroying Vault Manager
INFO:VaultManager:Stopping EncryptedFS
INFO:DB:Stopping DB
INFO:DB:Stopped DB
INFO:VaultManager:Stopped EncryptedFS
INFO:VaultManager:Destroyed Vault Manager
INFO:NodeManager:Destroyed Node Manager
INFO:GestaltGraph:Destroyed Gestalt Graph
INFO:ACL:Destroyed ACL
INFO:Sigchain:Destroyed Sigchain
INFO:NodeManagerTest:Destroyed Reverse Proxy
INFO:NodeManagerTest:Destroyed Forward Proxy Server
INFO:KeyManager:Destroyed Key Manager
INFO:NodeManagerTest:Destroyed Polykey
INFO:NodeManagerTest:Destroyed Node Manager
INFO:NodeManagerTest:Destroyed Forward Proxy Server
INFO:NodeManagerTest:Destroyed Reverse Proxy
 FAIL  tests/nodes/NodeManager.test.ts (49.97 s)
  NodeManager
    ○ skipped pings node
    ○ skipped finds node (local)
    ○ skipped finds node (contacts remote node)
    ○ skipped cannot find node (contacts remote node)
    ○ skipped knows node (true and false case)
    getConnectionToNode
      ✕ unable to create new connection to offline node (43020 ms)
      ○ skipped creates new connection to node
      ○ skipped gets existing connection to node
      ○ skipped concurrent connection creation to same target results in 1 connection

  ● NodeManager › getConnectionToNode › unable to create new connection to offline node

    : Timeout - Async callback was not invoked within the 20000 ms timeout specified by jest.setTimeout.Timeout - Async callback was not invoked within the 20000 ms timeout specified by jest.setTimeout.Error:

      206 |       expect(finalConnLock?.lock.isLocked()).toBeFalsy();
      207 |     });
    > 208 |     test.only('unable to create new connection to offline node', async () => {
          |          ^
      209 |       // Add the dummy node
      210 |       await nodeManager.setNode(
      211 |         dummyNode,

      at new Spec (node_modules/jest-jasmine2/build/jasmine/Spec.js:116:22)
      at Suite.<anonymous> (tests/nodes/NodeManager.test.ts:208:10)

  ● NodeManager › getConnectionToNode › unable to create new connection to offline node

    Timeout - Async callback was not invoked within the 20000 ms timeout specified by jest.setTimeout.Error: Timeout - Async callback was not invoked within the 20000 ms timeout specified by jest.setTimeout.

      at mapper (node_modules/jest-jasmine2/build/queueRunner.js:27:45)

Test Suites: 1 failed, 1 total
Tests:       1 failed, 8 skipped, 9 total
Snapshots:   0 total
Time:        50.009 s, estimated 57 s
Ran all test suites matching /tests\/nodes\/NodeManager.test.ts/i.
GLOBAL TEARDOWN
INFO:NodeManagerTest:Stopped Reverse Proxy
Jest did not exit one second after the test run has completed.

This usually means that there are asynchronous operations that weren't stopped in your tests. Consider running Jest with `--detectOpenHandles` to troubleshoot this issue.
  console.error
    Failed to connect to proxy :::43265 with error connect ECONNREFUSED :::43265

      at Object.<anonymous>.exports.log (node_modules/@grpc/grpc-js/src/logging.ts:57:13)
      at ClientRequest.<anonymous> (node_modules/@grpc/grpc-js/src/http_proxy.ts:283:7)

  console.error
    Failed to connect to proxy :::43265 with error connect ECONNREFUSED :::43265

      at Object.<anonymous>.exports.log (node_modules/@grpc/grpc-js/src/logging.ts:57:13)
      at ClientRequest.<anonymous> (node_modules/@grpc/grpc-js/src/http_proxy.ts:283:7)

  console.error
    Failed to connect to proxy :::43265 with error connect ECONNREFUSED :::43265

      at Object.<anonymous>.exports.log (node_modules/@grpc/grpc-js/src/logging.ts:57:13)
      at ClientRequest.<anonymous> (node_modules/@grpc/grpc-js/src/http_proxy.ts:283:7)

  console.error
    Failed to connect to proxy :::43265 with error connect ECONNREFUSED :::43265

      at Object.<anonymous>.exports.log (node_modules/@grpc/grpc-js/src/logging.ts:57:13)
      at ClientRequest.<anonymous> (node_modules/@grpc/grpc-js/src/http_proxy.ts:283:7)

  console.error
    Failed to connect to proxy :::43265 with error connect ECONNREFUSED :::43265

      at Object.<anonymous>.exports.log (node_modules/@grpc/grpc-js/src/logging.ts:57:13)
      at ClientRequest.<anonymous> (node_modules/@grpc/grpc-js/src/http_proxy.ts:283:7)


A few things I've realised:

  • An ErrorConnectionStartTimeout exception is being thrown from ConnectionForward.start. This is expected, as the target can't be connected to.
  • This thrown exception bubbles up to the handleConnect handler in ForwardProxy. From here, it reaches:
// ForwardProxy
  protected handleConnect = async (
  ...
      try {
        await this.connect(
          nodeId,
          ingressHost,
          ingressPort,
          clientSocket,
          timer,
        );
      } catch (e) {
        this.logger.info('caught e in forwardProxy ' + e.toString());
        if (e instanceof networkErrors.ErrorConnection) {
          this.logger.info('e instanceof ErrorConnection');
          if (!clientSocket.destroyed) {
            // Reaches here, destroys the socket, and returns
            await clientSocketEnd('HTTP/1.1 400 Bad Request\r\n' + '\r\n');
            clientSocket.destroy(e);
          }
          return;
        }
  • i.e. the exception is handled here, and not bubbled up any further
  • I can see from the logger output that the handleConnectError in handleConnect displays an Failed CONNECT to ... message, but again, no exception bubbled up
  • Now, once again, this goes back to our discussions about how we treat the network domain as something entirely separate to the rest of Polykey
  • I don't think I'm completely understanding it though. Given that we don't bubble an exception up from client.start, how am I able to know that this connection error has occurred?

@joshuakarp
Copy link
Contributor Author

@CMCDragonkai so the more targeted question... how does an error occurring in the networking domain (in this case, from the ForwardProxy attempting to establish a connection - throws an ErrorConnectionStartTimeout on ConnectionForward.start) propagate up to GRPCClient.start?

@CMCDragonkai
Copy link
Member

Well the exception cannot propagate because it's going over the network. So GRPC client will likely error out with its own exception.

@joshuakarp
Copy link
Contributor Author

Okay. Will take a look into client.start.

@joshuakarp
Copy link
Contributor Author

I'm just running a test.ts file now, so that I don't deal with any timeout problems from the jest testing.

import type { Host, Port } from './src/network/types';
import Logger, { LogLevel, StreamHandler } from '@matrixai/logger';
import * as testUtils from './tests/utils';
import { makeNodeId } from './src/nodes/utils';

async function main() {
  const clientLogger = new Logger('ClientLogger', LogLevel.DEBUG, [
    new StreamHandler(),
  ]);
  const client = await testUtils.setupRemoteKeynode({ 
    logger: clientLogger,
  });

  const dummyNode = makeNodeId(
    'vi3et1hrpv2m2lrplcm7cu913kr45v51cak54vm68anlbvuf83ra0',
  );
  await client.nodes.setNode(
    dummyNode,
    {
      ip: '125.0.0.1' as Host,
      port: 55555 as Port,
    }
  );

  await client.nodes.getConnectionToNode(dummyNode);

  await testUtils.cleanupRemoteKeynode(client);
}

main();

And logging output:

[nix-shell:~/Documents/MatrixAI/js-polykey]$ npm run ts-node test.ts

> @matrixai/[email protected] ts-node /home/josh/Documents/MatrixAI/js-polykey
> ts-node -r tsconfig-paths/register "test.ts"

INFO:ClientLogger:Setting umask to 077
INFO:ClientLogger:Setting node path to /run/user/1000/polykey-test-remote-u2gPyR
INFO:ClientLogger:Failed to open version file: ENOENT: no such file or directory, open '/run/user/1000/polykey-test-remote-u2gPyR/versionFile'
INFO:ClientLogger:Creating Forward Proxy
INFO:ClientLogger:Created Forward Proxy
INFO:ClientLogger:Creating Reverse Proxy
INFO:ClientLogger:Created Reverse Proxy
INFO:KeyManager:Creating Key Manager
INFO:KeyManager:Setting keys path to /run/user/1000/polykey-test-remote-u2gPyR/keys
INFO:KeyManager:Checking /run/user/1000/polykey-test-remote-u2gPyR/keys/root.pub and /run/user/1000/polykey-test-remote-u2gPyR/keys/root.key
INFO:KeyManager:Generating root key pair
INFO:KeyManager:Writing /run/user/1000/polykey-test-remote-u2gPyR/keys/root.pub and /run/user/1000/polykey-test-remote-u2gPyR/keys/root.key
INFO:KeyManager:Checking /run/user/1000/polykey-test-remote-u2gPyR/keys/root.crt
INFO:KeyManager:Generating root certificate
INFO:KeyManager:Writing /run/user/1000/polykey-test-remote-u2gPyR/keys/root.crt
INFO:KeyManager:Checking /run/user/1000/polykey-test-remote-u2gPyR/keys/db.key
INFO:KeyManager:Generating keys db key
INFO:KeyManager:Writing /run/user/1000/polykey-test-remote-u2gPyR/keys/db.key
INFO:KeyManager:Checking /run/user/1000/polykey-test-remote-u2gPyR/keys/vault.key
INFO:KeyManager:Generating keys db key
INFO:KeyManager:Writing /run/user/1000/polykey-test-remote-u2gPyR/keys/vault.key
INFO:KeyManager:Created Key Manager
INFO:ClientLogger:Starting DB
INFO:ClientLogger:Setting DB path to /run/user/1000/polykey-test-remote-u2gPyR/db
INFO:ClientLogger:Started DB
INFO:Sigchain:Creating Sigchain
INFO:Sigchain:Created Sigchain
INFO:ACL:Starting ACL
INFO:ACL:Started ACL
INFO:GestaltGraph:Starting Gestalt Graph
INFO:GestaltGraph:Started Gestalts Graph
INFO:NodeManager:Creating Node Manager
INFO:NodeManager:Created Node Manager
INFO:VaultManager:Creating Vault Manager
INFO:DB:Starting DB
INFO:DB:Setting DB path to /run/user/1000/polykey-test-remote-u2gPyR/vaults
INFO:DB:Started DB
INFO:VaultManager:Starting EncryptedFS
INFO:VaultManager:Started EncryptedFS
INFO:VaultManager:Created Vault Manager
INFO:IdentitiesManager:Starting Identities Manager
INFO:IdentitiesManager:Started Identities Manager
INFO:Discovery:Creating Discovery
INFO:Discovery:Created Discovery
INFO:NotificationsManager:Starting Notifications Manager
INFO:NotificationsManager:Started Notifications Manager
INFO:ClientLogger:Starting SessionManager
INFO:ClientLogger:Putting keypair into DB
INFO:ClientLogger:Started SessionManager
INFO:ClientServer:Creating GRPC Server
INFO:ClientServer:Created GRPC Server
INFO:AgentServer:Creating GRPC Server
INFO:AgentServer:Created GRPC Server
INFO:ClientLogger:Starting Polykey
INFO:NodeManager:Starting Node Manager
INFO:NodeManager:Starting Node Graph
INFO:NodeManager:Started Node Graph
INFO:NodeManager:Started Node Manager
INFO:ClientServer:Starting GRPC Server on 127.0.0.1:0
INFO:ClientServer:Started GRPC Server on 127.0.0.1:38283
INFO:AgentServer:Starting GRPC Server on 127.0.0.1:0
INFO:AgentServer:Started GRPC Server on 127.0.0.1:46237
INFO:ClientLogger:Starting Forward Proxy from [::]:0 to 0.0.0.0:0
INFO:ClientLogger:Started Forward Proxy from [::]:43209 to 0.0.0.0:53419
INFO:ClientLogger:Starting Reverse Proxy from 0.0.0.0:0 to 127.0.0.1:46237
INFO:ClientLogger:Started Reverse Proxy from 0.0.0.0:39264 to 127.0.0.1:46237
INFO:Lockfile:Writing lockfile to /run/user/1000/polykey-test-remote-u2gPyR/agent-lock.json
INFO:Lockfile:Writing lockfile to /run/user/1000/polykey-test-remote-u2gPyR/agent-lock.json
INFO:Lockfile:Writing lockfile to /run/user/1000/polykey-test-remote-u2gPyR/agent-lock.json
INFO:Lockfile:Writing lockfile to /run/user/1000/polykey-test-remote-u2gPyR/agent-lock.json
INFO:Lockfile:Writing lockfile to /run/user/1000/polykey-test-remote-u2gPyR/agent-lock.json
INFO:ClientLogger:Started Polykey
INFO:NodeManager:Creating GRPCClientAgent
INFO:NodeManager:Created GRPCClientAgent
INFO:NodeManager:Creating NodeConnection
INFO:NodeManager:Created NodeConnection
INFO:NodeManager:Starting NodeConnection
INFO:NodeManager:Starting GRPC Client connecting to 125.0.0.1:55555
INFO:NodeManager:Timeout before: Infinity
INFO:NodeManager:after timeout+=: Infinity
INFO:NodeManager:waiting for ready
INFO:ClientLogger:Handling CONNECT to 125.0.0.1:55555
INFO:Connection 125.0.0.1:55555:Starting Connection Forward
INFO:Connection 125.0.0.1:55555:before race
INFO:Connection 125.0.0.1:55555:after race
INFO:Connection 125.0.0.1:55555:Stopping Connection Forward
INFO:Connection 125.0.0.1:55555:Stopped Connection Forward
INFO:Connection 125.0.0.1:55555:catching e at endErrorConnectionStartTimeout
INFO:ClientLogger:caught e in forwardProxy ErrorConnectionStartTimeout
INFO:ClientLogger:e instanceof ErrorConnection
ERROR:ClientLogger:Failed CONNECT to 125.0.0.1:55555 - ErrorConnectionStartTimeout
Failed to connect to 125.0.0.1:55555/?nodeId=vi3et1hrpv2m2lrplcm7cu913kr45v51cak54vm68anlbvuf83ra0 through proxy :::43209 with status 400
INFO:ClientLogger:Handling CONNECT to 125.0.0.1:55555
INFO:Connection 125.0.0.1:55555:Starting Connection Forward
INFO:Connection 125.0.0.1:55555:before race
INFO:Connection 125.0.0.1:55555:after race
INFO:Connection 125.0.0.1:55555:Stopping Connection Forward
INFO:Connection 125.0.0.1:55555:Stopped Connection Forward
INFO:Connection 125.0.0.1:55555:catching e at endErrorConnectionStartTimeout
INFO:ClientLogger:caught e in forwardProxy ErrorConnectionStartTimeout
INFO:ClientLogger:e instanceof ErrorConnection
ERROR:ClientLogger:Failed CONNECT to 125.0.0.1:55555 - ErrorConnectionStartTimeout
Failed to connect to 125.0.0.1:55555/?nodeId=vi3et1hrpv2m2lrplcm7cu913kr45v51cak54vm68anlbvuf83ra0 through proxy :::43209 with status 400
INFO:ClientLogger:Handling CONNECT to 125.0.0.1:55555
INFO:Connection 125.0.0.1:55555:Starting Connection Forward
INFO:Connection 125.0.0.1:55555:before race
INFO:Connection 125.0.0.1:55555:after race
INFO:Connection 125.0.0.1:55555:Stopping Connection Forward
INFO:Connection 125.0.0.1:55555:Stopped Connection Forward
INFO:Connection 125.0.0.1:55555:catching e at endErrorConnectionStartTimeout
INFO:ClientLogger:caught e in forwardProxy ErrorConnectionStartTimeout
INFO:ClientLogger:e instanceof ErrorConnection
ERROR:ClientLogger:Failed CONNECT to 125.0.0.1:55555 - ErrorConnectionStartTimeout
Failed to connect to 125.0.0.1:55555/?nodeId=vi3et1hrpv2m2lrplcm7cu913kr45v51cak54vm68anlbvuf83ra0 through proxy :::43209 with status 400
INFO:ClientLogger:Handling CONNECT to 125.0.0.1:55555
INFO:Connection 125.0.0.1:55555:Starting Connection Forward
INFO:Connection 125.0.0.1:55555:before race
INFO:Connection 125.0.0.1:55555:after race
INFO:Connection 125.0.0.1:55555:Stopping Connection Forward
INFO:Connection 125.0.0.1:55555:Stopped Connection Forward
INFO:Connection 125.0.0.1:55555:catching e at endErrorConnectionStartTimeout
INFO:ClientLogger:caught e in forwardProxy ErrorConnectionStartTimeout
INFO:ClientLogger:e instanceof ErrorConnection
ERROR:ClientLogger:Failed CONNECT to 125.0.0.1:55555 - ErrorConnectionStartTimeout
Failed to connect to 125.0.0.1:55555/?nodeId=vi3et1hrpv2m2lrplcm7cu913kr45v51cak54vm68anlbvuf83ra0 through proxy :::43209 with status 400
INFO:ClientLogger:Handling CONNECT to 125.0.0.1:55555
INFO:Connection 125.0.0.1:55555:Starting Connection Forward
INFO:Connection 125.0.0.1:55555:before race
INFO:Connection 125.0.0.1:55555:after race
INFO:Connection 125.0.0.1:55555:Stopping Connection Forward
INFO:Connection 125.0.0.1:55555:Stopped Connection Forward
INFO:Connection 125.0.0.1:55555:catching e at endErrorConnectionStartTimeout
INFO:ClientLogger:caught e in forwardProxy ErrorConnectionStartTimeout
INFO:ClientLogger:e instanceof ErrorConnection
ERROR:ClientLogger:Failed CONNECT to 125.0.0.1:55555 - ErrorConnectionStartTimeout
Failed to connect to 125.0.0.1:55555/?nodeId=vi3et1hrpv2m2lrplcm7cu913kr45v51cak54vm68anlbvuf83ra0 through proxy :::43209 with status 400
INFO:ClientLogger:Handling CONNECT to 125.0.0.1:55555
INFO:Connection 125.0.0.1:55555:Starting Connection Forward
INFO:Connection 125.0.0.1:55555:before race
INFO:Connection 125.0.0.1:55555:after race
INFO:Connection 125.0.0.1:55555:Stopping Connection Forward
INFO:Connection 125.0.0.1:55555:Stopped Connection Forward
INFO:Connection 125.0.0.1:55555:catching e at endErrorConnectionStartTimeout
INFO:ClientLogger:caught e in forwardProxy ErrorConnectionStartTimeout
INFO:ClientLogger:e instanceof ErrorConnection
ERROR:ClientLogger:Failed CONNECT to 125.0.0.1:55555 - ErrorConnectionStartTimeout
Failed to connect to 125.0.0.1:55555/?nodeId=vi3et1hrpv2m2lrplcm7cu913kr45v51cak54vm68anlbvuf83ra0 through proxy :::43209 with status 400
INFO:ClientLogger:Handling CONNECT to 125.0.0.1:55555
INFO:Connection 125.0.0.1:55555:Starting Connection Forward
INFO:Connection 125.0.0.1:55555:before race
INFO:Connection 125.0.0.1:55555:after race
INFO:Connection 125.0.0.1:55555:Stopping Connection Forward
INFO:Connection 125.0.0.1:55555:Stopped Connection Forward
INFO:Connection 125.0.0.1:55555:catching e at endErrorConnectionStartTimeout
INFO:ClientLogger:caught e in forwardProxy ErrorConnectionStartTimeout
INFO:ClientLogger:e instanceof ErrorConnection
ERROR:ClientLogger:Failed CONNECT to 125.0.0.1:55555 - ErrorConnectionStartTimeout
Failed to connect to 125.0.0.1:55555/?nodeId=vi3et1hrpv2m2lrplcm7cu913kr45v51cak54vm68anlbvuf83ra0 through proxy :::43209 with status 400
INFO:ClientLogger:Handling CONNECT to 125.0.0.1:55555
INFO:Connection 125.0.0.1:55555:Starting Connection Forward
INFO:Connection 125.0.0.1:55555:before race
^C

Some observations from this:

On the networking side:

  • the handleConnect seems to repeatedly be called, even after the initial connection request times out. See this repeated set of logger outputs:
INFO:ClientLogger:Handling CONNECT to 125.0.0.1:55555
INFO:Connection 125.0.0.1:55555:Starting Connection Forward
INFO:Connection 125.0.0.1:55555:before race
INFO:Connection 125.0.0.1:55555:after race
INFO:Connection 125.0.0.1:55555:Stopping Connection Forward
INFO:Connection 125.0.0.1:55555:Stopped Connection Forward
INFO:Connection 125.0.0.1:55555:catching e at endErrorConnectionStartTimeout
INFO:ClientLogger:caught e in forwardProxy ErrorConnectionStartTimeout
INFO:ClientLogger:e instanceof ErrorConnection
ERROR:ClientLogger:Failed CONNECT to 125.0.0.1:55555 - ErrorConnectionStartTimeout
Failed to connect to 125.0.0.1:55555/?nodeId=vi3et1hrpv2m2lrplcm7cu913kr45v51cak54vm68anlbvuf83ra0 through proxy :::43209 with status 400
  • I'm assuming that this is expected

On the GRPCClient side:

  • execution gets caught in GRPCClient.start:
  public async start({ ... }) {
    ...
    const waitForReady = promisify(client.waitForReady).bind(client);
    // Add the current unix time because grpc expects the milliseconds since unix epoch
    timeout += Date.now();
    try {
      await waitForReady(timeout);
    } catch (e) {
      throw new grpcErrors.ErrorGRPCClientTimeout();
    }
    ...
  }
  • it reaches the await waitForReady(timeout);, but never moves past this.
  • However, timeout is defaulted to Infinity - I wonder if this should be defaulted to be the same as the connection timeout with respect to the ForwardProxy. Is this an oversight? @CMCDragonkai

@CMCDragonkai
Copy link
Member

CMCDragonkai commented Nov 5, 2021

  1. Refer to the diagram in https://github.com/MatrixAI/js-polykey/wiki/network
  2. The ForwardProxy is performing correctly, it's receiving repeated attempts to CONNECT
  3. The GRPC Client is retrying the CONNECT call over and over
  4. The timeout of infinity is intentional, but its just a default, you can change this in production
  5. Alternatively find an option to control the number of retries that GRPC client attempts
  6. Check the source code of https://github.com/grpc/grpc-node to see how to make that work

@joshuakarp
Copy link
Contributor Author

Curiously, I wanted to see what would happen if we converted the waitForReady back to a callback execution style, instead of using our promisify helper:

    // Add the current unix time because grpc expects the milliseconds since unix epoch
    timeout += Date.now();
    this.logger.info('after timeout+=: ' + timeout);
    client.waitForReady(timeout, (err: Error | undefined) => {
      this.logger.info('returned');
      if (err != null) {
        this.logger.info('Error thrown: ' + err!.toString());
      }
    });

This results in the following terminating execution:

[nix-shell:~/Documents/MatrixAI/js-polykey]$ npm run ts-node test.ts

> @matrixai/[email protected] ts-node /home/josh/Documents/MatrixAI/js-polykey
> ts-node -r tsconfig-paths/register "test.ts"

INFO:ClientLogger:Setting umask to 077
INFO:ClientLogger:Setting node path to /run/user/1000/polykey-test-remote-gHS0MO
INFO:ClientLogger:Failed to open version file: ENOENT: no such file or directory, open '/run/user/1000/polykey-test-remote-gHS0MO/versionFile'
INFO:ClientLogger:Creating Forward Proxy
INFO:ClientLogger:Created Forward Proxy
INFO:ClientLogger:Creating Reverse Proxy
INFO:ClientLogger:Created Reverse Proxy
INFO:KeyManager:Creating Key Manager
INFO:KeyManager:Setting keys path to /run/user/1000/polykey-test-remote-gHS0MO/keys
INFO:KeyManager:Checking /run/user/1000/polykey-test-remote-gHS0MO/keys/root.pub and /run/user/1000/polykey-test-remote-gHS0MO/keys/root.key
INFO:KeyManager:Generating root key pair
INFO:KeyManager:Writing /run/user/1000/polykey-test-remote-gHS0MO/keys/root.pub and /run/user/1000/polykey-test-remote-gHS0MO/keys/root.key
INFO:KeyManager:Checking /run/user/1000/polykey-test-remote-gHS0MO/keys/root.crt
INFO:KeyManager:Generating root certificate
INFO:KeyManager:Writing /run/user/1000/polykey-test-remote-gHS0MO/keys/root.crt
INFO:KeyManager:Checking /run/user/1000/polykey-test-remote-gHS0MO/keys/db.key
INFO:KeyManager:Generating keys db key
INFO:KeyManager:Writing /run/user/1000/polykey-test-remote-gHS0MO/keys/db.key
INFO:KeyManager:Checking /run/user/1000/polykey-test-remote-gHS0MO/keys/vault.key
INFO:KeyManager:Generating keys db key
INFO:KeyManager:Writing /run/user/1000/polykey-test-remote-gHS0MO/keys/vault.key
INFO:KeyManager:Created Key Manager
INFO:ClientLogger:Starting DB
INFO:ClientLogger:Setting DB path to /run/user/1000/polykey-test-remote-gHS0MO/db
INFO:ClientLogger:Started DB
INFO:Sigchain:Creating Sigchain
INFO:Sigchain:Created Sigchain
INFO:ACL:Starting ACL
INFO:ACL:Started ACL
INFO:GestaltGraph:Starting Gestalt Graph
INFO:GestaltGraph:Started Gestalts Graph
INFO:NodeManager:Creating Node Manager
INFO:NodeManager:Created Node Manager
INFO:VaultManager:Creating Vault Manager
INFO:DB:Starting DB
INFO:DB:Setting DB path to /run/user/1000/polykey-test-remote-gHS0MO/vaults
INFO:DB:Started DB
INFO:VaultManager:Starting EncryptedFS
INFO:VaultManager:Started EncryptedFS
INFO:VaultManager:Created Vault Manager
INFO:IdentitiesManager:Starting Identities Manager
INFO:IdentitiesManager:Started Identities Manager
INFO:Discovery:Creating Discovery
INFO:Discovery:Created Discovery
INFO:NotificationsManager:Starting Notifications Manager
INFO:NotificationsManager:Started Notifications Manager
INFO:ClientLogger:Starting SessionManager
INFO:ClientLogger:Putting keypair into DB
INFO:ClientLogger:Started SessionManager
INFO:ClientServer:Creating GRPC Server
INFO:ClientServer:Created GRPC Server
INFO:AgentServer:Creating GRPC Server
INFO:AgentServer:Created GRPC Server
INFO:ClientLogger:Starting Polykey
INFO:NodeManager:Starting Node Manager
INFO:NodeManager:Starting Node Graph
INFO:NodeManager:Started Node Graph
INFO:NodeManager:Started Node Manager
INFO:ClientServer:Starting GRPC Server on 127.0.0.1:0
INFO:ClientServer:Started GRPC Server on 127.0.0.1:41243
INFO:AgentServer:Starting GRPC Server on 127.0.0.1:0
INFO:AgentServer:Started GRPC Server on 127.0.0.1:42961
INFO:ClientLogger:Starting Forward Proxy from [::]:0 to 0.0.0.0:0
INFO:ClientLogger:Started Forward Proxy from [::]:43065 to 0.0.0.0:34492
INFO:ClientLogger:Starting Reverse Proxy from 0.0.0.0:0 to 127.0.0.1:42961
INFO:ClientLogger:Started Reverse Proxy from 0.0.0.0:40592 to 127.0.0.1:42961
INFO:Lockfile:Writing lockfile to /run/user/1000/polykey-test-remote-gHS0MO/agent-lock.json
INFO:Lockfile:Writing lockfile to /run/user/1000/polykey-test-remote-gHS0MO/agent-lock.json
INFO:Lockfile:Writing lockfile to /run/user/1000/polykey-test-remote-gHS0MO/agent-lock.json
INFO:Lockfile:Writing lockfile to /run/user/1000/polykey-test-remote-gHS0MO/agent-lock.json
INFO:Lockfile:Writing lockfile to /run/user/1000/polykey-test-remote-gHS0MO/agent-lock.json
INFO:ClientLogger:Started Polykey
INFO:NodeManager:Creating GRPCClientAgent
INFO:NodeManager:Created GRPCClientAgent
INFO:NodeManager:Creating NodeConnection
INFO:NodeManager:Created NodeConnection
INFO:NodeManager:Starting NodeConnection
INFO:NodeManager:Starting GRPC Client connecting to 125.0.0.1:55555
INFO:NodeManager:after timeout+=: Infinity
INFO:NodeManager:if secure
INFO:NodeManager:Started GRPC Client connected to 125.0.0.1:55555
INFO:NodeManager:Started NodeConnection from vsks1smfjjoc0i329n9tl8lo1o9beh5bmapkssbn45q7a3m2ckv5g to vi3et1hrpv2m2lrplcm7cu913kr45v51cak54vm68anlbvuf83ra0
INFO:ClientLogger:Stopping Polykey
INFO:ClientServer:Stopping GRPC Server
INFO:ClientServer:Stopped GRPC Server
INFO:AgentServer:Stopping GRPC Server
INFO:AgentServer:Stopped GRPC Server
INFO:Lockfile:Deleting lockfile from /run/user/1000/polykey-test-remote-gHS0MO/agent-lock.json
INFO:ClientLogger:Handling CONNECT to 125.0.0.1:55555
INFO:Connection 125.0.0.1:55555:Starting Connection Forward
INFO:Connection 125.0.0.1:55555:before race
INFO:NodeManager:Stopping Node Manager
INFO:NodeManager:Stopping NodeConnection
INFO:NodeManager:Stopping GRPC Client connected to 125.0.0.1:55555
INFO:NodeManager:returned
INFO:NodeManager:Error thrown: Error: The channel has been closed
INFO:NodeManager:Stopped GRPC Client connected to 125.0.0.1:55555
INFO:NodeManager:Stopped NodeConnection from vsks1smfjjoc0i329n9tl8lo1o9beh5bmapkssbn45q7a3m2ckv5g to vi3et1hrpv2m2lrplcm7cu913kr45v51cak54vm68anlbvuf83ra0
INFO:NodeManager:Stopping Node Graph
INFO:NodeManager:Stopped Node Graph
INFO:NodeManager:Stopped Node Manager
INFO:ClientLogger:Stopping Reverse Proxy
INFO:ClientLogger:Stopped Reverse Proxy
INFO:ClientLogger:Stopping Forward Proxy Server
INFO:Connection 125.0.0.1:55555:after race
INFO:Connection 125.0.0.1:55555:Stopping Connection Forward
INFO:Connection 125.0.0.1:55555:Stopped Connection Forward
INFO:Connection 125.0.0.1:55555:catching e at endErrorConnectionStartTimeout
INFO:ClientLogger:caught e in forwardProxy ErrorConnectionStartTimeout
INFO:ClientLogger:e instanceof ErrorConnection
ERROR:ClientLogger:Failed CONNECT to 125.0.0.1:55555 - ErrorConnectionStartTimeout
Failed to connect to 125.0.0.1:55555/?nodeId=vi3et1hrpv2m2lrplcm7cu913kr45v51cak54vm68anlbvuf83ra0 through proxy :::43065 with status 400
INFO:ClientLogger:Stopped Forward Proxy Server
INFO:ClientLogger:Stopping DB
INFO:ClientLogger:Stopped DB
INFO:ClientLogger:Stopped Polykey
INFO:ClientLogger:Destroying Polykey
INFO:AgentServer:Destroyed GRPC server
INFO:ClientServer:Destroyed GRPC server
INFO:ClientLogger:Destroyed SessionManager
INFO:NotificationsManager:Destroyed Notifications Manager
INFO:Discovery:Destroyed Discovery
INFO:IdentitiesManager:Destroyed Identities Manager
INFO:VaultManager:Destroying Vault Manager
INFO:VaultManager:Stopping EncryptedFS
INFO:DB:Stopping DB
INFO:DB:Stopped DB
INFO:VaultManager:Stopped EncryptedFS
INFO:VaultManager:Destroyed Vault Manager
INFO:NodeManager:Destroyed Node Manager
INFO:GestaltGraph:Destroyed Gestalt Graph
INFO:ACL:Destroyed ACL
INFO:Sigchain:Destroyed Sigchain
INFO:ClientLogger:Destroyed Reverse Proxy
INFO:ClientLogger:Destroyed Forward Proxy Server
INFO:KeyManager:Destroyed Key Manager
INFO:ClientLogger:Destroyed Polykey

The callback shows the error thrown: INFO:NodeManager:Error thrown: Error: The channel has been closed.

I think I'm potentially misusing the callback here though. It's asynchronous, and we only see the returned and Error thrown logger message after the PolykeyAgent instigates shutdown.

@joshuakarp
Copy link
Contributor Author

Nonetheless, I couldn't figure out if there was a way to reduce the number of retries, so I'll be simply applying a finite timeout to the client connection. I'm thinking that this should be the same as the connection timeout specified in ForwardProxy.

@CMCDragonkai
Copy link
Member

CMCDragonkai commented Nov 5, 2021

Promisify should put any errors values in the callback into exceptions thrown. That's how it works.

@joshuakarp
Copy link
Contributor Author

I've changed the timeout parameter on GRPCClient to default to 25000ms instead of Infinity - I figured this would be reasonable, given that the ForwardProxy's connection timeout is already defaulted to 20000ms. This can be reconfigured as necessary.

@joshuakarp
Copy link
Contributor Author

All NodeManager tests passing:

[nix-shell:~/Documents/MatrixAI/js-polykey]$ npm test -- tests/nodes/NodeManager.test.ts 

> @matrixai/[email protected] test /home/josh/Documents/MatrixAI/js-polykey
> jest "tests/nodes/NodeManager.test.ts"

Determining test suites to run...
GLOBAL SETUP
ERROR:NodeManagerTest:Failed CONNECT to 125.0.0.1:55555 - ErrorConnectionStartTimeout
  console.error
    Failed to connect to 125.0.0.1:55555/?nodeId=vi3et1hrpv2m2lrplcm7cu913kr45v51cak54vm68anlbvuf83ra0 through proxy :::42787 with status 400

      at Object.<anonymous>.exports.log (node_modules/@grpc/grpc-js/src/logging.ts:57:13)
      at ClientRequest.<anonymous> (node_modules/@grpc/grpc-js/src/http_proxy.ts:269:9)

WARN:Connection 0.0.0.0:45412:Connection Error: ErrorConnectionTimeout
ERROR:NodeManagerTest:Failed CONNECT to 127.0.0.2:22222 - ErrorConnectionStartTimeout
  console.error
    Failed to connect to 127.0.0.2:22222/?nodeId=vi3et1hrpv2m2lrplcm7cu913kr45v51cak54vm68anlbvuf83ra0 through proxy :::37865 with status 400

      at Object.<anonymous>.exports.log (node_modules/@grpc/grpc-js/src/logging.ts:57:13)
      at ClientRequest.<anonymous> (node_modules/@grpc/grpc-js/src/http_proxy.ts:269:9)

 PASS  tests/nodes/NodeManager.test.ts (187.511 s)
  NodeManager
    ✓ pings node (82422 ms)
    ✓ finds node (local) (3314 ms)
    ✓ finds node (contacts remote node) (8265 ms)
    ✓ cannot find node (contacts remote node) (28246 ms)
    ✓ knows node (true and false case) (3719 ms)
    getConnectionToNode
      ✓ creates new connection to node (5421 ms)
      ✓ gets existing connection to node (5362 ms)
      ✓ concurrent connection creation to same target results in 1 connection (5930 ms)
      ✓ unable to create new connection to offline node (25668 ms)
    Cross signing claims
      ✓ can successfully cross sign a claim (3631 ms)

Test Suites: 1 passed, 1 total
Tests:       10 passed, 10 total
Snapshots:   0 total
Time:        187.55 s
Ran all test suites matching /tests\/nodes\/NodeManager.test.ts/i.
GLOBAL TEARDOWN

As seen in the output though, there is a console.error being outputted, but this is coming internally from the grpc-js module:

// grpc-js/src/http_proxy.ts
      } else {
        log(
          LogVerbosity.ERROR,
          'Failed to connect to ' +
            options.path +
            ' through proxy ' +
            proxyAddressString +
            ' with status ' +
            res.statusCode
        );
        reject();
      }

We can potentially look at suppressing this error at another time. This might become a part of the CLI review occurring on GitLab !213 at the moment: https://gitlab.com/MatrixAI/Engineering/Polykey/js-polykey/-/merge_requests/213

@joshuakarp
Copy link
Contributor Author

client tests all passing:

[nix-shell:~/Documents/MatrixAI/js-polykey]$ npm test -- tests/client/clientService.test.ts 

> @matrixai/[email protected] test /home/josh/Documents/MatrixAI/js-polykey
> jest "tests/client/clientService.test.ts"

Determining test suites to run...
GLOBAL SETUP
WARN:Connection 0.0.0.0:36057:Connection Error: ErrorConnectionTimeout
ERROR:ClientServerTest:Failed CONNECT to 0.0.0.0:36057 - ErrorConnectionStartTimeout
  console.error
    Failed to connect to 0.0.0.0:36057/?nodeId=vqdsufn3lrh6bovsgr03ggh260mpm9mnsehjrll9k25pe249r60l0 through proxy :::42323 with status 400

      at Object.<anonymous>.exports.log (node_modules/@grpc/grpc-js/src/logging.ts:57:13)
      at ClientRequest.<anonymous> (node_modules/@grpc/grpc-js/src/http_proxy.ts:269:9)

ERROR:ClientServerTest:Failed CONNECT to 127.0.0.1:11111 - ErrorConnectionStartTimeout
  console.error
    Failed to connect to 127.0.0.1:11111/?nodeId=vrcacp9vsb4ht25hds6s4lpp2abfaso0mptcfnh499n35vfcn2gkg through proxy :::42323 with status 400

      at Object.<anonymous>.exports.log (node_modules/@grpc/grpc-js/src/logging.ts:57:13)
      at ClientRequest.<anonymous> (node_modules/@grpc/grpc-js/src/http_proxy.ts:269:9)

ERROR:ClientServerTest:Failed CONNECT to 127.0.0.1:11111 - ErrorConnectionStartTimeout
  console.error
    Failed to connect to 127.0.0.1:11111/?nodeId=v359vgrgmqf1r5g4fvisiddjknjko6bmm4qv7646jr7fi9enbfuug through proxy :::42323 with status 400

      at Object.<anonymous>.exports.log (node_modules/@grpc/grpc-js/src/logging.ts:57:13)
      at ClientRequest.<anonymous> (node_modules/@grpc/grpc-js/src/http_proxy.ts:269:9)

 PASS  tests/client/clientService.test.ts (282.018 s)
  Client service
    ✓ can echo (80 ms)
    sessions
      ✓ can request a session (634 ms)
      ✓ can refresh session (533 ms)
      ✓ session can lock all (725 ms)
      ✎ todo actions over GRPC refresh the session
    agent
      ✓ stop (11429 ms)
    vaults
      ✓ should get vaults (5605 ms)
      ✓ should create vault (1002 ms)
      ✓ should delete vaults (4992 ms)
      ✓ should rename vaults (1008 ms)
      ✓ should make a directory in a vault (1656 ms)
      ✓ should list secrets in a vault (3763 ms)
      ✓ should delete secrets in a vault (7280 ms)
      ✓ should edit secrets in a vault (7327 ms)
      ✓ should get secrets in a vault (3683 ms)
      ✓ should rename secrets in a vault (6939 ms)
      ✓ should add secrets in a vault (2206 ms)
      ✓ should add a directory of secrets in a vault (7258 ms)
      ○ skipped should get stats for vaults
      ○ skipped should add permissions to a vault
      ○ skipped should remove permissions to a vault
      ○ skipped should get permissions to a vault
      vault versions
        ✓ should be able to switch a vault to a specific version of it's history using VaultName (4285 ms)
        ✓ should be able to switch a vault to a specific version of it's history using VaultId (4098 ms)
        ✓ should fail to find a non existent version (3747 ms)
        ✓ should be able to go to the end of the vault history (4475 ms)
        ✓ should destroy newer history when writing to an old version (7426 ms)
      Vault Log
        ✓ should get the full log (5810 ms)
        ✓ should get a part of the log (6083 ms)
        ✓ should get a specific commit (5563 ms)
    keys
      ✓ should get root keypair (18 ms)
      ✓ should reset root keypair (2099 ms)
      ✓ should renew root keypair (2225 ms)
      ✓ should encrypt and decrypt with root keypair (259 ms)
      ✓ should encrypt and decrypt with root keypair (246 ms)
      ✓ should get the root certificate and chains (33 ms)
      ○ skipped should change password
    identities
      ✓ should Authenticate an identity. (23 ms)
      ✓ should manipulate tokens for providers (72 ms)
      ✓ should list providers. (20 ms)
      ✓ should list connected Identities. (31 ms)
      ✓ should get identity info. (21 ms)
      ✓ should augment a keynode. (27 ms)
    gestalts
      ✓ should get all gestalts (24 ms)
      ✓ should set independent node and identity gestalts (11 ms)
      ✓ should get gestalt from Node. (26 ms)
      ✓ should get gestalt from identity. (24 ms)
      ✓ should discover gestalt via Node. (38 ms)
      ✓ should discover gestalt via Identity. (19 ms)
      ✓ should get gestalt permissions by node. (37 ms)
      ✓ should get gestalt permissions by Identity. (37 ms)
      ✓ should set gestalt permissions by node. (36 ms)
      ✓ should set gestalt permissions by Identity. (38 ms)
      ✓ should unset gestalt permissions by node. (37 ms)
      ✓ should unset gestalt permissions by Identity. (51 ms)
    Nodes RPC
      ✓ should add a node (33 ms)
      ✓ should ping a node (online + offline) (77021 ms)
      ✓ should find a node (local) (60 ms)
      ✓ should fail to find a node (contacts remote node) (60872 ms)
      ○ skipped should find a node (contacts remote node)
    Nodes claims
      ✓ should send a gestalt invite (no existing invitation) (284 ms)
      ✓ should send a gestalt invite (existing invitation) (329 ms)
      ✓ should claim node (154 ms)
    Notifications RPC
      ✓ should send notifications. (277 ms)
      ✓ should read all notifications. (355 ms)
      ✓ should read a single notification. (58 ms)
      ✓ should clear all notifications. (108 ms)
  google/protobuf message examples
    ✓ testing Any message type (1 ms)
    ✓ testing TimeStamp message
    ✓ testing structs usage (2 ms)

Test Suites: 1 passed, 1 total
Tests:       6 skipped, 1 todo, 63 passed, 70 total
Snapshots:   0 total
Time:        282.059 s
Ran all test suites matching /tests\/client\/clientService.test.ts/i.
GLOBAL TEARDOWN

[nix-shell:~/Documents/MatrixAI/js-polykey]$ npm test -- tests/client/GRPCClientClient.test.ts 

> @matrixai/[email protected] test /home/josh/Documents/MatrixAI/js-polykey
> jest "tests/client/GRPCClientClient.test.ts"

Determining test suites to run...
GLOBAL SETUP
 PASS  tests/client/GRPCClientClient.test.ts (7.836 s)
  GRPCClientClient
    ✓ echo (4420 ms)

Test Suites: 1 passed, 1 total
Tests:       1 passed, 1 total
Snapshots:   0 total
Time:        7.882 s
Ran all test suites matching /tests\/client\/GRPCClientClient.test.ts/i.
GLOBAL TEARDOWN

[nix-shell:~/Documents/MatrixAI/js-polykey]$ npm test -- tests/client/PolykeyClient.test.ts    

> @matrixai/[email protected] test /home/josh/Documents/MatrixAI/js-polykey
> jest "tests/client/PolykeyClient.test.ts"

Determining test suites to run...
GLOBAL SETUP
 PASS  tests/client/PolykeyClient.test.ts (12.767 s)
  GRPCClientClient
    ✓ echo (4608 ms)
  TLS tests
    ✓ Can connect and echo over TLS (29 ms)

Test Suites: 1 passed, 1 total
Tests:       2 passed, 2 total
Snapshots:   0 total
Time:        12.803 s
Ran all test suites matching /tests\/client\/PolykeyClient.test.ts/i.
GLOBAL TEARDOWN

Similar problems with the error output.

@joshuakarp
Copy link
Contributor Author

agent all passing:

[nix-shell:~/Documents/MatrixAI/js-polykey]$ npm test -- tests/agent/

> @matrixai/[email protected] test /home/josh/Documents/MatrixAI/js-polykey
> jest "tests/agent/"

Determining test suites to run...
GLOBAL SETUP
 PASS  tests/agent/GRPCClientAgent.test.ts (24.547 s)
  GRPC agent
    ✓ echo (2306 ms)
    ✓ Can connect over insecure connection. (2217 ms)
    ○ skipped can check permissions
    ○ skipped can scan vaults
    Cross signing claims
      ✓ can successfully cross sign a claim (4578 ms)
      ✓ fails after receiving undefined singly signed claim (5472 ms)
      ✓ fails after receiving singly signed claim with no signature (4894 ms)

 PASS  tests/agent/utils.test.ts (30.478 s)
  agent utils
    checkAgentRunning
      ✓ False if agent not running. (4 ms)
      ✓ True if agent running. (4422 ms)
    spawnBackgroundAgent
      ✓ Should spawn an agent in the background. (17140 ms)
      ✓ Should throw error if agent already running. (3941 ms)

Test Suites: 2 passed, 2 total
Tests:       2 skipped, 9 passed, 11 total
Snapshots:   0 total
Time:        30.735 s
Ran all test suites matching /tests\/agent\//i.
GLOBAL TEARDOWN

@CMCDragonkai
Copy link
Member

It appears logging in grpc can be controlled with a few env variables. https://stackoverflow.com/questions/60934882/nodejs-how-is-logging-enabled-for-the-grpc-grpc-js-package

However I believe these are actual configuration parameters as well.

I wonder if it's possible to dependency inject a logger thus be able to propagate their messages into js-logger. I'd open up an issue on grpc-node asking about this if it's not obvious from docs.

@joshuakarp
Copy link
Contributor Author

It appears logging in grpc can be controlled with a few env variables. https://stackoverflow.com/questions/60934882/nodejs-how-is-logging-enabled-for-the-grpc-grpc-js-package

However I believe these are actual configuration parameters as well.

I wonder if it's possible to dependency inject a logger thus be able to propagate their messages into js-logger. I'd open up an issue on grpc-node asking about this if it's not obvious from docs.

There is a setLogger function that takes a TypeScript Console type:

https://grpc.github.io/grpc/node/grpc.html#.setLogger__anchor

// grpc-js/src/logging.ts
export const setLogger = (logger: Partial<Console>): void => {
  _logger = logger;
};

export const setLoggerVerbosity = (verbosity: LogVerbosity): void => {
  _logVerbosity = verbosity;
};

Also able to set the verbosity of the logger there.

@CMCDragonkai
Copy link
Member

But can it be DIed from the client or server construction?

@joshuakarp
Copy link
Contributor Author

I figured out why my tests were timing out... the timeout set in GRPCClient.start also has a super.start called in GRPCClientAgent - this was also defaulted to Infinity which I hadn't changed over to 25000.

@joshuakarp
Copy link
Contributor Author

But can it be DIed from the client or server construction?

Will have to look into this.

@joshuakarp
Copy link
Contributor Author

Tests:

clientService: all passed

[nix-shell:~/Documents/MatrixAI/js-polykey]$ npm test -- tests/client/clientService.test.ts 

> @matrixai/[email protected] test /home/josh/Documents/MatrixAI/js-polykey
> jest "tests/client/clientService.test.ts"

Determining test suites to run...
GLOBAL SETUP
WARN:Connection 0.0.0.0:43159:Connection Error: ErrorConnectionTimeout
ERROR:ClientServerTest:Failed CONNECT to 127.0.0.1:11111 - ErrorConnectionStartTimeout
  console.error
    Failed to connect to 127.0.0.1:11111/?nodeId=vrcacp9vsb4ht25hds6s4lpp2abfaso0mptcfnh499n35vfcn2gkg through proxy :::40513 with status 400

      at Object.<anonymous>.exports.log (node_modules/@grpc/grpc-js/src/logging.ts:57:13)
      at ClientRequest.<anonymous> (node_modules/@grpc/grpc-js/src/http_proxy.ts:269:9)

ERROR:ClientServerTest:Failed CONNECT to 127.0.0.1:11111 - ErrorConnectionStartTimeout
  console.error
    Failed to connect to 127.0.0.1:11111/?nodeId=vrcacp9vsb4ht25hds6s4lpp2abfaso0mptcfnh499n35vfcn2gkg through proxy :::40513 with status 400

      at Object.<anonymous>.exports.log (node_modules/@grpc/grpc-js/src/logging.ts:57:13)
      at ClientRequest.<anonymous> (node_modules/@grpc/grpc-js/src/http_proxy.ts:269:9)

ERROR:ClientServerTest:Failed CONNECT to 127.0.0.1:11111 - ErrorConnectionStartTimeout
  console.error
    Failed to connect to 127.0.0.1:11111/?nodeId=v359vgrgmqf1r5g4fvisiddjknjko6bmm4qv7646jr7fi9enbfuug through proxy :::40513 with status 400

      at Object.<anonymous>.exports.log (node_modules/@grpc/grpc-js/src/logging.ts:57:13)
      at ClientRequest.<anonymous> (node_modules/@grpc/grpc-js/src/http_proxy.ts:269:9)

ERROR:ClientServerTest:Failed CONNECT to 0.0.0.0:43159 - ErrorConnectionStartTimeout
  console.error
    Failed to connect to 0.0.0.0:43159/?nodeId=va2jeudlsshh7o2bsd7f9qodcc9ear7mfpl7c72vn7oru55kjiq0g through proxy :::40513 with status 400

      at Object.<anonymous>.exports.log (node_modules/@grpc/grpc-js/src/logging.ts:57:13)
      at ClientRequest.<anonymous> (node_modules/@grpc/grpc-js/src/http_proxy.ts:269:9)

ERROR:ClientServerTest:Failed CONNECT to 0.0.0.0:43159 - ErrorConnectionStartTimeout
  console.error
    Failed to connect to 0.0.0.0:43159/?nodeId=va2jeudlsshh7o2bsd7f9qodcc9ear7mfpl7c72vn7oru55kjiq0g through proxy :::40513 with status 400

      at Object.<anonymous>.exports.log (node_modules/@grpc/grpc-js/src/logging.ts:57:13)
      at ClientRequest.<anonymous> (node_modules/@grpc/grpc-js/src/http_proxy.ts:269:9)

 PASS  tests/client/clientService.test.ts (290.952 s)
  Client service
    ✓ can echo (92 ms)
    sessions
      ✓ can request a session (572 ms)
      ✓ can refresh session (548 ms)
      ✓ session can lock all (1000 ms)
      ✎ todo actions over GRPC refresh the session
    agent
      ✓ stop (12634 ms)
    vaults
      ✓ should get vaults (4585 ms)
      ✓ should create vault (850 ms)
      ✓ should delete vaults (4251 ms)
      ✓ should rename vaults (906 ms)
      ✓ should make a directory in a vault (1734 ms)
      ✓ should list secrets in a vault (3810 ms)
      ✓ should delete secrets in a vault (6583 ms)
      ✓ should edit secrets in a vault (7006 ms)
      ✓ should get secrets in a vault (3564 ms)
      ✓ should rename secrets in a vault (6985 ms)
      ✓ should add secrets in a vault (2021 ms)
      ✓ should add a directory of secrets in a vault (6540 ms)
      ○ skipped should get stats for vaults
      ○ skipped should add permissions to a vault
      ○ skipped should remove permissions to a vault
      ○ skipped should get permissions to a vault
      vault versions
        ✓ should be able to switch a vault to a specific version of it's history using VaultName (4257 ms)
        ✓ should be able to switch a vault to a specific version of it's history using VaultId (4234 ms)
        ✓ should fail to find a non existent version (3566 ms)
        ✓ should be able to go to the end of the vault history (4859 ms)
        ✓ should destroy newer history when writing to an old version (8179 ms)
      Vault Log
        ✓ should get the full log (6168 ms)
        ✓ should get a part of the log (6067 ms)
        ✓ should get a specific commit (6505 ms)
    keys
      ✓ should get root keypair (18 ms)
      ✓ should reset root keypair (1670 ms)
      ✓ should renew root keypair (2411 ms)
      ✓ should encrypt and decrypt with root keypair (264 ms)
      ✓ should encrypt and decrypt with root keypair (270 ms)
      ✓ should get the root certificate and chains (39 ms)
      ○ skipped should change password
    identities
      ✓ should Authenticate an identity. (21 ms)
      ✓ should manipulate tokens for providers (73 ms)
      ✓ should list providers. (19 ms)
      ✓ should list connected Identities. (22 ms)
      ✓ should get identity info. (21 ms)
      ✓ should augment a keynode. (30 ms)
    gestalts
      ✓ should get all gestalts (30 ms)
      ✓ should set independent node and identity gestalts (13 ms)
      ✓ should get gestalt from Node. (30 ms)
      ✓ should get gestalt from identity. (28 ms)
      ✓ should discover gestalt via Node. (42 ms)
      ✓ should discover gestalt via Identity. (23 ms)
      ✓ should get gestalt permissions by node. (44 ms)
      ✓ should get gestalt permissions by Identity. (47 ms)
      ✓ should set gestalt permissions by node. (42 ms)
      ✓ should set gestalt permissions by Identity. (46 ms)
      ✓ should unset gestalt permissions by node. (49 ms)
      ✓ should unset gestalt permissions by Identity. (48 ms)
    Nodes RPC
      ✓ should add a node (25 ms)
      ✓ should ping a node (online + offline) (76812 ms)
      ✓ should find a node (local) (62 ms)
      ✓ should fail to find a node (contacts remote node) (75717 ms)
      ○ skipped should find a node (contacts remote node)
    Nodes claims
      ✓ should send a gestalt invite (no existing invitation) (274 ms)
      ✓ should send a gestalt invite (existing invitation) (337 ms)
      ✓ should claim node (160 ms)
    Notifications RPC
      ✓ should send notifications. (280 ms)
      ✓ should read all notifications. (338 ms)
      ✓ should read a single notification. (110 ms)
      ✓ should clear all notifications. (119 ms)
  google/protobuf message examples
    ✓ testing Any message type (1 ms)
    ✓ testing TimeStamp message
    ✓ testing structs usage (2 ms)

Test Suites: 1 passed, 1 total
Tests:       6 skipped, 1 todo, 63 passed, 70 total
Snapshots:   0 total
Time:        290.992 s
Ran all test suites matching /tests\/client\/clientService.test.ts/i.
GLOBAL TEARDOWN

bin/nodes: all passed, but an async timeout issue

[nix-shell:~/Documents/MatrixAI/js-polykey]$ npm test -- tests/bin/node

> @matrixai/[email protected] test /home/josh/Documents/MatrixAI/js-polykey
> jest "tests/bin/node"

Determining test suites to run...
GLOBAL SETUP
ERROR:pkWithStdio Test:Failed CONNECT to 0.0.0.0:46602 - ErrorConnectionStartTimeout
  console.error
    Failed to connect to 0.0.0.0:46602/?nodeId=v9k55auofnv05i303gfmfmtkkd452cq4aclds15b5jdbq6vfbqrjg through proxy :::42309 with status 400

      at Object.<anonymous>.exports.log (node_modules/@grpc/grpc-js/src/logging.ts:57:13)
      at ClientRequest.<anonymous> (node_modules/@grpc/grpc-js/src/http_proxy.ts:269:9)

 PASS  tests/bin/nodes.test.ts (179.27 s)
  CLI Nodes
    commandClaimNode
      ✓ Should send a gestalt invite (312 ms)
      ✓ Should send a gestalt invite (force invite) (351 ms)
      ✓ Should claim remote node (182 ms)
    commandPingNode
      ✓ Should return failure when pinging an offline node (43216 ms)
      ✓ Should return failure if can't find the node (50663 ms)
      ✓ Should return success when pinging a live node (68 ms)
    commandFindNode
      ✓ Should find an online node (67 ms)
      ✓ Should find an offline node (52 ms)
      ✓ Should fail to find an unknown node (50623 ms)
    commandAddNode
      ✓ Should add the node (54 ms)
      ✓ Should fail to add the node (invalid node ID) (37 ms)
      ✓ Should fail to add the node (invalid IP address) (35 ms)

Test Suites: 1 passed, 1 total
Tests:       12 passed, 12 total
Snapshots:   0 total
Time:        179.333 s
Ran all test suites matching /tests\/bin\/node/i.
GLOBAL TEARDOWN
Jest did not exit one second after the test run has completed.

This usually means that there are asynchronous operations that weren't stopped in your tests. Consider running Jest with `--detectOpenHandles` to troubleshoot this issue.

src/nodes: all passed

[nix-shell:~/Documents/MatrixAI/js-polykey]$ npm test -- tests/nodes

> @matrixai/[email protected] test /home/josh/Documents/MatrixAI/js-polykey
> jest "tests/nodes"

Determining test suites to run...
GLOBAL SETUP
 PASS  tests/nodes/utils.test.ts
  Nodes utils
    ✓ basic distance calculation (5 ms)
    ✓ calculates correct first bucket (bucket 0) (1 ms)
    ✓ calculates correct arbitrary bucket (bucket 63) (2 ms)
    ✓ calculates correct last bucket (bucket 255)
    ✓ testing type guard. (2 ms)

 PASS  tests/nodes/NodeGraph.test.ts (8.458 s)
  NodeGraph
    ✓ finds correct node address (17 ms)
    ✓ unable to find node address (9 ms)
    ✓ adds a single node into a bucket (6 ms)
    ✓ adds multiple nodes into the same bucket (26 ms)
    ✓ adds a single node into different buckets (13 ms)
    ✓ deletes a single node (and removes bucket) (8 ms)
    ✓ deletes a single node (and retains remainder of bucket) (27 ms)
    ✓ enforces k-bucket size, removing least active node when a new node is discovered (109 ms)
    ✓ retrieves all buckets (in expected lexicographic order) (17 ms)
    ✓ refreshes buckets (2574 ms)
    ✓ finds a single closest node (3 ms)
    ✓ finds 3 closest nodes (12 ms)
    ✓ finds the 20 closest nodes (113 ms)
    ✓ updates node (7 ms)

 PASS  tests/nodes/NodeConnection.test.ts (15.106 s)
  NodeConnection
    ✓ connects to its target (via direct connection) (2780 ms)
    ✓ receives 20 closest local nodes from connected target (3450 ms)
    ✓ sends hole punch message to connected target (expected to be broker, to relay further) (3928 ms)
    ○ skipped scans the servers vaults

ERROR:NodeManagerTest:Failed CONNECT to 125.0.0.1:55555 - ErrorConnectionStartTimeout
  console.error
    Failed to connect to 125.0.0.1:55555/?nodeId=vi3et1hrpv2m2lrplcm7cu913kr45v51cak54vm68anlbvuf83ra0 through proxy :::43927 with status 400

      at Object.<anonymous>.exports.log (node_modules/@grpc/grpc-js/src/logging.ts:57:13)
      at ClientRequest.<anonymous> (node_modules/@grpc/grpc-js/src/http_proxy.ts:269:9)

ERROR:NodeManagerTest:Failed CONNECT to 125.0.0.1:55555 - ErrorConnectionStartTimeout
  console.error
    Failed to connect to 125.0.0.1:55555/?nodeId=vi3et1hrpv2m2lrplcm7cu913kr45v51cak54vm68anlbvuf83ra0 through proxy :::43927 with status 400

      at Object.<anonymous>.exports.log (node_modules/@grpc/grpc-js/src/logging.ts:57:13)
      at ClientRequest.<anonymous> (node_modules/@grpc/grpc-js/src/http_proxy.ts:269:9)

WARN:Connection 0.0.0.0:41923:Connection Error: ErrorConnectionTimeout
ERROR:NodeManagerTest:Failed CONNECT to 127.0.0.2:22222 - ErrorConnectionStartTimeout
  console.error
    Failed to connect to 127.0.0.2:22222/?nodeId=vi3et1hrpv2m2lrplcm7cu913kr45v51cak54vm68anlbvuf83ra0 through proxy :::38949 with status 400

      at Object.<anonymous>.exports.log (node_modules/@grpc/grpc-js/src/logging.ts:57:13)
      at ClientRequest.<anonymous> (node_modules/@grpc/grpc-js/src/http_proxy.ts:269:9)

ERROR:NodeManagerTest:Failed CONNECT to 127.0.0.2:22222 - ErrorConnectionStartTimeout
  console.error
    Failed to connect to 127.0.0.2:22222/?nodeId=vi3et1hrpv2m2lrplcm7cu913kr45v51cak54vm68anlbvuf83ra0 through proxy :::38949 with status 400

      at Object.<anonymous>.exports.log (node_modules/@grpc/grpc-js/src/logging.ts:57:13)
      at ClientRequest.<anonymous> (node_modules/@grpc/grpc-js/src/http_proxy.ts:269:9)

 PASS  tests/nodes/NodeManager.test.ts (218.609 s)
  NodeManager
    ✓ pings node (81491 ms)
    ✓ finds node (local) (3018 ms)
    ✓ finds node (contacts remote node) (7134 ms)
    ✓ cannot find node (contacts remote node) (45313 ms)
    ✓ knows node (true and false case) (3595 ms)
    getConnectionToNode
      ✓ creates new connection to node (6665 ms)
      ✓ gets existing connection to node (5413 ms)
      ✓ concurrent connection creation to same target results in 1 connection (5705 ms)
      ✓ unable to create new connection to offline node (43633 ms)
    Cross signing claims
      ✓ can successfully cross sign a claim (3868 ms)

Test Suites: 4 passed, 4 total
Tests:       1 skipped, 32 passed, 33 total
Snapshots:   0 total
Time:        218.944 s, estimated 230 s
Ran all test suites matching /tests\/nodes/i.
GLOBAL TEARDOWN

@joshuakarp
Copy link
Contributor Author

bin/nodes async timeout issue not present in master, so something's caused it in this branch:

[nix-shell:~/Documents/MatrixAI/js-polykey]$ npm test -- tests/bin/nodes.test.ts 

> @matrixai/[email protected] test /home/josh/Documents/MatrixAI/js-polykey
> jest "tests/bin/nodes.test.ts"

Determining test suites to run...
GLOBAL SETUP
 PASS  tests/bin/nodes.test.ts (148.185 s)
  CLI Nodes
    commandClaimNode
      ✓ Should send a gestalt invite (357 ms)
      ✓ Should send a gestalt invite (force invite) (359 ms)
      ✓ Should claim remote node (131 ms)
    commandPingNode
      ✓ Should return failure when pinging an offline node (43124 ms)
      ✓ Should return failure if can't find the node (43341 ms)
      ✓ Should return success when pinging a live node (110 ms)
    commandFindNode
      ✓ Should find an online node (73 ms)
      ✓ Should find an offline node (69 ms)
      ✓ Should fail to find an unknown node (43122 ms)
    commandAddNode
      ✓ Should add the node (63 ms)
      ✓ Should fail to add the node (invalid node ID) (31 ms)
      ✓ Should fail to add the node (invalid IP address) (35 ms)

Test Suites: 1 passed, 1 total
Tests:       12 passed, 12 total
Snapshots:   0 total
Time:        148.243 s, estimated 180 s
Ran all test suites matching /tests\/bin\/nodes.test.ts/i.
GLOBAL TEARDOWN

@joshuakarp
Copy link
Contributor Author

I ran each describe block in bin/nodes individually, and this caused no async timeout closing issues:

commandClaimNode

[nix-shell:~/Documents/MatrixAI/js-polykey]$ npm test -- tests/bin/nodes.test.ts 

> @matrixai/[email protected] test /home/josh/Documents/MatrixAI/js-polykey
> jest "tests/bin/nodes.test.ts"

Determining test suites to run...
GLOBAL SETUP
 PASS  tests/bin/nodes.test.ts (18.227 s)
  CLI Nodes
    commandClaimNode
      ✓ Should send a gestalt invite (289 ms)
      ✓ Should send a gestalt invite (force invite) (339 ms)
      ✓ Should claim remote node (170 ms)
    commandPingNode
      ○ skipped Should return failure when pinging an offline node
      ○ skipped Should return failure if can't find the node
      ○ skipped Should return success when pinging a live node
    commandFindNode
      ○ skipped Should find an online node
      ○ skipped Should find an offline node
      ○ skipped Should fail to find an unknown node
    commandAddNode
      ○ skipped Should add the node
      ○ skipped Should fail to add the node (invalid node ID)
      ○ skipped Should fail to add the node (invalid IP address)

Test Suites: 1 passed, 1 total
Tests:       9 skipped, 3 passed, 12 total
Snapshots:   0 total
Time:        18.268 s
Ran all test suites matching /tests\/bin\/nodes.test.ts/i.
GLOBAL TEARDOWN

commandPingNode

[nix-shell:~/Documents/MatrixAI/js-polykey]$ npm test -- tests/bin/nodes.test.ts 

> @matrixai/[email protected] test /home/josh/Documents/MatrixAI/js-polykey
> jest "tests/bin/nodes.test.ts"

Determining test suites to run...
GLOBAL SETUP
ERROR:pkWithStdio Test:Failed CONNECT to 0.0.0.0:58630 - ErrorConnectionStartTimeout
  console.error
    Failed to connect to 0.0.0.0:58630/?nodeId=vhi422fdapra63ev3gtfpr0kegn12a2t8gl9olne0r3a3nh7k3ne0 through proxy :::39701 with status 400

      at Object.<anonymous>.exports.log (node_modules/@grpc/grpc-js/src/logging.ts:57:13)
      at ClientRequest.<anonymous> (node_modules/@grpc/grpc-js/src/http_proxy.ts:269:9)

 PASS  tests/bin/nodes.test.ts (118.297 s)
  CLI Nodes
    commandClaimNode
      ○ skipped Should send a gestalt invite
      ○ skipped Should send a gestalt invite (force invite)
      ○ skipped Should claim remote node
    commandPingNode
      ✓ Should return failure when pinging an offline node (43567 ms)
      ✓ Should return failure if can't find the node (50839 ms)
      ✓ Should return success when pinging a live node (68 ms)
    commandFindNode
      ○ skipped Should find an online node
      ○ skipped Should find an offline node
      ○ skipped Should fail to find an unknown node
    commandAddNode
      ○ skipped Should add the node
      ○ skipped Should fail to add the node (invalid node ID)
      ○ skipped Should fail to add the node (invalid IP address)

Test Suites: 1 passed, 1 total
Tests:       9 skipped, 3 passed, 12 total
Snapshots:   0 total
Time:        118.348 s
Ran all test suites matching /tests\/bin\/nodes.test.ts/i.
GLOBAL TEARDOWN

commandFindNode

[nix-shell:~/Documents/MatrixAI/js-polykey]$ npm test -- tests/bin/nodes.test.ts 

> @matrixai/[email protected] test /home/josh/Documents/MatrixAI/js-polykey
> jest "tests/bin/nodes.test.ts"

Determining test suites to run...
GLOBAL SETUP
ERROR:pkWithStdio Test:Failed CONNECT to 0.0.0.0:40203 - ErrorConnectionStartTimeout
  console.error
    Failed to connect to 0.0.0.0:40203/?nodeId=vmdfi6k5mi3tn8ru1123icomoqdi5b4jqr64am5nk9hbmcg7ibeb0 through proxy :::37969 with status 400

      at Object.<anonymous>.exports.log (node_modules/@grpc/grpc-js/src/logging.ts:57:13)
      at ClientRequest.<anonymous> (node_modules/@grpc/grpc-js/src/http_proxy.ts:269:9)

 PASS  tests/bin/nodes.test.ts (75.807 s)
  CLI Nodes
    commandClaimNode
      ○ skipped Should send a gestalt invite
      ○ skipped Should send a gestalt invite (force invite)
      ○ skipped Should claim remote node
    commandPingNode
      ○ skipped Should return failure when pinging an offline node
      ○ skipped Should return failure if can't find the node
      ○ skipped Should return success when pinging a live node
    commandFindNode
      ✓ Should find an online node (62 ms)
      ✓ Should find an offline node (51 ms)
      ✓ Should fail to find an unknown node (50771 ms)
    commandAddNode
      ○ skipped Should add the node
      ○ skipped Should fail to add the node (invalid node ID)
      ○ skipped Should fail to add the node (invalid IP address)

Test Suites: 1 passed, 1 total
Tests:       9 skipped, 3 passed, 12 total
Snapshots:   0 total
Time:        75.862 s, estimated 119 s
Ran all test suites matching /tests\/bin\/nodes.test.ts/i.
GLOBAL TEARDOWN

commandAddNode

[nix-shell:~/Documents/MatrixAI/js-polykey]$ npm test -- tests/bin/nodes.test.ts 

> @matrixai/[email protected] test /home/josh/Documents/MatrixAI/js-polykey
> jest "tests/bin/nodes.test.ts"

Determining test suites to run...
GLOBAL SETUP
 PASS  tests/bin/nodes.test.ts (16.53 s)
  CLI Nodes
    commandClaimNode
      ○ skipped Should send a gestalt invite
      ○ skipped Should send a gestalt invite (force invite)
      ○ skipped Should claim remote node
    commandPingNode
      ○ skipped Should return failure when pinging an offline node
      ○ skipped Should return failure if can't find the node
      ○ skipped Should return success when pinging a live node
    commandFindNode
      ○ skipped Should find an online node
      ○ skipped Should find an offline node
      ○ skipped Should fail to find an unknown node
    commandAddNode
      ✓ Should add the node (40 ms)
      ✓ Should fail to add the node (invalid node ID) (64 ms)
      ✓ Should fail to add the node (invalid IP address) (30 ms)

Test Suites: 1 passed, 1 total
Tests:       9 skipped, 3 passed, 12 total
Snapshots:   0 total
Time:        16.577 s, estimated 76 s
Ran all test suites matching /tests\/bin\/nodes.test.ts/i.
GLOBAL TEARDOWN

@joshuakarp
Copy link
Contributor Author

Given that the closure issue is only occurring locally when all bin/nodes tests are run together, I'm more inclined to leave this until #264, when we take a closer look at optimising our tests (specifically, when I look into optimising the nodes tests). I envisage that this investigation will resolve this problem.

…moved ForwardProxy.openConnection from NodeConnection.start
@joshuakarp joshuakarp marked this pull request as ready for review November 9, 2021 02:39
@joshuakarp
Copy link
Contributor Author

Squashed and ready to merge. I believe the plan is to first merge https://gitlab.com/MatrixAI/Engineering/Polykey/js-polykey/-/merge_requests/213, and then this should rebase and merge after.

The only lingering issue is the test closure on tests/bin/nodes (#284 (comment) and following comments), but as mentioned, this will be likely resolved in #264.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Development

Successfully merging this pull request may close these issues.

Refactor getConnectionToNode to use the correct ObjectMap structure
2 participants