BUG: FetchError: network timeout (maybe Notification Queue Two only)

theimo1221 commented 2 years ago

What happened

Switching my enviroment from meteor to express I now have some fetch-timeouts which crash the whole process. I'll look into this more deeply.

What did you expect to happen

Exceptions should be handled in a way to not interrupt the outer process.

Debug logging

2021-12-02 09:52:08.543: FetchError: network timeout at: http://xxxxx:1400/MediaRenderer/AVTransport/Control
2021-12-02 09:52:08.543:     at Timeout.<anonymous> (C:\xxxxx\node_modules\@svrooij\sonos\node_modules\node-fetch\lib\index.js:1476:13)
2021-12-02 09:52:08.543:     at listOnTimeout (node:internal/timers:557:17)
2021-12-02 09:52:08.543:     at processTimers (node:internal/timers:500:7) {
2021-12-02 09:52:08.543:   type: 'request-timeout'
2021-12-02 09:52:08.543: }

Environment

sonos-ts version: 2.4.1
OS: Windows 10
node version (node -v): v16.13.0

Checklist

Please confirm the following before creating the issue.

[x] Environment specified
[x] Checked issues for duplicates
[x] Debug log added

theimo1221 commented 2 years ago

As the mentioned error occurs only sporadically I enabled full logging and will wait for some time, to see if it does occur again.

theimo1221 commented 2 years ago

2021-12-03 15:47:15.654: xxx\node_modules\@svrooij\sonos\lib\services\base-service.js:190
2021-12-03 15:47:15.654:             throw new Error(`Error handlingRequest to "${request.url}" Method:"${request.method}" \nReason: ${reason !== null && reason !== void 0 ? reason : 'Unkown reason'}`);
2021-12-03 15:47:15.654:                   ^
2021-12-03 15:47:15.654: 
2021-12-03 15:47:15.654: Error: Error handlingRequest to "http://xxx.43:1400/MediaRenderer/RenderingControl/Control" Method:"POST" 
2021-12-03 15:47:15.654: Reason: FetchError: network timeout at: http://xxx.43:1400/MediaRenderer/RenderingControl/Control
2021-12-03 15:47:15.654:     at RenderingControlService.handleRequest (xxx\node_modules\@svrooij\sonos\lib\services\base-service.js:190:19)
2021-12-03 15:47:15.654:     at runMicrotasks (<anonymous>)
2021-12-03 15:47:15.654:     at processTicksAndRejections (node:internal/process/task_queues:96:5)
2021-12-03 15:47:15.654:     at async RenderingControlService.SoapRequestWithBodyNoResponse (xxx\node_modules\@svrooij\sonos\lib\services\base-service.js:123:16)
2021-12-03 15:47:15.654:     at async RenderingControlService.SetVolume (xxx\node_modules\@svrooij\sonos\lib\services\rendering-control.service.js:116:37)
2021-12-03 15:47:15.654:     at async SonosDevice.playQueue (xxx\node_modules\@svrooij\sonos\lib\sonos-device.js:1096:13)
2021-12-03 15:47:15.654:     at async SonosDevice.startQueue (xxx\node_modules\@svrooij\sonos\lib\sonos-device.js:1249:9)
2021-12-03 17:25:45.442:

Got it 👍

Locally I adressed this and will report back, if it resolves the issue

Edit 1: Since yesterday the error did not occure again. Generally it seems theese errors mostly arises when I let several sonos speak the same message (not grouped).

svrooij commented 2 years ago

Exceptions should be handled in a way to not interrupt the outer process.

I don't agree with your statement. I think it absolutely should. That way you can process the exceptions the way you want. The only place where it sends multiple requests at once are in not generated code. And the only places I can think of are Notifications and possibly event subscriptions. That code is responsible for handling errors.

Like it's done here https://github.com/svrooij/node-sonos-ts/blob/a4abbca1fe4203bc9bcfa40d4e7ef9172ac1abd5/src/sonos-device.ts#L392-L400

