JRiver error: "The operation has timed out"

[leepingdiablo]

Hello again,

I'm having an interesting bug with network connectivity to the JRiver server. Thanks in advance for your help, jitterjames!

Steps to reproduce

1. Open or restart VoxCommando
2. Perform any action that performs a network request to JRiver
3. Wait at least 90 seconds
4. Repeat #2 and observe that this error occurs: JRiver error: System.Net.WebException: The operation has timed out

Other observations

• The behavior is consistent: the first network request always works, network requests after 90 seconds of inactivity always time out
• While the error is happening in VoxCommando, requesting the same JRiver URL in the browser works OK
• If I swap Scraper.Simple for JRiver.Raw (and request precisely the same URL), the bug does not happen

Logs

Here is an example where I click "Stop playback", wait 90 seconds, then click "Stop playback" again.

Code: [Select]

4/20/2020 9:23:30 PM 356 doCommand:Stop playback
4/20/2020 9:23:30 PM 366 Action is NOT threadsafe: JRiver.Stop
4/20/2020 9:23:30 PM 416 action repeat set to: 1
4/20/2020 9:23:30 PM 416 Action:  JRiver.Stop
4/20/2020 9:23:30 PM 416 addHistoryItem [action] JRiver.Stop:

4/20/2020 9:23:30 PM 416 Action from plugin: C:\Users\leepingdiablo\AppData\Roaming\VoxCommando\Plugins\JRiver\JRiver.dll
4/20/2020 9:23:30 PM 416 [plugin] http://localhost:52199/MCWS/v1/Playback/Stop
4/20/2020 9:23:30 PM 416 Action INFO: <?xml version="1.0" encoding="UTF-8" standalone="yes" ?>
<Response Status="OK"/>

4/20/2020 9:23:32 PM 566 Focused: VoxCommando
4/20/2020 9:23:35 PM 567 Focused: ShellExperienceHost
4/20/2020 9:23:49 PM 457 Check for updates required.
4/20/2020 9:23:49 PM 457 Updates: True
4/20/2020 9:25:01 PM 860 doCommand:Stop playback
4/20/2020 9:25:01 PM 860 Action is NOT threadsafe: JRiver.Stop
4/20/2020 9:25:01 PM 860 action repeat set to: 1
4/20/2020 9:25:01 PM 860 Action:  JRiver.Stop
4/20/2020 9:25:01 PM 860 addHistoryItem [action] JRiver.Stop:

4/20/2020 9:25:01 PM 860 Action from plugin: C:\Users\leepingdiablo\AppData\Roaming\VoxCommando\Plugins\JRiver\JRiver.dll
4/20/2020 9:25:01 PM 860 [plugin] http://localhost:52199/MCWS/v1/Playback/Stop
4/20/2020 9:25:03 PM 880 [plugin] JRiver error: System.Net.WebException: The operation has timed out
   at System.Net.HttpWebRequest.GetResponse()
   at vcPlugin.webstuff.scrapeRawText(String strURL, Int32 reqTimeout)
4/20/2020 9:25:03 PM 880 Action INFO: JRiver error :
http://localhost:52199/MCWS/v1/Playback/Stop?token=JQ642QrK
System.Net.WebException: The operation has timed out
   at System.Net.HttpWebRequest.GetResponse()
   at vcPlugin.webstuff.scrapeRawText(String strURL, Int32 reqTimeout)

[jitterjames]

Bummer.  Sorry about that.  I will try to recreate and fix this today.

[jitterjames]

I don't know if it is related, but in which folder did you install VoxCommando?

Based on your log I think you might have installed VC in a protected folder which is not recommended.

[jitterjames]

I have tried a few computers but I am not able to reproduce this error unless I set the plugin to use a very short web request timeout.  The timeout was 2 seconds which should be more than enough for simple commands like "stop".

I'm not sure why the 90 seconds would be significant, nor can I think of a reason why the raw action would work differently from the basic stop action because they all end up being routed through the same method with the same web request.

I suspect there could be something on your system that is not quite right.  Network issues or an overactive firewall or antivirus, or maybe it has to do with the way you installed VoxCommando.

https://voxcommando.com/mediawiki/index.php?title=Installation#Installing_VoxCommando

In any case, here is an updated version of the plugin with a 5 second timeout and a bit more logging.

Please give it a try and get back to me when you can.

[leepingdiablo]

Hi, jitterjames!

Based on your log I think you might have installed VC in a protected folder which is not recommended.

The software is installed in the %AppData% directory, which is a directory for programs to manage their own files in. I haven't had any issues with file system permissions (ex. writing voicecommands.xml). This is the best official explanation I could find from Microsoft about this directory:

https://web.archive.org/web/20140802194144/http://download.microsoft.com/download/e/6/a/e6aa654f-cccb-421e-9b50-3392e9886084/VistaFileSysNamespaces.pdf

Good news: I'm not sure I have an explanation, but the bug is fixed in the 2020-04-21 version of JRiver.dll! I even tried reverting to the 2020-04-19 version and back again twice to be doubly-sure. Below are the logs (this time I used the "Get detailed info" command) for both versions.


2020-04-19 version of JRiver.dll

Code: [Select]

4/22/2020 6:48:27 AM 256 doCommand:Get detailed info
4/22/2020 6:48:27 AM 256 Action is NOT threadsafe: JRiver.Raw
4/22/2020 6:48:27 AM 321 action repeat set to: 1
4/22/2020 6:48:27 AM 321 Action:  JRiver.Raw
4/22/2020 6:48:27 AM 321 Param1:Playback/Info?Zone=-1
4/22/2020 6:48:27 AM 321 addHistoryItem [action] JRiver.Raw:Playback/Info?Zone=-1

