Winkstart Add Media - large wave file fails silently

[Alan Evans]

Hello Dev Team,

This took some tracing :-(

I'm having a voice quality issue so I decided to create a reference wave file that could be played out by dialing a test number.

When I use winkstart to "Add Media" and select a large .wav file (~5M). The upload would fail but there is no indication via the GUI that anything went wrong.

I turned on debug logs and I see this:

2012-05-24 09:42:27.714 [debug] |09d8c3140a08cd0294d2c35667b79513|v1_resource:71 (<0.12097.0>) OPTIONS: /v1/accounts/6ff4f0ab8bb5abd7c18d17cc65001312/media/675c90f5bb38406e6ca30616491efb9d/raw?<<>>
2012-05-24 09:42:27.715 [debug] |09d8c3140a08cd0294d2c35667b79513|crossbar_bindings:227 (<0.12122.0>) running fold for binding v1_resource.init
2012-05-24 09:42:27.729 [debug] |09d8c3140a08cd0294d2c35667b79513|v1_util:334 (<0.12097.0>) mod accounts has params [<<"6ff4f0ab8bb5abd7c18d17cc65001312">>]
2012-05-24 09:42:27.751 [debug] |09d8c3140a08cd0294d2c35667b79513|v1_util:334 (<0.12097.0>) mod media has params [<<"675c90f5bb38406e6ca30616491efb9d">>,<<"raw">>]
2012-05-24 09:42:27.751 [debug] |09d8c3140a08cd0294d2c35667b79513|v1_util:112 (<0.12097.0>) undefined content type when getting req data
2012-05-24 09:42:27.751 [debug] |09d8c3140a08cd0294d2c35667b79513|crossbar_bindings:208 (<0.12123.0>) exact match <<"v1_resource.allowed_methods.media">> to <<"v1_resource.allowed_methods.media">>
2012-05-24 09:42:27.751 [debug] |09d8c3140a08cd0294d2c35667b79513|crossbar_bindings:204 (<0.12123.0>) sending routing v1_resource.allowed_methods.media to cb_media:allowed_methods
2012-05-24 09:42:27.752 [debug] |09d8c3140a08cd0294d2c35667b79513|v1_util:293 (<0.12097.0>) sticking with method OPTIONS
2012-05-24 09:42:27.752 [debug] |09d8c3140a08cd0294d2c35667b79513|v1_resource:130 (<0.12097.0>) allowing OPTIONS request for CORS preflight
2012-05-24 09:42:27.752 [debug] |09d8c3140a08cd0294d2c35667b79513|v1_util:443 (<0.12097.0>) options requests are permitted by default
2012-05-24 09:42:27.752 [debug] |09d8c3140a08cd0294d2c35667b79513|v1_util:462 (<0.12097.0>) ignore content type for options
2012-05-24 09:42:27.752 [debug] |09d8c3140a08cd0294d2c35667b79513|v1_resource:187 (<0.12097.0>) is CORS request
2012-05-24 09:42:27.752 [debug] |09d8c3140a08cd0294d2c35667b79513|v1_resource:91 (<0.12097.0>) fulfilled in 37 ms
2012-05-24 09:42:27.897 [debug] |eee1ed1bbeef227d2cd0b7b4f5bf116e|v1_resource:71 (<0.12097.0>) POST: /v1/accounts/6ff4f0ab8bb5abd7c18d17cc65001312/media/675c90f5bb38406e6ca30616491efb9d/raw?<<>>
2012-05-24 09:42:27.897 [debug] |eee1ed1bbeef227d2cd0b7b4f5bf116e|crossbar_bindings:227 (<0.12126.0>) running fold for binding v1_resource.init
2012-05-24 09:42:27.910 [debug] |eee1ed1bbeef227d2cd0b7b4f5bf116e|v1_util:334 (<0.12097.0>) mod accounts has params [<<"6ff4f0ab8bb5abd7c18d17cc65001312">>]
2012-05-24 09:42:27.932 [debug] |eee1ed1bbeef227d2cd0b7b4f5bf116e|v1_util:334 (<0.12097.0>) mod media has params [<<"675c90f5bb38406e6ca30616491efb9d">>,<<"raw">>]
2012-05-24 09:42:27.932 [debug] |eee1ed1bbeef227d2cd0b7b4f5bf116e|v1_util:150 (<0.12097.0>) application/x-base64 content type when getting req data
2012-05-24 09:42:32.935 [error] <0.12097.0> ** Handler v1_resource terminating in rest_init/3
   for the reason error:{case_clause,{error,timeout}}
** Options were []
** Request was {http_req,#Port<0.46264>,cowboy_tcp_transport,keepalive,<0.12097.0>,'POST',{1,1},undefined,[<<"whistle">>,<<"kagesys">>,<<"com">>],undefined,<<"whistle.kagesys.com">>,8000,[<<"v1">>,<<"accounts">>,<<"6ff4f0ab8bb5abd7c18d17cc65001312">>,<<"media">>,<<"675c90f5bb38406e6ca30616491efb9d">>,<<"raw">>],[<<"accounts">>,<<"6ff4f0ab8bb5abd7c18d17cc65001312">>,<<"media">>,<<"675c90f5bb38406e6ca30616491efb9d">>,<<"raw">>],<<"/v1/accounts/6ff4f0ab8bb5abd7c18d17cc65001312/media/675c90f5bb38406e6ca30616491efb9d/raw">>,undefined,<<>>,[{v1,<<"v1">>}],[{'Cache-Control',<<"no-cache">>},{'Pragma',<<"no-cache">>},{<<"Origin">>,<<"http://whistle.kagesys.com">>},{'Content-Length',<<"6403924">>},{'Referer',<<"http://whistle.kagesys.com/winkstart/">>},{<<"X-Auth-Token">>,<<"183738eeaaa5ddc5d7f9968d730f28f1">>},{'Content-Type',<<"application/x-base64; charset=UTF-8">>},{'Connection',<<"keep-alive">>},{<<"Dnt">>,<<"1">>},{'Accept-Language',<<"en-us,en;q=0.5">>},{'Accept',<<"application/json, text/javascript, */*; q=0.01">>},{'User-Agent',<<"Mozilla/5.0 (Windows NT 6.1; WOW64; rv:12.0) Gecko/20100101 Firefox/12.0">>},{'Host',<<"whistle.kagesys.com">>}],[{'Connection',[<<"keep-alive">>]}],undefined,[],waiting,<<"data:audio/x-wav;base64,UklGRrBFAABXQVZFZm10IBAAAAABAAEAQB8AAIA+AAACABAAZGF0YUBJSQAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAEAAQAAAAEAAQABgA0P/Q/+j/+P8AANj/4P/o/wAAwP/Q//D/WACQADgAyP/A/wAA6P+w/7D/4P8QAAAA4P/w/xAAKADQ/+D/AAAoADAACAAIABAAIAAYAAgAEAAQABAAAAAAAGgFuAOoB/AC8AVoA+gFcAOQBDgCgAPAALD8CAGg/Sj+0P9A/Qj+wP8Y/oj9iACQ/sD94PpQ+hD8EPxo/tD9mP5o/ij+4P0o/kj/yP5o/nj9kP3w/cj+mP5I/hD+8P1g/oD+4P4Y/0j/cP9o/5j/qP/g/xAAIAA4ADgASABQAGD/wP/w/6AAwACIAFgAYAB4AGgAiACYAKAAuACYALAAyADYAMgAyACwAMAAqAC4AMAA0ADYANAA2ADQALAAsACoALAAsACgAKAAkACIAIAAeABwAGgAYABgAFgAUABIAEgASABAADgAMAAwACgAIAAgABgAGAAQAAgACAAIAAgACAAAAPj/8P/w/+j/6P/o/+D/4P/Y/9j/2P/Y/+D/4...">>,...}
** Stacktrace: [{v1_util,decode_base64,3},{v1_resource,allowed_methods,2},{cowboy_http_rest,allowed_methods,2},{cowboy_http_rest,upgrade,4},{cowboy_http_protocol,upgrade_protocol,3}]


After some investigation I found that the problem is in cowboy_http_req:body/1

The timeout is hard coded to 5 seconds. It takes a lot longer than 5 secs to upload a 5Meg file. I increased it to 50000 and now it works fine.

body(Length, Req=#http_req{socket=Socket, transport=Transport,
                body_state=waiting, buffer=Buffer}) ->
        case Transport:recv(Socket, Length - byte_size(Buffer), 5000) of
                {ok, Body} -> {ok, << Buffer/binary, Body/binary >>,
                        Req#http_req{body_state=done, buffer= <<>>}};
                {error, Reason} -> {error, Reason}
        end.



--
Alan R Evans
KAGE Systems Ltd
Tel: +44 7891 773415

[James Aimonetti]

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

Hi Alan,

Thanks for the alert. We are aware of the issue and have patched
Cowboy ourselves to address the issue. What version of the platform
are you running? Newer versions have it patched, and with the release
of Cowboy 0.6.0 (yesterday I think), we can set the timeout option
without needing to modify Cowboy's code. Look for the next release to
have a configurable option in Crossbar to handle these upload timeouts
more gracefully.

James

> data *2012-05-24 09:42:32.935 [error] <0.12097.0> ** Handler

> v1_resource terminating in rest_init/3 for the reason

> error:{case_clause,{error,timeout}} ** Options were []* ** Request

> was
> {http_req,#Port<0.46264>,cowboy_tcp_transport,keepalive,<0.12097.0>,'POST',{1,1},undefined,[<<"whistle">>,<<"kagesys">>,<<"com">>],undefined,<<"
>
>
whistle.kagesys.com
> ">>,8000,[<<"v1">>,<<"accounts">>,<<"6ff4f0ab8bb5abd7c18d17cc65001312">>,<<"media">>,<<"675c90f5bb38406e6ca30616491efb9d">>,<<"raw">>],[<<"accounts">>,<<"6ff4f0ab8bb5abd7c18d17cc65001312">>,<<"media">>,<<"675c90f5bb38406e6ca30616491efb9d">>,<<"raw">>],<<"/v1/accounts/6ff4f0ab8bb5abd7c18d17cc65001312/media/675c90f5bb38406e6ca30616491efb9d/raw">>,undefined,<<>>,[{v1,<<"v1">>}],[{'Cache-Control',<<"no-cache">>},{'Pragma',<<"no-cache">>},{<<"Origin">>,<<"
>
>
http://whistle.kagesys.com
> ">>},{'Content-Length',<<"6403924">>},{'Referer',<<"
> http://whistle.kagesys.com/winkstart/">>},{<<"X-Auth-Token">>,<<"183738eeaaa5ddc5d7f9968d730f28f1">>},{'Content-Type',<<"application/x-base64;
>
>
charset=UTF-8">>},{'Connection',<<"keep-alive">>},{<<"Dnt">>,<<"1">>},{'Accept-Language',<<"en-us,en;q=0.5">>},{'Accept',<<"application/json,
> text/javascript, */*; q=0.01">>},{'User-Agent',<<"Mozilla/5.0
> (Windows NT 6.1; WOW64; rv:12.0) Gecko/20100101
> Firefox/12.0">>},{'Host',<<" whistle.kagesys.com
> ">>}],[{'Connection',[<<"keep-alive">>]}],undefined,[],waiting,<<"data:audio/x-wav;base64,UklGRrBFAABXQVZFZm10IBAAAAABAAEAQB8AAIA+AAACABAAZGF0YUBJSQAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAEAAQAAAAEAAQABgA0P/Q/+j/+P8AANj/4P/o/wAAwP/Q//D/WACQADgAyP/A/wAA6P+w/7D/4P8QAAAA4P/w/xAAKADQ/+D/AAAoADAACAAIABAAIAAYAAgAEAAQABAAAAAAAGgFuAOoB/AC8AVoA+gFcAOQBDgCgAPAALD8CAGg/Sj+0P9A/Qj+wP8Y/oj9iACQ/sD94PpQ+hD8EPxo/tD9mP5o/ij+4P0o/kj/yP5o/nj9kP3w/cj+mP5I/hD+8P1g/oD+4P4Y/0j/cP9o/5j/qP/g/xAAIAA4ADgASABQAGD/wP/w/6AAwACIAFgAYAB4AGgAiACYAKAAuACYALAAyADYAMgAyACwAMAAqAC4AMAA0ADYANAA2ADQALAAsACoALAAsACgAKAAkACIAIAAeABwAGgAYABgAFgAUABIAEgASABAADgAMAAwACgAIAAgABgAGAAQAAgACAAIAAgACAAAAPj/8P/w/+j/6P/o/+D/4P/Y/9j/2P/Y/+D/4...">>,...}
>
>
** Stacktrace:
> [{v1_util,decode_base64,3},{v1_resource,allowed_methods,2},{cowboy_http_rest,allowed_methods,2},{cowboy_http_rest,upgrade,4},{cowboy_http_protocol,upgrade_protocol,3}]
>
>
>
> After some investigation I found that the problem is in
> cowboy_http_req:body/1
>
> The timeout is hard coded to 5 seconds. It takes a lot longer than
> 5 secs to upload a 5Meg file. I increased it to 50000 and now it
> works fine.
>
> body(Length, Req=#http_req{socket=Socket, transport=Transport,
> body_state=waiting, buffer=Buffer}) -> case Transport:recv(Socket,

> Length - byte_size(Buffer), *5000*) of {ok, Body} -> {ok, <<

> Buffer/binary, Body/binary >>, Req#http_req{body_state=done,
> buffer= <<>>}}; {error, Reason} -> {error, Reason} end.
>
>
>

- --
James Aimonetti
Distributed Systems Engineer / DJ MC_

2600hz | http://2600hz.com
sip:ja...@2600hz.com
tel: 415.886.7905
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.11 (GNU/Linux)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org/

iQEcBAEBAgAGBQJPvoIdAAoJENc77s1OYoGgSbwH/2MeRbVDkaR/apdf3aYwtqFY
E/HaSuj0uUImSiuGyWXjBnXkhrP81qEWW48978anFzBmkyaI4UmxzTeHc/BKvLYi
P1zbG8CrfhpayrYznOnqXgJJWPKTNOx/0K7RyrB5fcRvoj1Qx0bW8By7b3bP2Jyy
BlMLFJp5QEbX+TD1Oev8R9Y7/Onc/LdDiISMEygrG9efpT9qHP2DWIlRJx1SRRxc
FXBs99TrO7Ig6Lha0QJaLdn9yZYWmK5UGSGkhbRzQ13M/Z1DLEoVD6YnXlj+oMdc
3cpeupDKwfdbl6qUqvkoqmf57Ciq1iN9kqWoKW5lhBL6OD5P+SjmVVSvji6KCw4=
=A8PO
-----END PGP SIGNATURE-----

[Alan Evans]

Hi James,

I'm running: v1.51.23

I suppose I should upgrade sometime soon, next time I'll check master before posting

cheers
AlanE

[Darren Schreiber]

Hi Alan,

The project is super active and bugs like this get fixed somewhat quickly when they occur (think: Music On Hold, which clients use, would have (and did) generate tons of tickets when we switched to Cowboy). Going forward it might be wise to avoid pulling one's own hair out and post here first – we're happy to answer even seemingly silly questions.

--

Darren Schreiber

CEO / Co-Founder

 visit: www.2600hz.com

 sip:dar...@2600hz.com

 tel: 415-886-7901

[Alan Evans]

Hi Darren,

That last one wasn't so bad but this one I am going bald!

The problem is that when I dial the VoiceMail and prompted for a PIN. FS stops sending an outbound RTP stream while its waiting for the User to enter the VM PIN. (so as not to waste resources).

However the client has problems if there is no incoming RTP stream and the call fails. The client is a GAN enabled mobile and it tries to Handout to the Macro cell. Not good.

Looking around I see that FS has a Channel Variable: record_waste_resources

record_waste_resources

By default record doesn't send RTP packets. This is generally acceptable, but for longer recordings or depending on the RTP timer of your gateway, your channel may hangup with cause MEDIA_TIMEOUT. Setting this variable will 'waste' bandwidth by sending RTP even during recording. The value can be true/false/<desired silence factor>. By default the silence factor is 1400 if you set record_waste_resources=true.

Usage:

<action application="set" data="record_waste_resources=true"/>

However this variable is not used unless FS is actually recording. As a quick hack I configured FS to record the first 20 seconds of a call, this seemed to work in that RTP packets are then sent out while waiting for the PIN digits.

However as soon as I press a key, the RECORD_STOP event fires and I'm back to square one again.

Any thoughts on how I should tackle this problem? I could keep going down the record path and figure out why the RECORD_STOP event is firing, but this doesn't feel like the right way to do it.

Thanks
AlanE

[Darren Schreiber]

Alan,

I'm guessing you are using a Dialogic board :-)

Put this in /opt/freeswitch/conf/freeswitch.xml , with the other X-PRE-PROCESS lines

<X-PRE-PROCESS cmd="set" data="send_silence_when_idle=400"/>

http://www.mail-archive.com/freeswit...@lists.freeswitch.org/msg11257.html for reference also. There's other threads about this, too, but I believe the above is sufficient.

--

Darren Schreiber

CEO / Co-Founder

 visit: www.2600hz.com

 sip:dar...@2600hz.com

 tel: 415-886-7901

From: Alan Evans <al...@kagesys.com>
Reply-To: "2600h...@googlegroups.com" <2600h...@googlegroups.com>
Date: Friday, May 25, 2012 7:48 AM
To: "2600h...@googlegroups.com" <2600h...@googlegroups.com>

[Alan Evans]

Hi Darren,

You are a star, works like a dream.

I had read the link, it's what prompted me to go down the 'record_waste_resources' path in the first place.

Many thanks
AlanE.

[Alan Evans]

Hi Darren,

I spoke too soon. I can now access the VM system without any issues, but when I try to listen to a VM there is a 500ms gap with no RTP, between selecting the message and it actually starting to play, and that seems to be enough to upset the mobile. I think I'm going to have to address this issue on my side.

I have developed a SIP-GAN/UMA Gateway that sits between FS and the end device. I have a Media Gw doing AMR<>G711 conversion. I'll see if I can fix it at that point.

cheers
AlanE

[Alan Evans]

Hi Darren,

FYI I have the problem on my side.

Thanks for the help
AlanE

[Darren Schreiber]

OK, keep me posted – sounds like the device is quite sensitive.

--

Darren Schreiber

CEO / Co-Founder

 visit: www.2600hz.com

 sip:dar...@2600hz.com

 tel: 415-886-7901

From: Alan Evans <al...@kagesys.com>
Reply-To: "2600h...@googlegroups.com" <2600h...@googlegroups.com>

Date: Friday, May 25, 2012 1:59 PM
To: "2600h...@googlegroups.com" <2600h...@googlegroups.com>

[Stephen Gibberd]

Hi,

I thought I'd post the solution to a problem that stumped us for several weeks
when calls from a mobile operator through a Cisco AS5400 to a Kazoo dialplan
that played a media file resulted in silence. It seems that the AS5400 wasn't
forwarding RTP packets when the Freeswitch server sent SIP Ringing packets
(using the ring_ready application). To disable them, I modified file
ecallmgr_fs_route.erl function reply_affirmative/5 line 214 to

{ok, XML1} = ecallmgr_fs_xml:route_resp_xml(RespJObj),
XML = case re:run(XML1,"(.+)<action application=\"ring_ready\"/>(.+)",
[{capture,all_but_first,list}]) of
{match,[P1,P2]} ->
P1 ++ P2;
_ ->
XML1
end,

basically removing the ring_ready application from the initial XML sent. If
there is a better solution, maybe modifying RespJObj, a document in bigcouch or
a configuration change on the AS5400, please let me know.

Thanks, Stephen

[James Aimonetti]

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

You can modify the system_config DB, the callflow document, and change
ring_ready_offnet from true to false. This should then not include the
ring_ready application in the final XML response (see
callflow/src/cf_route_req.erl the pre_park_action/1 function).

Darren or Karl will have to weigh in on what the tradeoffs here are
though, and how to better solve this situation to give you the
flexibility needed.

- --
James Aimonetti
Distributed Systems Engineer / DJ MC_

2600hz | http://2600hz.com
sip:ja...@2600hz.com
tel: 415.886.7905
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.11 (GNU/Linux)

Comment: Using GnuPG with Thunderbird - http://www.enigmail.net/

iQEcBAEBAgAGBQJRM5UAAAoJENc77s1OYoGgsy4H/AxPpkBwGmpCKaWsSVkd2lcn
3C6q33q1qcucLwg5iC3ijzFuPnNhhxwl0cCbCc9pib2W8zsC5XyBSnsyYb/sqSNb
QNDkrT4uWfnVY6PuQQ9aUM8755zfChG4IFMOYAtJXiHhVg3lCRQTsl8qc5lR618F
nNcsVqhmhkdD6jv2p99y+tgBvnMSEADnBLAbIJU04lmL2+UUbU5rJEMeKDB7n+TO
HrixQwPZrLYakP18CUVeFrKfwMYA3N/M+2ajVaCz4JuhKcVQJ8nUDImWR4O0AbKw
7DJKuOt09Upf6bYg9CdBSwSt4P5wb+63/ySbae5mzK4OKMaj6t8w91y+RMRDfOU=
=fLKf
-----END PGP SIGNATURE-----