Or in the sonos2mqtt library, it just uses a try catch in case something goes wrong. https://github.com/svrooij/sonos2mqtt/blob/20cab50852d1b24af28f139176172f14b3746914/src/sonos-to-mqtt.ts#L89-L109

This library throws an error if some request could not be completed. That is the idea behind throwing errors.

theimo1221 commented 2 years ago

Hi @svrooij,

thanks for your response.

Exceptions should be handled in a way to not interrupt the outer process.

This library throws an error if some request could not be completed. That is the idea behind throwing errors.

On having a second look my words weren't chosen carefully, I'm sorry for that.

I totally agree on your point regarding throwing errors to outside the library, so that the outer application can decide to either catch/handle it or stop/crash.

But this means, that all errors should be catchable from outside. This one isn't: To be more specific, following snippet handles the fetch().then() (inclusive afterwards handling !response.ok), but doesn't handle the fetch().then(...).catch(...): https://github.com/svrooij/node-sonos-ts/blob/25d4a6f8ae2c793768ff8af9f34af25a92720953/src/services/base-service.ts#L226-L232

Fetch itself has an timeout which throws that error but on a new thread (if not handled by a .catch()). This is one part which my PR adresses (adding catch handling to handleRequest), resulting in a new stacktrace like this:

2021-12-03 15:47:15.654: xxx\node_modules\@svrooij\sonos\lib\services\base-service.js:190
2021-12-03 15:47:15.654:             throw new Error(`Error handlingRequest to "${request.url}" Method:"${request.method}" \nReason: ${reason !== null && reason !== void 0 ? reason : 'Unkown reason'}`);
2021-12-03 15:47:15.654:                   ^
2021-12-03 15:47:15.654: 
2021-12-03 15:47:15.654: Error: Error handlingRequest to "http://xxx.43:1400/MediaRenderer/RenderingControl/Control" Method:"POST" 
2021-12-03 15:47:15.654: Reason: FetchError: network timeout at: http://xxx.43:1400/MediaRenderer/RenderingControl/Control
2021-12-03 15:47:15.654:     at RenderingControlService.handleRequest (xxx\node_modules\@svrooij\sonos\lib\services\base-service.js:190:19)
2021-12-03 15:47:15.654:     at runMicrotasks (<anonymous>)
2021-12-03 15:47:15.654:     at processTicksAndRejections (node:internal/process/task_queues:96:5)
2021-12-03 15:47:15.654:     at async RenderingControlService.SoapRequestWithBodyNoResponse (xxx\node_modules\@svrooij\sonos\lib\services\base-service.js:123:16)
2021-12-03 15:47:15.654:     at async RenderingControlService.SetVolume (xxx\node_modules\@svrooij\sonos\lib\services\rendering-control.service.js:116:37)
2021-12-03 15:47:15.654:     at async SonosDevice.playQueue (xxx\node_modules\@svrooij\sonos\lib\sonos-device.js:1096:13)
2021-12-03 15:47:15.654:     at async SonosDevice.startQueue (xxx\node_modules\@svrooij\sonos\lib\sonos-device.js:1249:9)
2021-12-03 17:25:45.442:

Additionally I added a new parameter for playing notification queue: catchQueueErrors?: boolean; which if set results in no errors bubbling up the stacktrace in case of queue playing.

The rest of my PR is improved error handling and debugging within the notification queue itself.

I hope this clarifies my changes and intention regarding this.

Thanks and best regards

Thiemo

svrooij commented 2 years ago

To my understanding this code either returns or throws.

 const response = await fetch(request);

A timeout is an error that is thrown. I'm able to catch those errors. They are not on a different thread. I've tested this by setting the timeout in the library to 1ms (everything started throwing timeouts).

My take on the library is that single requests just throw. But at points where the library executes multiple requests after each other (notifications) it should not make the application crash. With the PlayNotification method, you're able to catch the error from the outside, but that may also cancel out the restoring of the queue.

