versatica / mediasoup

Cutting Edge WebRTC Video Conferencing
https://mediasoup.org
ISC License
6.18k stars 1.12k forks source link

test-PipeTransport.ts randomly fails #1374

Closed ibc closed 3 months ago

ibc commented 5 months ago

As shown in CI: https://github.com/versatica/mediasoup/actions/runs/8619867847/job/23625492760?pr=1373

FAIL node/src/test/test-PipeTransport.ts (6.443 s)
  ✓ router.pipeToRouter() succeeds with audio (434 ms)
  ✓ router.pipeToRouter() succeeds with video (313 ms)
  ✓ router.createPipeTransport() with wrong arguments rejects with TypeError (380 ms)
  ✓ router.createPipeTransport() with enableRtx succeeds (295 ms)
  ✓ pipeTransport.connect() with valid SRTP parameters succeeds (348 ms)
  ✓ pipeTransport.connect() with srtpParameters fails if enableSrtp is unset (435 ms)
  ✓ pipeTransport.connect() with invalid srtpParameters fails (342 ms)
  ✓ router.createPipeTransport() with fixed port succeeds (314 ms)
  ✓ transport.consume() for a pipe Producer succeeds ([39](https://github.com/versatica/mediasoup/actions/runs/8619867847/job/23625492760?pr=1373#step:7:40)9 ms)
  ✕ producer.pause() and producer.resume() are transmitted to pipe Consumer ([40](https://github.com/versatica/mediasoup/actions/runs/8619867847/job/23625492760?pr=1373#step:7:41)6 ms)
  ✓ producer.close() is transmitted to pipe Consumer (394 ms)
  ✓ router.pipeToRouter() fails if both Routers belong to the same Worker (370 ms)
  ✓ router.pipeToRouter() succeeds with data (367 ms)
  ✓ transport.dataConsume() for a pipe DataProducer succeeds (387 ms)
  ✓ dataProducer.close() is transmitted to pipe DataConsumer (366 ms)
  ✓ router.pipeToRouter() called twice generates a single PipeTransport pair (380 ms)
  ✓ router.pipeToRouter() called in two Routers passing one to each other as argument generates a single a single PipeTransport pair (371 ms)

  ● producer.pause() and producer.resume() are transmitted to pipe Consumer

    InvalidStateError: Channel closed, pending request aborted [method:PRODUCER_PAUSE, id:8]

      392 |                 close: () => {
      393 |                     pReject(
    > 394 |                         new InvalidStateError(
          |                         ^
      395 |                             `Channel closed, pending request aborted [method:${Method[method]}, id:${id}]`
      396 |                         )
      397 |                     );

      at Object.close (node/src/Channel.ts:394:7)
      at Channel.close (node/src/Channel.ts:218:9)
      at Worker.close (node/src/Worker.ts:584:17)
      at node/src/test/test-PipeTransport.ts:201:15
      at node/src/test/test-PipeTransport.ts:8:71
      at Object.<anonymous>.__awaiter (node/src/test/test-PipeTransport.ts:4:12)
      at Object.<anonymous> (node/src/test/test-PipeTransport.ts:199:22)

Note that we already had these kind of errors in the past and, in same cases, they were produced by other tests that were still running code once completed.

ibc commented 5 months ago

I've taken a look to all tests in which we call producer.pause() and AFAIS everything is ok, but the issue still exists.

ibc commented 5 months ago

Here another unrelated PR in which same test is failing:

https://github.com/versatica/mediasoup/actions/runs/8788437337/job/24115870840?pr=1380#step:7:60

satoren commented 3 months ago

https://github.com/versatica/mediasoup/blob/0cb131cd3d1dc95cc09ee6e82dc556d8f4822117/node/src/Router.ts#L1265 The error seems to occur if the test ends without waiting for this pause promise to fully complete. This is more likely to occur in slow running environments. It seems possible to work around this by delaying the completion of the test a bit, but I think the correct approach is to wait for this completion if possible.

ibc commented 3 months ago

https://github.com/versatica/mediasoup/blob/0cb131cd3d1dc95cc09ee6e82dc556d8f4822117/node/src/Router.ts#L1265

The error seems to occur if the test ends without waiting for this pause promise to fully complete. This is more likely to occur in slow running environments. It seems possible to work around this by delaying the completion of the test a bit, but I think the correct approach is to wait for this completion if possible.

Very good point! And the issue is reproducible locally doing this change:

diff --git a/node/src/Router.ts b/node/src/Router.ts
index c60476805..33dfc343a 100644
--- a/node/src/Router.ts
+++ b/node/src/Router.ts
@@ -1262,9 +1262,15 @@ export class Router<

                // Pipe events from the pipe Consumer to the pipe Producer.
                pipeConsumer!.observer.on('close', () => pipeProducer!.close());
-               pipeConsumer!.observer.on('pause', () => pipeProducer!.pause());
-               pipeConsumer!.observer.on('resume', () => pipeProducer!.resume());
-
+               console.log('UNCOMMENT AND REMOVE');
+               // pipeConsumer!.observer.on('pause', () => pipeProducer!.pause());
+               pipeConsumer!.observer.on('pause', () =>
+                   setTimeout(() => pipeProducer!.pause(), 1000)
+               );
+               // pipeConsumer!.observer.on('resume', () => pipeProducer!.resume());
+               pipeConsumer!.observer.on('resume', () =>
+                   setTimeout(() => pipeProducer!.resume(), 1000)
+               );
                // Pipe events from the pipe Producer to the pipe Consumer.
                pipeProducer.observer.on('close', () => pipeConsumer!.close());

and then:

npx jest --testPathPattern node/src/test/test-PipeTransport.ts
ibc commented 3 months ago

Fixed here: https://github.com/versatica/mediasoup/commit/dedfb24a6a5c5c25ee91744b10bc426e3dbdf5cc

Thanks @satoren!