Unable to dial service using NodeJS SDK

Node 17 / Express / OpenZiti 0.13.3

We are experiencing problems when implementing the OpenZiti SDK for NodeJs (v0.13.3).

  1. We have created and enrolled an identity for this application.
  2. The identity is being read in correctly, and the application is connecting to the right controller.
  3. The container has extra_hosts specified to allow the SDK to resolve the OZ fabric components (e.g. ziti-edge-controller:1880)
  4. The service appears to initialise correctly with ziti.init().
  5. When attempting to use httpRequest the request fails with Error: Unknown serviceName.

Note: we tried upgrading to SDK 0.14.0 on both Node 17 and 18 but it crashed the application both times.


On the edge config side of things, we have created a service (client-server) that this application has permission to dial. The test-service is left in for completeness, especially as we can see log lines indicating this service was being picked up correctly. Otherwise, test-service should be unrelated to this bug.
ziti edge list services returns

╭────────────────────────┬──────────────────────┬────────────┬─────────────────────┬────────────╮
│ ID                     │ NAME                 │ ENCRYPTION │ TERMINATOR STRATEGY │ ATTRIBUTES │
│                        │                      │  REQUIRED  │                     │            │
├────────────────────────┼──────────────────────┼────────────┼─────────────────────┼────────────┤
│ 1Wx6Vbqku5nHMDLE7Cp21V │ test-service         │ true       │ smartrouting        │            │
├6DipYlwdJV2W4jB4kSiTJm  │ client-server        │ true       │ smartrouting        |            |
╰────────────────────────┴──────────────────────┴────────────┴─────────────────────┴────────────╯

ziti edge list service-policies returns (these are of type Dial and Bind, as they are named)

╭────────────────────────┬───────────────────────────┬──────────┬───────────────────────┬───────────────────┬─────────────────────╮
│ ID                     │ NAME                      │ SEMANTIC │ SERVICE ROLES         │ IDENTITY ROLES    │ POSTURE CHECK ROLES │
├────────────────────────┼───────────────────────────┼──────────┼───────────────────────┼───────────────────┼─────────────────────┤
│ 34P2yv7cQQ8Mq3UbQ52c8l │ client-server-dial        │ AllOf    │ @client-server        │ @client           │                     │
│ 3thVBHENWNWv3ykUvVx0VJ │ client-server-bind        │ AllOf    │ @client-server        │ @server           │                     │
│ 4lAXc35bHHgCowWlmQKz12 │ test-service-bind         │ AllOf    │ @test-service         │ @tunnel-1         │                     │
│ 5uDGOTEcIbQCfuCFl69mpg │ test-service-dial         │ AllOf    │ @test-service         │ @tunnel-2         │                     │
╰────────────────────────┴───────────────────────────┴──────────┴───────────────────────┴───────────────────┴─────────────────────╯

This service is using two configs, an intercept and a host config, as follows:

{
    "addresses": [
        "client-server"
    ],
    "portRanges": [
        {
            "high": 5000,
            "low": 5000
        }
    ],
    "protocols": [
        "tcp"
    ]
}
{
    "address": "127.0.0.1",
    "port": 5000,
    "protocol": "tcp"
}

The application binding to this service (@server) is using the Python SDK and has connected correctly. If a new service-policy is created, allowing another identity (e.g. a ziti-edge-tunnel) to dial the service, we get a response back from the same endpoint as used in the below examples.

We've tried with the "addresses" in the intercept being the same as the service name, as well as a qualified hostname (e.g. client-server.ziti), however this has had no effect.

Initially we tried following the sample code from https://github.com/openziti/ziti-sdk-nodejs#usage. (Note: that sample code is incomplete as it's missing the required undefined port as per the SDK API reference.

Example 1

Code

const app = express();

const zitiServiceName = 'client-server';

ziti.setLogLevel(5);

await ziti.init(`${rootname}/service/jwt.json`).catch(( err ) => { console.error(err) });	

function onResponse(obj) {
	console.log(`response is: ${obj.body.toString('utf8')}`);
}