The problem lies in the fact that your notification solution disconnects the thread, as in starts a new thread to process the queue. I think I also mentioned this before, not sure though.

https://github.com/svrooij/node-sonos-ts/blob/a4abbca1fe4203bc9bcfa40d4e7ef9172ac1abd5/src/sonos-device.ts#L1347

I also think you could catch all the errors, with the .catch(()....); inside all the code that has something to do with the notifications. Or with a try...catch for that matter. But is has to be in the playQueue part.

theimo1221 commented 2 years ago

async function thisThrows() {
  await wait(1000);
  console.log("thisThrows");
  throw new Error("Thrown from thisThrows()");
}

async function handleRequest() {
  console.log("handleRequest");
  const response = await thisThrows();
  if (response.ok) { 
     return true; 
  }
  return await this.handleResponse(response);
}

async function handleResponse() {
  console.log("handleResponse");
}

async function baseCaller() {
  console.log("baseCaller");
  await handleRequest();
}
async function wait(ms) {
  return new Promise(resolve => {
    setTimeout(resolve, ms);
  });
}

baseCaller();

Using this snippet I agree on your point regarding the capability to have a complete stacktrace and catch an error outside, regardless off using .catch() or not, as long as the outer function returns a promise itself and awaits it's subcalls properly.

I'll look into it more deeply

github-actions[bot] commented 2 years ago

:tada: This issue has been resolved in version 2.5.0-beta.2 :tada:

The release is available on:

Your semantic-release bot :package::rocket:

github-actions[bot] commented 2 years ago

:tada: This issue has been resolved in version 2.5.0 :tada:

The release is available on:

Your semantic-release bot :package::rocket:

orensharon commented 2 years ago

I read the full discussion regarding the timeout error handling and I'm still not sure how to handle this case.

Info:

On the latest version (2.5.0), I'm getting the following error:

FetchError: network timeout at: http://192.168.68.67:1400/MediaRenderer/AVTransport/Event
    at Timeout.<anonymous> (c:\dev\sonos-api\node_modules\node-fetch\lib\index.js:1484:13)
    at listOnTimeout (node:internal/timers:564:17)
    at process.processTimers (node:internal/timers:507:7) {
  type: 'request-timeout'

This is the only log output I got at this moment., seems like this is related to the library internal event-subscription.

Here is my subscribe and unsubscribe functions:

const subscribe = d => {
    debug("Subscribing device %s events", d.uuid)
    d.Events.on(SonosEvents.SubscriptionError, error => onSubscriptionError(d.uuid, error))
    d.RenderingControlService.Events.on(ServiceEvents.ServiceEvent, async data => await Util.async(() => onDeviceRendererChanged(d.uuid, data)))
    d.Events.on(SonosEvents.CurrentTransportStateSimple, async data => await Util.async(() => onTransportStateChanged(d, data)))
    d.ZoneGroupTopologyService.Events.on(ServiceEvents.ServiceEvent, async data => await Util.async(() => onGroupTopologyChanged(d, data)))
    d.GroupRenderingControlService.Events.on(ServiceEvents.ServiceEvent, async data => await Util.async(() => onGroupRendererChanged(d, data)))
}

const unsubscribe = d => {
    d.CancelEvents()
    d.AlarmClockService.Events.removeAllListeners(ServiceEvents.ServiceEvent)
    d.AVTransportService.Events.removeAllListeners(ServiceEvents.ServiceEvent)
    d.RenderingControlService.Events.removeAllListeners(ServiceEvents.ServiceEvent)
    d.ZoneGroupTopologyService.Events.removeAllListeners(ServiceEvents.ServiceEvent)
    d.GroupRenderingControlService.Events.removeAllListeners(ServiceEvents.ServiceEvent)
    debug('Device [%s] [%s] is now unsubsribed', d.uuid, d.name)
}

svrooij / node-sonos-ts