WIP: Add logging to debug Send step failures

package.json

@@ -73,6 +73,7 @@
   },
   "dependencies": {
     "@graphql-tools/utils": "^8.8.0",
+    "@httptoolkit/util": "^0.1.1",
     "@types/lodash": "^4.14.182",
     "@types/sdp-transform": "^2.4.5",
     "graphql": "^15.8.0",

src/handling/handler-steps.ts

@@ -152,6 +152,7 @@ export class SendStep extends SendStepDefinition {
             .filter((channel) => this.matchesChannel(channel))
             .map((channel) => {
                 return new Promise<void>((resolve, reject) => {
+                    console.log('Channel Send', this.message.toString('utf8'));
                     channel.write(this.message, (error: Error | null | undefined) => {
                         if (error) reject(error);
                         else resolve();

src/server/mockrtc-server-peer.ts

@@ -25,6 +25,7 @@ import { MockRTCConnection } from '../webrtc/mockrtc-connection';
 import { DataChannelStream } from '../webrtc/datachannel-stream';
 import { MediaTrackStream } from '../webrtc/mediatrack-stream';
 import { TimingEvents } from '../mockrtc';
+import { delay } from '@httptoolkit/util';
 
 export class MockRTCServerPeer implements MockRTCPeer {
 
@@ -314,7 +315,11 @@ export class MockRTCServerPeer implements MockRTCPeer {
             await step.handle(conn);
         }
 
+        console.log('All steps handled');
+        await delay(10);
+        console.log('Now closing');
         await conn.close();
+        console.log('Connection closed');
     }
 
     async close() {

test/integration/echo-steps.spec.ts

@@ -38,10 +38,10 @@ describe("Echo steps", function () {
         const dataChannel2 = localConnection.createDataChannel("dataChannel2");
         dataChannel2.addEventListener('message', (event) => messages.push("2: " + event.data));
         await waitForChannelOpen(dataChannel2);
-        await delay(10); // Delay to guarantee ordering
+        await delay(50); // Delay to guarantee ordering
         dataChannel2.send('Test message 2');
 
-        await delay(10); // Delay to guarantee ordering
+        await delay(50); // Delay to guarantee ordering
         dataChannel1.send('Test message 3');
 
         await delay(50); // Delay to guarantee delivery

test/integration/proxy.spec.ts

@@ -11,7 +11,8 @@ import {
     waitForChannelClose,
     waitForState,
     setupPerfectNegotiation,
-    getDeferred
+    getDeferred,
+    delay
 } from '../test-setup';
 
 describe("When proxying WebRTC traffic", () => {
@@ -150,7 +151,9 @@ describe("When proxying WebRTC traffic", () => {
         await new Promise<void>((resolve) => dataChannel.onopen = () => resolve());
 
         dataChannel.send('local message 1');
+        await delay(1);
         dataChannel.send('local message 2');
+        await delay(1);
         dataChannel.send('local message 3');
 
         await new Promise((resolve) => dataChannel.addEventListener('close', resolve));

test/integration/send-steps.spec.ts

@@ -5,6 +5,7 @@
 
 import {
     MockRTC,
+    delay,
     expect,
     waitForChannelClose
 } from '../test-setup';
@@ -33,11 +34,19 @@ describe("Send steps", function () {
 
         // Wait for a response:
         let messages: Array<any> = [];
-        dataChannel1.addEventListener('message', (event) => messages.push("1: " + event.data));
-        dataChannel2.addEventListener('message', (event) => messages.push("2: " + event.data));
+        dataChannel1.addEventListener('message', (event) => {
+            console.log('dc1 got message');
+            messages.push("1: " + event.data);
+        });
+        dataChannel2.addEventListener('message', (event) => {
+            console.log('dc2 got message');
+            messages.push("2: " + event.data);
+        });
 
         await waitForChannelClose(dataChannel1);
 
+        await delay(500);
+
         expect(messages).to.deep.equal([
             '1: Hello and goodbye',
             '2: Hello and goodbye',
@@ -114,11 +123,14 @@ describe("Send steps", function () {
         // Wait for a response:
         let messages: Array<any> = [];
         dataChannel1.addEventListener('message', (event) => {
+            console.log('got message', event.data);
             messages.push(Buffer.from(event.data)); // ArrayBuffer -> node Buffer
         });
 
         await waitForChannelClose(dataChannel1);
 
+        await delay(500);
+
         expect(messages.map(m => m.toString('utf8'))).to.deep.equal([
             'Hello from buffer'
         ]);