try {
	ziti.httpRequest(

		// OpenZiti Service name or HTTP origin part of the URL
		serviceName,
	
		// port - don't need both port and service name - note this property is
		// missing from the documentation and, therefore, out of sync with 
		undefined,
	
		'GET',
	
		// path part of the URL including query params
		'/health',
	
		// headers
		['Accept: application/json' ],
	
		// optional on_req cb
		undefined, 
	
		// optional on_req_data cb
		undefined,
	
		// optional on_resp_data cb
		onResponse
	);	
} catch (err) {
	console.error(`Ziti error: ${err} - (tried ${serviceName})`);
}

Error trace

[        0.006] DEBUG   ziti-sdk-nodejs/src/ziti_init.c:264 _ziti_init(): initializing
[        0.006] DEBUG   ziti-sdk-nodejs/src/ziti_init.c:294 _ziti_init(): config_file_name: /usr/share/app/server/src/service/jwt.json
[        0.009] DEBUG   ziti-sdk-nodejs/src/ziti_init.c:343 _ziti_init(): ziti_init_opts rc: 0
(1)[        0.132]    INFO ziti-sdk:ziti.c:413 ziti_init_async() ztx[0] Ziti C SDK version 0.29.7.18-200 @28fdbf8(HEAD) starting at (2023-11-06T16:46:29.030)
(1)[        0.132]    INFO ziti-sdk:ziti.c:416 ziti_init_async() ztx[0] using uv_mbed[v0.14.10], tls[OpenSSL 3.0.3+quic 3 May 2022]
(1)[        0.132]    INFO ziti-sdk:ziti.c:417 ziti_init_async() ztx[0] Loading from config[/usr/share/app/server/src/service/jwt.json] controller[https://ziti-edge-controller:1280/edge/client/v1]
(1)[        0.132]    INFO ziti-sdk:ziti_ctrl.c:401 ziti_ctrl_init() ctrl[ziti-edge-controller] ziti controller client initialized
(1)[        0.132]   DEBUG ziti-sdk:ziti.c:433 ziti_init_async() ztx[0] using metrics interval: 6
(1)[        0.132] VERBOSE ziti-sdk:ziti_ctrl.c:131 start_request() ctrl[ziti-edge-controller] starting GET[/version]
(1)[        0.132]   DEBUG ziti-sdk:ziti.c:249 ziti_set_unauthenticated() ztx[0] setting api_session_state[0] to 0
(1)[        0.132]   DEBUG ziti-sdk:ziti_ctrl.c:242 ziti_ctrl_clear_api_session() ctrl[ziti-edge-controller] clearing api session token for ziti_controller
(1)[        0.132]   DEBUG ziti-sdk:ziti.c:901 ziti_re_auth() ztx[0] re-auth executing, transitioning to unauthenticated
(1)[        0.132]   DEBUG ziti-sdk:ziti.c:249 ziti_set_unauthenticated() ztx[0] setting api_session_state[0] to 0
(1)[        0.132]   DEBUG ziti-sdk:ziti_ctrl.c:242 ziti_ctrl_clear_api_session() ctrl[ziti-edge-controller] clearing api session token for ziti_controller
(1)[        0.132]   DEBUG ziti-sdk:ziti.c:280 is_api_session_expired() ztx[0] is_api_session_expired[TRUE] - api_session is null
(1)[        0.132]    INFO ziti-sdk:ziti.c:849 ziti_re_auth_with_cb() ztx[0] starting to re-auth with ctlr[https://ziti-edge-controller:1280/edge/client/v1] api_session_status[0] api_session_expired[TRUE]
(1)[        0.132]   DEBUG ziti-sdk:ziti.c:242 ziti_set_auth_started() ztx[0] setting api_session_state[0] to 1
(1)[        0.132]   DEBUG ziti-sdk:ziti.c:314 ziti_stop_api_session_refresh() ztx[0] ziti_stop_api_session_refresh: stopping api session refresh
(1)[        0.132] VERBOSE ziti-sdk:ziti_ctrl.c:131 start_request() ctrl[ziti-edge-controller] starting POST[/authenticate?method=cert]
(1)[        0.160] VERBOSE ziti-sdk:ziti_ctrl.c:166 ctrl_resp_cb() ctrl[ziti-edge-controller] received headers GET[/version]
(1)[        0.160]   DEBUG ziti-sdk:ziti_ctrl.c:322 ctrl_body_cb() ctrl[ziti-edge-controller] completed GET[/version] in 0.027 s
(1)[        0.160]    INFO ziti-sdk:ziti.c:1514 version_cb() ztx[0] connected to controller https://ziti-edge-controller:1280/edge/client/v1 version v0.30.5(4f324bd22875 2023-10-13T20:22:56Z) (1)[        0.170] VERBOSE ziti-sdk:ziti_ctrl.c:166 ctrl_resp_cb() ctrl[ziti-edge-controller] received headers POST[/authenticate?method=cert]
(1)[        0.170]   DEBUG ziti-sdk:ziti_ctrl.c:322 ctrl_body_cb() ctrl[ziti-edge-controller] completed POST[/authenticate?method=cert] in 0.037 s
(1)[        0.170]   DEBUG ziti-sdk:ziti_ctrl.c:255 ctrl_login_cb() ctrl[ziti-edge-controller] authenticated successfully session[clon4wpu1vsxhk7n6iw64c954]
(1)[        0.170]   DEBUG ziti-sdk:ziti.c:1431 api_session_cb() ztx[0] logged in successfully => api_session[clon4wpu1vsxhk7n6iw64c954]
(1)[        0.170]   DEBUG ziti-sdk:ziti.c:1381 ziti_set_api_session() ztx[0] ziti api session expires in 1800 seconds
(1)[        0.170]    INFO ziti-sdk:ziti.c:1405 ziti_set_api_session() ztx[0] api session set, setting api_session_timer to 1740s
(1)[        0.170]   DEBUG ziti-sdk:ziti.c:319 ziti_schedule_api_session_refresh() ztx[0] ziti_schedule_api_session_refresh: scheduling api session refresh: 1740000ms
(1)[        0.170]   DEBUG ziti-sdk:ziti.c:274 ziti_set_fully_authenticated() ztx[0] setting api_session_state[1] to 3
(1)[        0.170] VERBOSE ziti-sdk:ziti_ctrl.c:131 start_request() ctrl[ziti-edge-controller] starting GET[/current-identity]
(1)[        0.170] VERBOSE ziti-sdk:ziti.c:1320 session_post_auth_query_cb() ztx[0] post auth query callback starting with status[OK]
(1)[        0.170] VERBOSE ziti-sdk:ziti.c:1322 session_post_auth_query_cb() ztx[0] transitioning to fully authenticated
(1)[        0.170]   DEBUG ziti-sdk:ziti.c:274 ziti_set_fully_authenticated() ztx[0] setting api_session_state[3] to 3
[        0.049] INFO    ziti-sdk-nodejs/src/ziti_init.c:127 on_ziti_event(): controller version = v0.30.5(4f324bd22875)[2023-10-13T20:22:56Z]
[        0.049] INFO    ziti-sdk-nodejs/src/ziti_init.c:128 on_ziti_event(): identity = <client>[xB9NHRwfc-]@https://ziti-edge-controller:1280/edge/client/v1
(1)[        0.170] VERBOSE ziti-sdk:ziti_ctrl.c:131 start_request() ctrl[ziti-edge-controller] starting GET[/current-identity]
(1)[        0.170] VERBOSE ziti-sdk:ziti.c:1221 ziti_services_refresh() ztx[0] forcing service refresh
(1)[        0.170]   DEBUG ziti-sdk:ziti_ctrl.c:768 ctrl_paging_req() ctrl[ziti-edge-controller] starting paging request GET[/current-identity/edge-routers]
(1)[        0.170] VERBOSE ziti-sdk:ziti_ctrl.c:773 ctrl_paging_req() ctrl[ziti-edge-controller] requesting /current-identity/edge-routers?limit=25&offset=0
(1)[        0.170] VERBOSE ziti-sdk:ziti_ctrl.c:131 start_request() ctrl[ziti-edge-controller] starting GET[/current-identity/edge-routers?limit=25&offset=0]
(1)[        0.170] VERBOSE ziti-sdk:ziti_ctrl.c:131 start_request() ctrl[ziti-edge-controller] starting GET[/current-api-session/service-updates]
(1)[        0.171] VERBOSE ziti-sdk:ziti_ctrl.c:166 ctrl_resp_cb() ctrl[ziti-edge-controller] received headers GET[/current-identity]
(1)[        0.171]   DEBUG ziti-sdk:ziti_ctrl.c:322 ctrl_body_cb() ctrl[ziti-edge-controller] completed GET[/current-identity] in 0.001 s
(1)[        0.172] VERBOSE ziti-sdk:ziti_ctrl.c:166 ctrl_resp_cb() ctrl[ziti-edge-controller] received headers GET[/current-identity]
(1)[        0.172]   DEBUG ziti-sdk:ziti_ctrl.c:322 ctrl_body_cb() ctrl[ziti-edge-controller] completed GET[/current-identity] in 0.002 s
(1)[        0.173] VERBOSE ziti-sdk:ziti_ctrl.c:166 ctrl_resp_cb() ctrl[ziti-edge-controller] received headers GET[/current-identity/edge-routers?limit=25&offset=0]
(1)[        0.173]   DEBUG ziti-sdk:ziti_ctrl.c:322 ctrl_body_cb() ctrl[ziti-edge-controller] completed GET[/current-identity/edge-routers?limit=25&offset=0] in 0.003 s
(1)[        0.173]   DEBUG ziti-sdk:ziti_ctrl.c:338 ctrl_body_cb() ctrl[ziti-edge-controller] received 2/2 for paging request GET[/current-identity/edge-routers]
(1)[        0.173]   DEBUG ziti-sdk:ziti_ctrl.c:350 ctrl_body_cb() ctrl[ziti-edge-controller] completed paging request GET[/current-identity/edge-routers] in 0.003 s
(1)[        0.173]    INFO ziti-sdk:channel.c:231 new_ziti_channel() ch[0] (ziti-edge-router-1@tls://ziti-edge-router-1:3022) new channel for ztx[0] identity[client]
[        0.052] INFO    ziti-sdk-nodejs/src/ziti_init.c:247 on_ziti_event(): edge router ziti-edge-router-1@tls://ziti-edge-router-1:3022 was added
(1)[        0.173]    INFO ziti-sdk:channel.c:742 reconnect_channel() ch[0] reconnecting NOW
(1)[        0.173]    INFO ziti-sdk:channel.c:231 new_ziti_channel() ch[1] (ziti-edge-router-2@tls://ziti-edge-router-2:3022) new channel for ztx[0] identity[client]
[        0.052] INFO    ziti-sdk-nodejs/src/ziti_init.c:247 on_ziti_event(): edge router ziti-edge-router-2@tls://ziti-edge-router-2:3022 was added
(1)[        0.173]    INFO ziti-sdk:channel.c:742 reconnect_channel() ch[1] reconnecting NOW
(1)[        0.173]   DEBUG ziti-sdk:channel.c:713 reconnect_cb() ch[0] connecting to ziti-edge-router-1:3022
(1)[        0.173]   DEBUG ziti-sdk:channel.c:713 reconnect_cb() ch[1] connecting to ziti-edge-router-2:3022
(1)[        0.174] VERBOSE ziti-sdk:ziti_ctrl.c:166 ctrl_resp_cb() ctrl[ziti-edge-controller] received headers GET[/current-api-session/service-updates]
(1)[        0.174]   DEBUG ziti-sdk:ziti_ctrl.c:322 ctrl_body_cb() ctrl[ziti-edge-controller] completed GET[/current-api-session/service-updates] in 0.003 s
(1)[        0.174] VERBOSE ziti-sdk:ziti.c:1181 check_service_update() ztx[0] ztx last_update = 2023-11-03T15:35:11.435Z
(1)[        0.174]   DEBUG ziti-sdk:ziti_ctrl.c:768 ctrl_paging_req() ctrl[ziti-edge-controller] starting paging request GET[/services]
(1)[        0.174] VERBOSE ziti-sdk:ziti_ctrl.c:773 ctrl_paging_req() ctrl[ziti-edge-controller] requesting /services?limit=25&offset=0
(1)[        0.174] VERBOSE ziti-sdk:ziti_ctrl.c:131 start_request() ctrl[ziti-edge-controller] starting GET[/services?limit=25&offset=0]
(1)[        0.175] VERBOSE ziti-sdk:ziti_ctrl.c:166 ctrl_resp_cb() ctrl[ziti-edge-controller] received headers GET[/services?limit=25&offset=0]
(1)[        0.175]   DEBUG ziti-sdk:ziti_ctrl.c:322 ctrl_body_cb() ctrl[ziti-edge-controller] completed GET[/services?limit=25&offset=0] in 0.000 s
(1)[        0.175]   DEBUG ziti-sdk:ziti_ctrl.c:338 ctrl_body_cb() ctrl[ziti-edge-controller] received 2/2 for paging request GET[/services]
(1)[        0.175]   DEBUG ziti-sdk:ziti_ctrl.c:350 ctrl_body_cb() ctrl[ziti-edge-controller] completed paging request GET[/services] in 0.000 s
(1)[        0.175] VERBOSE ziti-sdk:ziti.c:1223 ziti_services_refresh() ztx[0] scheduling service refresh 60 seconds from now
(1)[        0.175] VERBOSE ziti-sdk:ziti.c:1051 update_services() ztx[0] processing service updates
(1)[        0.175]   DEBUG ziti-sdk:ziti.c:1128 update_services() ztx[0] sending service event 2 added, 0 removed, 0 changed
[        0.053] DEBUG   ziti-sdk-nodejs/src/Ziti_https_request.c:244 track_service_to_hostname(): track_service_to_hostname() entered, service_name: test-service hostname: test-ui.ziti port: 80
[        0.053] DEBUG   ziti-sdk-nodejs/src/Ziti_https_request.c:219 getHostnamePortForService(): getHostnamePortForService() entered, key: test-service
[        0.054] DEBUG   ziti-sdk-nodejs/src/Ziti_https_request.c:233 getHostnamePortForService(): getHostnamePortForService() returning value '(nil)'
[        0.054] DEBUG   ziti-sdk-nodejs/src/Ziti_https_request.c:67 listMapInsert(): collection->count total is: [1]
[        0.054] DEBUG   ziti-sdk-nodejs/src/Ziti_https_request.c:260 track_service_to_hostname(): track_service_to_hostname() inserting service_name: test-service hostname: test-ui.ziti port: 80
[        0.054] DEBUG   ziti-sdk-nodejs/src/Ziti_https_request.c:244 track_service_to_hostname(): track_service_to_hostname() entered, service_name: test-service hostname: test-ui.ziti port: 10
[        0.054] DEBUG   ziti-sdk-nodejs/src/Ziti_https_request.c:219 getHostnamePortForService(): getHostnamePortForService() entered, key: test-service
[        0.054] DEBUG   ziti-sdk-nodejs/src/Ziti_https_request.c:228 getHostnamePortForService(): getHostnamePortForService() found value->hostname is: [test-ui.ziti], port is: [80]
[        0.054] DEBUG   ziti-sdk-nodejs/src/Ziti_https_request.c:233 getHostnamePortForService(): getHostnamePortForService() returning value '0x60d9090'
[        0.054] DEBUG   ziti-sdk-nodejs/src/Ziti_https_request.c:267 track_service_to_hostname(): track_service_to_hostname() updating service_name: test-service hostname: test-ui.ziti port: 10
[        0.054] DEBUG   ziti-sdk-nodejs/src/ziti_init.c:221 on_ziti_event(): addon_data->on_init_cb_invoked 0
[        0.054] DEBUG   ziti-sdk-nodejs/src/Ziti_https_request.c:747 _Ziti_http_request(): entered
[        0.054] DEBUG   ziti-sdk-nodejs/src/Ziti_https_request.c:767 _Ziti_http_request(): allocated addon_data : 0x60e20b0
[        0.054] DEBUG   ziti-sdk-nodejs/src/Ziti_https_request.c:776 _Ziti_http_request(): serviceName is specified
[        0.054] DEBUG   ziti-sdk-nodejs/src/Ziti_https_request.c:219 getHostnamePortForService(): getHostnamePortForService() entered, key: client-server
[        0.054] DEBUG   ziti-sdk-nodejs/src/Ziti_https_request.c:233 getHostnamePortForService(): getHostnamePortForService() returning value '(nil)'
Ziti error: Error: Unknown serviceName - (tried client-server)
http server running on port 4000
Catalogue loaded
(1)[        0.189]   DEBUG ziti-sdk:channel.c:861 on_channel_connect_internal() ch[1] connected
(1)[        0.196]   DEBUG ziti-sdk:channel.c:861 on_channel_connect_internal() ch[0] connected
(1)[        0.202]    INFO ziti-sdk:channel.c:640 hello_reply_cb() ch[1] connected. EdgeRouter version: v0.30.5|4f324bd22875|2023-10-13T20:22:56Z|linux|amd64
[        0.081] INFO    ziti-sdk-nodejs/src/ziti_init.c:235 on_ziti_event(): ziti connected to edge router ziti-edge-router-2@tls://ziti-edge-router-2:3022
version = v0.30.5|4f324bd22875|2023-10-13T20:22:56Z|linux|amd64
(1)[        0.204]    INFO ziti-sdk:channel.c:640 hello_reply_cb() ch[0] connected. EdgeRouter version: v0.30.5|4f324bd22875|2023-10-13T20:22:56Z|linux|amd64
[        0.083] INFO    ziti-sdk-nodejs/src/ziti_init.c:235 on_ziti_event(): ziti connected to edge router ziti-edge-router-1@tls://ziti-edge-router-1:3022
version = v0.30.5|4f324bd22875|2023-10-13T20:22:56Z|linux|amd64
(1)[        1.171] VERBOSE ziti-sdk:posture.c:198 ziti_send_posture_data() ztx[0] starting to send posture data
(1)[        1.171]    INFO ziti-sdk:posture.c:204 ziti_send_posture_data() ztx[0] first run or potential controller restart detected
(1)[        1.171]   DEBUG ziti-sdk:posture.c:208 ziti_send_posture_data() ztx[0] posture checks must_send set to TRUE, new_session_id[TRUE], must_send_every_time[TRUE], new_controller_instance[TRUE]
(1)[        1.171] VERBOSE ziti-sdk:posture.c:236 ziti_send_posture_data() ztx[0] checking posture queries on 2 service(s)
(1)[        1.171]   DEBUG ziti-sdk:posture.c:535 ziti_pr_send_bulk() ztx[0] no change in posture data, not sending

Example 2

When Example 1 didn't work we then changed the code to see if a timeout between the initialisation and the request would help. This didn't change the outcome, but the logs (removed for brevity) did show an extra 10s of background fabric logs before the same error, so it's definitely not that the service hasn't yet been added to the map of hostnames/ports.

Code

const app = express();

const zitiServiceName = 'client-server';

ziti.setLogLevel(5);

function onResponse(obj) {
	console.log(`response is: ${obj.body.toString('utf8')}`);
}

async function zitiConnect() {
	console.log('Initialising Ziti');
	return ziti.init(`${rootname}/service/jwt.json`).catch(( err ) => { console.error(err) });	
}

function zitiRequest(status, serviceName) {

	console.log(`Connection status is ${status}. Attempting request...`);

	try {
		ziti.httpRequest(
	
			// OpenZiti Service name or HTTP origin part of the URL
			serviceName,
		
			// port - don't need both port and service name
			undefined,
		
			'GET',
		
			// path part of the URL including query params
			'/health',
		
			// headers
			['Accept: application/json' ],
		
			// optional on_req cb
			undefined, 
		
			// optional on_req_data cb
			undefined,
		
			// optional on_resp_data cb
			onResponse
		);	
	} catch (err) {
		console.error(`Ziti error: ${err} - (tried ${serviceName})`);
	}
	
}

(async () => {
	const status = await zitiConnect();
	console.log('Attempting request in 10 seconds...');
	setTimeout(zitiRequest, 1000 * 10, status, zitiServiceName);
})();

The track_service_to_hostname function is called whenever a service event fires, and we see 2 services are to be added, however it seems to just add the test-service, then add it again but update it to the wrong port. This may well be the "smoking gun", but we can't find anything wrong with the client-server service configuration. It was setup pretty much identically to the test-service, albeit with new intercept/host configs and different identity/service roles.

Hi @Coconutcoo . Stand by. We are looking into this.

@Coconutcoo version 0.14.1 of the SDK has just been published. I fixed some issues related to exceptions/crashes when certain (optional) parms were specified as undefined. This is what I believe your crashes were while you tried the 0.14.0 release. Give the latest release a try, and let us know if things are now resolved for you.