fix: improve portfinder usage (#9366)

- Ensure we use the latest `portfinder` version available
- Adjust default start port for every portfinder call, so if two calls happen simultaneously, they don't try to acquire the same port
- Add logging for portfinder errors and port used before listening
- If portfinder fails, try using preferred port, letting listen to fail and provide more sensible error

Composer/packages/server/package.json

@@ -116,7 +116,7 @@
     "node-fetch": "2.6.1",
     "passport": "^0.4.1",
     "path-to-regexp": "^6.1.0",
-    "portfinder": "^1.0.28",
+    "portfinder": "^1.0.32",
     "rimraf": "3.0.2",
     "rsa-pem-from-mod-exp": "^0.8.4",
     "tar": "^6.0.5",

Composer/packages/server/src/directline/utils/webSocketServer.ts

@@ -80,8 +80,13 @@ export class WebSocketServer {
         const res = new http.ServerResponse(req);
         return app(req, res as Response);
       });
-      const port = await portfinder.getPortPromise();
+      const preferredPort = 7000;
+      const port = await portfinder.getPortPromise().catch((err) => {
+        log(`Unable to find an open port for directline (wanted ${preferredPort}): ${err}`);
+        return preferredPort;
+      });
       this.port = port;
+      log(`Using ${port} port for directline`);
       this.restServer.listen(port);
 
       app.use('/ws/conversation/:conversationId', (req: express.Request, res: express.Response) => {

Composer/packages/server/src/locales/en-US.json

@@ -3686,6 +3686,12 @@
   "sorted_a_to_z_915b2ed3": {
     "message": "Sorted A to Z"
   },
+  "sorted_ascending_a1e96e3a": {
+    "message": "Sorted ascending"
+  },
+  "sorted_descending_3093c22f": {
+    "message": "Sorted descending"
+  },
   "sorted_z_to_a_722f1567": {
     "message": "Sorted Z to A"
   },

Composer/packages/server/src/server.ts

@@ -141,8 +141,12 @@ export async function start(electronContext?: ElectronContext): Promise<number |
     // Dynamically search for an open PORT starting with PORT or 5000, so that
     // the app doesn't crash if the port is already being used.
     // (disabled in dev in order to avoid breaking the webpack dev server proxy)
-    port = await portfinder.getPortPromise({ port: preferredPort });
+    port = await portfinder.getPortPromise({ port: preferredPort }).catch((err) => {
+      log(`Unable to find an open port for server (wanted ${preferredPort}): ${err}`);
+      return preferredPort;
+    });
   }
+  log(`Using ${port} port for server`);
 
   // Setup directline and conversation routes for v3 bots
   const DLServerState = DLServerContext.getInstance(port);

Composer/yarn-berry.lock

@@ -4212,7 +4212,7 @@ __metadata:
     nodemon: ^2.0.3
     passport: ^0.4.1
     path-to-regexp: ^6.1.0
-    portfinder: ^1.0.28
+    portfinder: ^1.0.32
     prettier: 2.0.5
     rimraf: 3.0.2
     rsa-pem-from-mod-exp: ^0.8.4
@@ -9072,7 +9072,7 @@ __metadata:
   languageName: node
   linkType: hard
 
-"async@npm:^2.5.0, async@npm:^2.6.2":
+"async@npm:^2.5.0, async@npm:^2.6.2, async@npm:^2.6.4":
   version: 2.6.4
   resolution: "async@npm:2.6.4"
   dependencies:
@@ -22980,7 +22980,7 @@ __metadata:
   languageName: node
   linkType: hard
 
-"portfinder@npm:^1.0.26, portfinder@npm:^1.0.28":
+"portfinder@npm:^1.0.26":
   version: 1.0.28
   resolution: "portfinder@npm:1.0.28"
   dependencies:
@@ -22991,6 +22991,17 @@ __metadata:
   languageName: node
   linkType: hard
 
+"portfinder@npm:^1.0.32":
+  version: 1.0.32
+  resolution: "portfinder@npm:1.0.32"
+  dependencies:
+    async: ^2.6.4
+    debug: ^3.2.7
+    mkdirp: ^0.5.6
+  checksum: 116b4aed1b9e16f6d5503823d966d9ffd41b1c2339e27f54c06cd2f3015a9d8ef53e2a53b57bc0a25af0885977b692007353aa28f9a0a98a44335cb50487240d
+  languageName: node
+  linkType: hard
+
 "posix-character-classes@npm:^0.1.0":
   version: 0.1.1
   resolution: "posix-character-classes@npm:0.1.1"

extensions/azurePublish/yarn-berry.lock

@@ -1879,7 +1879,7 @@ __metadata:
 
 "@bfc/code-editor@file:../../Composer/packages/lib/code-editor::locator=azurePublish%40workspace%3A.":
   version: 0.0.0
-  resolution: "@bfc/code-editor@file:../../Composer/packages/lib/code-editor#../../Composer/packages/lib/code-editor::hash=b95663&locator=azurePublish%40workspace%3A."
+  resolution: "@bfc/code-editor@file:../../Composer/packages/lib/code-editor#../../Composer/packages/lib/code-editor::hash=14c2ca&locator=azurePublish%40workspace%3A."
   dependencies:
     "@emotion/react": ^11.1.3
     "@emotion/styled": ^11.1.3
@@ -1902,7 +1902,7 @@ __metadata:
     "@bfc/ui-shared": "*"
     react: 16.13.1
     react-dom: 16.13.1
-  checksum: d50192370950e7a5d11dc16625f70c88b70df4400e665978d7ac9be33e37897de3dd5107f0a87871e42ca3b9212ae7907f892fbe14e122d815b8e892041d26da
+  checksum: b81b6db7a4d65ab86ba4ef1b08854672c13310f6b5292b8c361b162f438a8b2aa0a0e5dfde903ef90e223ab89970c2141cc57f7fae1e02dc2d5e17fcbf0e7dd1
   languageName: node
   linkType: hard
 

extensions/localPublish/package.json

@@ -15,7 +15,7 @@
     "kill-port": "2.0.1",
     "lodash": "4.17.21",
     "path": "0.12.7",
-    "portfinder": "1.0.28",
+    "portfinder": "^1.0.32",
     "tcp-port-used": "1.0.2",
     "uuid": "8.3.2",
     "ws": "8.8.0"
@@ -25,6 +25,7 @@
     "bl": "^4.0.3"
   },
   "devDependencies": {
+    "@types/debug": "4.1.7",
     "@types/express": "4.17.13",
     "@types/lodash": "4.14.182",
     "@types/node": "18.0.3",

extensions/localPublish/src/index.ts

@@ -139,9 +139,14 @@ class LocalPublisher implements PublishPlugin<PublishConfig> {
         const retry = 10;
         let i = 0;
         do {
-          port = await portfinder.getPortPromise({ port: maxPort + 1, stopPort: 6000 });
+          const preferredPort = maxPort + 1;
+          port = await portfinder.getPortPromise({ port: preferredPort, stopPort: 6000 }).catch((err) => {
+            this.composer.log(`Unable to find an open port for ${this.name} (wanted ${preferredPort}): ${err}`);
+            return preferredPort;
+          });
           i++;
         } while (this.isPortUsed(port) && i < retry);
+        this.composer.log(`Using ${port} port for ${this.name}`);
 
         const updatedBotData: RunningBot = {
           ...LocalPublisher.runningBots[botId],
@@ -239,7 +244,9 @@ class LocalPublisher implements PublishPlugin<PublishConfig> {
   };
 
   setupRuntimeLogServer = async (projectId: string) => {
-    await RuntimeLogServer.init();
+    await RuntimeLogServer.init({
+      log: this.composer.log,
+    });
     return RuntimeLogServer.getRuntimeLogStreamingUrl(projectId);
   };
 

extensions/localPublish/src/runtimeLogServer.ts

@@ -6,6 +6,7 @@ import http from 'http';
 import portfinder from 'portfinder';
 import express, { Request, Response } from 'express';
 import { Server as WSServer } from 'ws';
+import { Debugger } from 'debug';
 
 interface WebSocket {
   close(): void;
@@ -22,7 +23,7 @@ export class RuntimeLogServer {
     return `ws://localhost:${this.port}/ws/runtimeLog/${projectId}`;
   }
 
-  public static async init(): Promise<number | void> {
+  public static async init({ log }: { log: Debugger }): Promise<number | void> {
     if (!this.restServer) {
       const app = express();
       this.restServer = http.createServer(app);
@@ -35,7 +36,12 @@ export class RuntimeLogServer {
         const res: any = new http.ServerResponse(req);
         return app(req, res);
       });
-      const port = await portfinder.getPortPromise();
+      const preferredPort = 8001;
+      const port = await portfinder.getPortPromise({ port: preferredPort }).catch((err) => {
+        log(`Unable to find an open port for runtime-log (wanted ${preferredPort}): ${err}`);
+        return preferredPort;
+      });
+      log(`Using ${port} port for runtime-log`);
       this.restServer.listen(port);
 
       app.use('/ws/runtimeLog/:projectId', (req: Request, res: Response) => {

extensions/localPublish/yarn-berry.lock

@@ -39,6 +39,15 @@ __metadata:
   languageName: node
   linkType: hard
 
+"@types/debug@npm:4.1.7":
+  version: 4.1.7
+  resolution: "@types/debug@npm:4.1.7"
+  dependencies:
+    "@types/ms": "*"
+  checksum: 0a7b89d8ed72526858f0b61c6fd81f477853e8c4415bb97f48b1b5545248d2ae389931680b94b393b993a7cfe893537a200647d93defe6d87159b96812305adc
+  languageName: node
+  linkType: hard
+
 "@types/express-serve-static-core@npm:*, @types/express-serve-static-core@npm:^4.17.18":
   version: 4.17.28
   resolution: "@types/express-serve-static-core@npm:4.17.28"
@@ -104,6 +113,13 @@ __metadata:
   languageName: node
   linkType: hard
 
+"@types/ms@npm:*":
+  version: 0.7.31
+  resolution: "@types/ms@npm:0.7.31"
+  checksum: daadd354aedde024cce6f5aa873fefe7b71b22cd0e28632a69e8b677aeb48ae8caa1c60e5919bb781df040d116b01cb4316335167a3fc0ef6a63fa3614c0f6da
+  languageName: node
+  linkType: hard
+
 "@types/node@npm:*":
   version: 17.0.10
   resolution: "@types/node@npm:17.0.10"
@@ -185,7 +201,7 @@ __metadata:
   languageName: node
   linkType: hard
 
-"async@npm:^2.6.2":
+"async@npm:^2.6.4":
   version: 2.6.4
   resolution: "async@npm:2.6.4"
   dependencies:
@@ -301,7 +317,7 @@ __metadata:
   languageName: node
   linkType: hard
 
-"debug@npm:^3.1.1":
+"debug@npm:^3.2.7":
   version: 3.2.7
   resolution: "debug@npm:3.2.7"
   dependencies:
@@ -577,6 +593,7 @@ __metadata:
   resolution: "localpublish@workspace:."
   dependencies:
     "@botframework-composer/types": "file:../../Composer/packages/types"
+    "@types/debug": 4.1.7
     "@types/express": 4.17.13
     "@types/lodash": 4.14.182
     "@types/node": 18.0.3
@@ -586,7 +603,7 @@ __metadata:
     kill-port: 2.0.1
     lodash: 4.17.21
     path: 0.12.7
-    portfinder: 1.0.28
+    portfinder: ^1.0.32
     tcp-port-used: 1.0.2
     uuid: 8.3.2
     ws: 8.8.0
@@ -662,21 +679,21 @@ __metadata:
   languageName: node
   linkType: hard
 
-"minimist@npm:^1.2.5":
+"minimist@npm:^1.2.6":
   version: 1.2.6
   resolution: "minimist@npm:1.2.6"
   checksum: d15428cd1e11eb14e1233bcfb88ae07ed7a147de251441d61158619dfb32c4d7e9061d09cab4825fdee18ecd6fce323228c8c47b5ba7cd20af378ca4048fb3fb
   languageName: node
   linkType: hard
 
-"mkdirp@npm:^0.5.5":
-  version: 0.5.5
-  resolution: "mkdirp@npm:0.5.5"
+"mkdirp@npm:^0.5.6":
+  version: 0.5.6
+  resolution: "mkdirp@npm:0.5.6"
   dependencies:
-    minimist: ^1.2.5
+    minimist: ^1.2.6
   bin:
     mkdirp: bin/cmd.js
-  checksum: 3bce20ea525f9477befe458ab85284b0b66c8dc3812f94155af07c827175948cdd8114852ac6c6d82009b13c1048c37f6d98743eb019651ee25c39acc8aabe7d
+  checksum: 0c91b721bb12c3f9af4b77ebf73604baf350e64d80df91754dc509491ae93bf238581e59c7188360cec7cb62fc4100959245a42cfe01834efedc5e9d068376c2
   languageName: node
   linkType: hard
 
@@ -748,14 +765,14 @@ __metadata:
   languageName: node
   linkType: hard
 
-"portfinder@npm:1.0.28":
-  version: 1.0.28
-  resolution: "portfinder@npm:1.0.28"
+"portfinder@npm:^1.0.32":
+  version: 1.0.32
+  resolution: "portfinder@npm:1.0.32"
   dependencies:
-    async: ^2.6.2
-    debug: ^3.1.1
-    mkdirp: ^0.5.5
-  checksum: 91fef602f13f8f4c64385d0ad2a36cc9dc6be0b8d10a2628ee2c3c7b9917ab4fefb458815b82cea2abf4b785cd11c9b4e2d917ac6fa06f14b6fa880ca8f8928c
+    async: ^2.6.4
+    debug: ^3.2.7
+    mkdirp: ^0.5.6
+  checksum: 116b4aed1b9e16f6d5503823d966d9ffd41b1c2339e27f54c06cd2f3015a9d8ef53e2a53b57bc0a25af0885977b692007353aa28f9a0a98a44335cb50487240d
   languageName: node
   linkType: hard