4/22/2020 6:48:27 AM 321 Action from plugin: C:\Users\leepingdiablo\AppData\Roaming\VoxCommando\Plugins\JRiver\JRiver.dll
4/22/2020 6:48:27 AM 326 Action RESULT:
4/22/2020 6:48:27 AM 326 Action is NOT threadsafe: OSD.ShowText
4/22/2020 6:48:27 AM 326 action repeat set to: 1
4/22/2020 6:48:27 AM 326 Action:  OSD.ShowText
4/22/2020 6:48:27 AM 326 Param1:<?xml version="1.0" encoding="UTF-8" standalone="yes" ?>
<Response Status="OK">

...

4/22/2020 6:50:16 AM 390 doCommand:Get detailed info
4/22/2020 6:50:16 AM 390 Action is NOT threadsafe: JRiver.Raw
4/22/2020 6:50:16 AM 390 action repeat set to: 1
4/22/2020 6:50:16 AM 390 Action:  JRiver.Raw
4/22/2020 6:50:16 AM 390 Param1:Playback/Info?Zone=-1
4/22/2020 6:50:16 AM 390 addHistoryItem [action] JRiver.Raw:Playback/Info?Zone=-1

4/22/2020 6:50:16 AM 390 Action from plugin: C:\Users\leepingdiablo\AppData\Roaming\VoxCommando\Plugins\JRiver\JRiver.dll
4/22/2020 6:50:18 AM 420 [plugin] JRiver error: System.Net.WebException: The operation has timed out
   at System.Net.HttpWebRequest.GetResponse()
   at vcPlugin.webstuff.scrapeRawText(String strURL, Int32 reqTimeout)
4/22/2020 6:50:18 AM 420 Action RESULT:
4/22/2020 6:50:18 AM 420 Action is NOT threadsafe: OSD.ShowText
4/22/2020 6:50:18 AM 420 action repeat set to: 1
4/22/2020 6:50:18 AM 420 Action:  OSD.ShowText
4/22/2020 6:50:18 AM 420 Param1:JRiver error :
http://localhost:52199/MCWS/v1/Playback/Info?Zone=-1&token=K5zejKzt
System.Net.WebException: The operation has timed out
   at System.Net.HttpWebRequest.GetResponse()
   at vcPlugin.webstuff.scrapeRawText(String strURL, Int32 reqTimeout)

2020-04-21 version of JRiver.dll

Code: [Select]

4/22/2020 6:53:09 AM 571 doCommand:Get detailed info
4/22/2020 6:53:09 AM 571 Action is NOT threadsafe: JRiver.Raw
4/22/2020 6:53:09 AM 631 action repeat set to: 1
4/22/2020 6:53:09 AM 631 Action:  JRiver.Raw
4/22/2020 6:53:09 AM 631 Param1:Playback/Info?Zone=-1
4/22/2020 6:53:09 AM 631 addHistoryItem [action] JRiver.Raw:Playback/Info?Zone=-1

4/22/2020 6:53:09 AM 631 Action from plugin: C:\Users\leepingdiablo\AppData\Roaming\VoxCommando\Plugins\JRiver\JRiver.dll
4/22/2020 6:53:09 AM 631 [plugin] JRiver: scrapeRaw with timeout: 5000
http://localhost:52199/MCWS/v1/Playback/Info?Zone=-1&token=K5zejKzt
4/22/2020 6:53:09 AM 631 Action RESULT:
4/22/2020 6:53:09 AM 631 Action is NOT threadsafe: OSD.ShowText
4/22/2020 6:53:09 AM 631 action repeat set to: 1
4/22/2020 6:53:09 AM 631 Action:  OSD.ShowText
4/22/2020 6:53:09 AM 641 Param1:<?xml version="1.0" encoding="UTF-8" standalone="yes" ?>
<Response Status="OK">

...

4/22/2020 6:55:12 AM 106 doCommand:Get detailed info
4/22/2020 6:55:12 AM 106 Action is NOT threadsafe: JRiver.Raw
4/22/2020 6:55:12 AM 106 action repeat set to: 1
4/22/2020 6:55:12 AM 106 Action:  JRiver.Raw
4/22/2020 6:55:12 AM 106 Param1:Playback/Info?Zone=-1
4/22/2020 6:55:12 AM 106 addHistoryItem [action] JRiver.Raw:Playback/Info?Zone=-1

4/22/2020 6:55:12 AM 106 Action from plugin: C:\Users\leepingdiablo\AppData\Roaming\VoxCommando\Plugins\JRiver\JRiver.dll
4/22/2020 6:55:12 AM 106 [plugin] JRiver: scrapeRaw with timeout: 5000
http://localhost:52199/MCWS/v1/Playback/Info?Zone=-1&token=K5zejKzt
4/22/2020 6:55:14 AM 176 Action RESULT:
4/22/2020 6:55:14 AM 176 Action is NOT threadsafe: OSD.ShowText
4/22/2020 6:55:14 AM 176 action repeat set to: 1
4/22/2020 6:55:14 AM 176 Action:  OSD.ShowText
4/22/2020 6:55:14 AM 176 Param1:<?xml version="1.0" encoding="UTF-8" standalone="yes" ?>
<Response Status="OK">


[jitterjames]

Ok. I guess your system is just a lot slower to respond than mine for some reason.

I am going to add an option in the plugin settings to set your own timeout.

The reason for not just having a really long timeout is that it can freeze VoxCommando for a long time waiting for a response from a server that might not be responding at all.

[jitterjames]

Here is the latest version with the options to specify the timeout.

I tested with a 10 millisecond timeout controlling JRiver running on a different machine in my LAN and had no issues, so I'm not sure why 2000 ms was too short on your system.

But as long as it's working for you that's what matters.