Mantis Bug Tracker

View Issue Details Jump to Notes ] Issue History ] Print ]
IDProjectCategoryView StatusDate SubmittedLast Update
0005336opensim[REGION] Specific OpenSim Modulepublic2011-01-18 09:122011-05-06 18:52
Reporteraiaustin 
Assigned Tojustincc 
PriorityurgentSeverityblockReproducibilityalways
StatusclosedResolutionfixed 
PlatformOSOS Version
Product Versionmaster (dev code) 
Target VersionFixed in Version 
Summary0005336: Using SL Viewer 2 get many repeats of [FreeSwitchVoice]: FreeSwitchSLVoiceSigninHTTPHandler called
DescriptionLogin using Viewer 2 to a region with Freeswitch voice enabled is very slow. OpenSim.exe console log indicates MANY repeats of this Freeswitch message....

[FreeSwitchVoice]: FreeSwitchSLVoiceSigninHTTPHandler called

About 6 per second... and continues forever. Region basically becomes unusable whenever anyone logs in via Viewer 2. Cannot be controlled by server end, and user is given no feedback that this is a serious problem.

Demonstrate via this method:

1. Log on to a region via SL Viewer 2 (e.g. 2.4.0 tested).

2. Watch OpenSim.exe console log and observe reponse drop immediately. Untick Preferences -> Sound & Media -> Voice Chat -> Enabled (default is that it is enabled).

3. Observe performance is normal again and stream of console messages stops.

4. Tick voice chat enabled again in Viewer and blocking problem restarts.

If Viewer 2 cannot be supported for FreeSwitch voice, can a way be found to temporarily not try FreeSwitch voice logins if viewer 2 is used? Or a general approach to protect the server by giving up and not providing voice services to a viewer after a given number of attempts to perform a "FreeSwitchSLVoiceSigninHTTPHandler" from ANY viewer?

At present this is a serious issue that cannot be mitigated at the server end - unless FreeSwitch is removed entirely.
Additional Information...
17:08:17 - [FreeSwitchVoice]: FreeSwitchSLVoiceSigninHTTPHandler called
17:08:17 - [FreeSwitchVoice]: FreeSwitchSLVoiceSigninHTTPHandler called
17:08:17 - [FreeSwitchVoice]: FreeSwitchSLVoiceSigninHTTPHandler called
17:08:17 - [FreeSwitchVoice]: FreeSwitchSLVoiceSigninHTTPHandler called
17:08:17 - [FreeSwitchVoice]: FreeSwitchSLVoiceSigninHTTPHandler called
17:08:17 - [FreeSwitchVoice]: FreeSwitchSLVoiceSigninHTTPHandler called
17:08:18 - [FreeSwitchVoice]: FreeSwitchSLVoiceSigninHTTPHandler called
17:08:18 - [FreeSwitchVoice]: FreeSwitchSLVoiceSigninHTTPHandler called
17:08:18 - [FreeSwitchVoice]: FreeSwitchSLVoiceSigninHTTPHandler called
17:08:18 - [FreeSwitchVoice]: FreeSwitchSLVoiceSigninHTTPHandler called
17:08:18 - [FreeSwitchVoice]: FreeSwitchSLVoiceSigninHTTPHandler called
17:08:18 - [FreeSwitchVoice]: FreeSwitchSLVoiceSigninHTTPHandler called
...
TagsNo tags attached.
Git Revision or version number0.7.1 dev master
Run Mode Grid (Multiple Regions per Sim)
Physics EngineODE
Environment.NET / Windows32
Mono VersionNone
ViewerSL Viewer 2.4.0
Attached Files

- Relationships

-  Notes
(0017867)
aiaustin (developer)
2011-01-19 09:04
edited on: 2011-01-27 04:34

Note client side user is not aware that there is a server issue, they just see very slow response. Server side shows the issue.

A fix is to turn off voice with Viewer 2, but user has no way to know that is the issue, and will drag down (or in my experience completely block) the service for everyone else without realising it.

(0017917)
aiaustin (developer)
2011-02-01 04:18
edited on: 2011-03-11 02:28

This problem also occurs when a hypergrid visitor arrives from another grid. If they are using Viewer 2.4.0 (for example) and have the default setting of voice being enabled in their preferences... then this triggers the same stream of OpenSim.exe messages and slows the sim to a crawl.

(0018131)
aiaustin (developer)
2011-03-11 02:28
edited on: 2011-03-11 02:29

Confirmed as still occuring in r/15002 10-Mar-2011 and with SL Viewer 2.5.1.

The serious problem is that the client side user has no idea they are causing a problem, so there is no way for them to know they should turn off voice before visiting a FreeSwitch voice enabled region.

(0018158)
melanie (administrator)
2011-03-22 04:45

We do carry the viewer signature into the region, so the info is available.
(0018162)
aiaustin (developer)
2011-03-23 11:20
edited on: 2011-03-23 11:22

I also notice that the Pheonix viewer labels avatars with a string saying which viewer that user is using. And for SL viewer 2 users it says "(Viewer 2)".

(0018286)
BlueWall (administrator)
2011-04-15 09:46

Some log and packet dumps from SL Viewer2 - Freeswitch enabled OpenSim

Portion of viewer log...
2011-04-15T13:37:24Z WARNING: LLVivoxVoiceClient::loginResponse: Account.Login response failure (30013): Error Parsing XML: Error document empty. row 0 col 0

Portion of OpenSim.log...
09:10:19 - [FreeSwitchVoice][PROVISIONVOICE]: avatar "Ima Bot": <llsd><map><key>username</key><string>xfn3HM9WERcCQZtOta1wpiQ==</string><key>password</key><string>1234</string><key>voice_sip_uri_hostname</key><string>74.237.137.28</string><key>voice_account_server_name</key><string>http://74.237.137.28:9800/fsapi/</string></map></llsd> [^]

WinGridProxy...
Date Fri, 15 Apr 2011 09:18:40 GMT
Content-Length 273
Content-Type application/xml
Server Tiny WebServer
Connection close

<llsd><map><key>username</key><string>xfn3HM9WERcCQZtOta1wpiQ==</string><key>password</key><string>1234</string><key>voice_sip_uri_hostname</key><string>74.237.137.28</string><key>voice_account_server_name</key><string>http://74.237.137.28:9800/fsapi/</string></map></llsd> [^]

Wireshark capture...
POST /CAPS/204b88b3-c4aa-4baa-9af2-db8f866602580008/ HTTP/1.1

Host: 74.237.137.28:9800

Accept: */*

X-SecondLife-UDP-Listen-Port: 43622

Content-Type: application/llsd+xml

Content-Length: 23



<llsd><undef /></llsd>
HTTP/1.1 200 OK

Date: Fri, 15 Apr 2011 09:39:07 GMT

Content-Length: 273

Content-Type: application/xml

Server: Tiny WebServer

Connection: close



<llsd><map><key>username</key><string>xfn3HM9WERcCQZtOta1wpiQ==</string><key>password</key><string>1234</string><key>voice_sip_uri_hostname</key><string>74.237.137.28</string><key>voice_account_server_name</key><string>http://74.237.137.28:9800/fsapi/</string></map></llsd> [^]
(0018302)
justincc (administrator)
2011-04-19 17:09

Further analysis reveals that we actually see the following sequence of calls.

ProvisionVoiceAccountRequest CAP - ProvisionVoiceAccountRequest()
viv_get_prelogin.php - FreeSwitchSLVoiceGetPreloginHTTPHandler()
viv_signin.php - FreeSwitchSLVoiceSigninHTTPHandler()
viv_buddy.php - FreeSwitchSLVoiceBuddyHTTPHandler()
viv_watcher.php - unhandled!

It's the unhandled call to viv_watcher.php that generates the

WARNING: LLVivoxVoiceClient::loginResponse: Account.Login response failure (30013): Error Parsing XML: Error document empty. row 0 col 0

message in the viewer log.

In viewer 2, the cycle signin, buddy, watcher then repeats ad inifinitum with constant warnings. Viewer 1 makes the same sequence of calls but appears to ignore the non-response to viv_watcher.php. It doesn't output the log error message either.

Commit ccc26f74436f0e3069587efd96497053e4129c3c fills out the bare minimum viv_watcher.php response (basically the "OK" response for the auth token). This appears to allow viewer 2 voice to work. Viewer 1 also continues to connect and work.

As a tip, there is a log message in OpenSim/Framework/Servers/HttpServer/BaseHttpServer:443

// m_log.DebugFormat("[BASE HTTP SERVER]: Handling {0} request for {1}", request.HttpMethod, path);

which can be uncommented to tell us exactly what HTTP requests the simulator is getting.

- Issue History
Date Modified Username Field Change
2011-01-18 09:12 aiaustin New Issue
2011-01-18 09:12 aiaustin Git Revision => 0.7.1 dev master
2011-01-18 09:12 aiaustin SVN Revision => 14806
2011-01-18 09:12 aiaustin Run Mode => Grid (Multiple Regions per Sim)
2011-01-18 09:12 aiaustin Physics Engine => ODE
2011-01-18 09:12 aiaustin Environment => Unknown, .NET / Windows32
2011-01-18 09:12 aiaustin Mono Version => None
2011-01-18 09:12 aiaustin Viewer => SL Viewer 2.4.0
2011-01-18 09:13 aiaustin Description Updated
2011-01-18 09:13 aiaustin Additional Information Updated
2011-01-19 09:04 aiaustin Note Added: 0017867
2011-01-27 04:31 aiaustin SVN Revision 14806 => 14838
2011-01-27 04:31 aiaustin Environment Unknown, .NET / Windows32 => .NET / Windows32
2011-01-27 04:31 aiaustin Priority normal => urgent
2011-01-27 04:31 aiaustin Severity major => block
2011-01-27 04:31 aiaustin Description Updated
2011-01-27 04:34 aiaustin Description Updated
2011-01-27 04:34 aiaustin Note Edited: 0017867
2011-01-27 04:38 aiaustin Description Updated
2011-02-01 04:18 aiaustin Note Added: 0017917
2011-02-01 04:19 aiaustin Note Edited: 0017917
2011-03-11 02:28 aiaustin Note Added: 0018131
2011-03-11 02:28 aiaustin Note Edited: 0017917
2011-03-11 02:29 aiaustin Note Edited: 0018131
2011-03-22 04:45 melanie Note Added: 0018158
2011-03-22 06:15 aiaustin Note Added: 0018159
2011-03-23 11:20 aiaustin Note Added: 0018162
2011-03-23 11:21 aiaustin Note Edited: 0018159
2011-03-23 11:21 aiaustin Note Deleted: 0018159
2011-03-23 11:22 aiaustin Note Edited: 0018162
2011-04-15 09:46 BlueWall Note Added: 0018286
2011-04-15 09:51 BlueWall Status new => confirmed
2011-04-19 17:09 justincc Note Added: 0018302
2011-04-19 17:09 justincc Status confirmed => resolved
2011-04-19 17:09 justincc Resolution open => fixed
2011-04-19 17:09 justincc Assigned To => justincc
2011-05-06 18:52 chi11ken Status resolved => closed


Copyright © 2000 - 2012 MantisBT Group
Powered by Mantis Bugtracker