Browse
 
Tools
Rss Categories

Media Server Log

Reference Number: AA-01760 Views: 3908 0 Rating/ Voters

The media_server_app.txt log (located in the Media Server logs directory) is one of the most useful logs in troubleshooting any kind of issue related to MRCP communication. With logging verbosity turned to 3 in  the client_property.conf file, the Media Server log is a good place to start looking for issues between LumenVox and any MRCP-enabled voice platform.

The first thing you will see in a Media Server log file is the startup sequence. It is always denoted by a long line of equal signs, making it easy to search for in log files (just search for ==== in a text editor). Here is an example of a startup sequence:

12/03/2012 16:15:09.179,INFO,Startup        ,==================================================================================
12/03/2012 16:15:09.179,INFO,Startup        ,LumenVox Media Server(11.0.300 64-bit build) on HOSTNAME [Windows 7  64-bit, 8 CPUs, 2798 MHz, 12581304 KB]
12/03/2012 16:15:09.179,INFO,Startup        ,Config: LVBIN=C:\Program Files\LumenVox\Engine
12/03/2012 16:15:09.179,INFO,Startup        ,Config: LVLIB=C:\Program Files\LumenVox\Engine\lib
12/03/2012 16:15:09.179,INFO,Startup        ,Config: LVLANG=C:\Program Files\LumenVox\Engine\Lang
12/03/2012 16:15:09.179,INFO,Startup        ,Using configuration settings from : C:\Program Files\LumenVox\Engine\config\media_server.conf
12/03/2012 16:15:09.180,INFO,InitResources  ,ResourceManager Initializing Resources...
12/03/2012 16:15:09.185,INFO,InitResources  ,ResourceManager RTP    Base Port : 35000 (200 ports allocated)
12/03/2012 16:15:09.185,INFO,InitResources  ,ResourceManager MRCPv2 Base Port : 30000 (200 ports allocated)
12/03/2012 16:15:09.185,INFO,InitResources  ,ResourceManager Listening Socket Size: 150
12/03/2012 16:15:09.185,INFO,InitResources  ,ResourceManager Port allocation mode : ROUND-ROBIN
12/03/2012 16:15:09.185,INFO,Startup        ,WARNING: mrcp_server_ip config setting is assigned to loop-back address. This may be incorrect
12/03/2012 16:15:09.185,INFO,Startup        ,LumenVox Media Server Started
 
12/03/2012 16:15:09.187,INFO,StartComms     ,[ SIP Interface Listening on port 5070 ]
12/03/2012 16:15:09.187,INFO,StrtupInterface,[ RTSP Interface active on port 554 ]
12/03/2012 16:15:09.188,INFO,Monitrng:Strtup,[ Monitoring Interface active on port 29900 ]
12/03/2012 16:15:10.190,INFO,StartServer    ,Server connection established. Now listening on port [7590]

There are a few lines worth paying special attention to:

12/03/2012 16:15:09.185,INFO,Startup        ,WARNING: mrcp_server_ip config setting is assigned to loop-back address. This may be incorrect

The presence of this line indicates that the mrcp_server_ip value in media_server.conf is set to the loopback IP address (127.0.0.1). If the Media Server is on a different machine from the voice platform, this value must be set to the actual IP address of the machine hosting the Media Server.

12/03/2012 16:15:09.187,INFO,StartComms     ,[ SIP Interface Listening on port 5070 ]
12/03/2012 16:15:09.187,INFO,StrtupInterface,[ RTSP Interface active on port 554 ]

Those two lines provide confirmation of the port numbers that the SIP (MRCPv2) and RTSP (MRCPv1) are good. A common error that occurs is the Media Server is installed on a machine where another service is using the default SIP port of 5060, preventing the Media Server from binding to that port. If the Media Server were unable to bind to the port, an error message would occur here in the log. If the Media Server is using a non-standard SIP port (as in the example above where it is using 5070), then you can use this log to see which port it is listening on.

When you have full verbosity enabled, you can also read all of the RTSP/SIP/MRCP communication happening. An example MRCPv1 SETUP and response looks like this:

12/17/2012 11:23:14.129,RECV,ProcessRcvdPkt ,SETUP rtsp://127.0.0.1:554/media/synthesizer RTSP/1.0
CSEQ:1
Transport:RTP/AVP;unicast;client_port=50519
Content-Type: application/sdp
Content-Length: 202

12/17/2012 11:23:14.129,DEBG,ProcessRcvdPkt ,Payload:
12/17/2012 11:23:14.129,RECV,ProcessRcvdPkt ,v=0
o=- 0 0 IN IP4 10.0.0.171
s=Lumenvox MRCPv1 Client
p=+1-858-707-0707
c=IN IP4 0.0.0.0
t=0 0
m=audio 64478 RTP/AVP 0 96
a=rtpmap:0 PCMU/8000
a=rtpmap:96 telephone-event/8000
a=fmtp:96 0-15

12/17/2012 11:23:14.129,DEBG,Rtsp_SETUP     ,RTSP: Received SETUP request 'rtsp://127.0.0.1:554/media/synthesizer'
12/17/2012 11:23:14.135,DEBG,CStrSy:OpenPort,SYNTHESIZER RESOURCE CREATED - Target IP = 127.0.0.1, Target Port = 64478
12/17/2012 11:23:14.135,SEND,SendPacket     ,RTSP/1.0 200 OK
CSeq: 1
Session: 96B3036E691DA4BB01C2
Transport: RTP/AVP;unicast;client_port=50519;server_port=35000
Content-Type: application/sdp
Content-Length: 210

v=0
o=- 1234 5678 IN IP4 127.0.0.1
s=LumenVox Media Server/11.0.300
c=IN IP4 127.0.0.1
t=0 0
m=audio 35000 RTP/AVP 0 96
a=rtpmap:0 PCMU/8000
a=rtpmap:96 telephone-event/8000
a=fmtp:96 0-15
a=ptime:20

12/17/2012 11:23:14.135,DEBG,Rtsp_SETUP     ,Sent Reply to SETUP request (CallIndex 1):

You can see a number of things in that log. First, in the first line marked RECV, you see the RTSP SETUP message that establishes an MRCPv1 session. The logs then include the full SDP (Session Description Protocol) information that contains the parameters for the MRCPv1 session. Following that are some DEBG messages indicating the successful creation of a synthesizer resource, and then the SEND messages contain the 200 OK response to the client that indicates the MRCPv1 session was setup correctly.

The SIP/MRCPv2 version of a session setup is a little more complex, but follows the same pattern. First, a RECV message logs out the SIP INVITE:

12/17/2012 11:23:15.298,RECV,HndlSipPrcsrTsk,INVITE sip:mresources@127.0.0.1 SIP/2.0 
Allow: REGISTER,OPTIONS,INVITE,ACK,CANCEL,BYE,NOTIFY,PHACK,REFER,INFO,SUBSCRIBE,UPDATE 
Call-ID: Lumenvox MRCPv2 Client@10.0.0.171:64479 
Contact: <sip:127.0.0.1> 
Content-Length: 282 
Content-Type: application/sdp 
CSeq: 1 
INVITE From: <sip:10.0.0.171:64479> 
Max-Forwards: 70 
Supported: em,timer,replaces,path,resource-priority 
To: <sip:mresources@127.0.0.1> 
Via: SIP/2.0/UDP 10.0.0.171:64479 
v=0 
o=- 0 0 IN IP4 10.0.0.171 
s=Lumenvox MRCPv2 Client 
c=IN IP4 10.0.0.171 
t=0 0 
m=audio 64480 RTP/AVP 0 96 
a=rtpmap:0 PCMU/8000 
a=rtpmap:96 telephone-event/8000 
a=fmtp:96 0-15 
m=application 9 TCP/MRCPv2 
a=setup:active 
a=connection:new 
a=resource:speechsynth 
a=cmid:1

Once it has processed the request and created the internal synthesizer resource, the Media Server sends an OK with detailed SDP:

12/17/2012 11:23:15.298,DEBG,PrepareResponse,CREATED SIP CALL Lumenvox MRCPv2 Client@10.0.0.171:64479
12/17/2012 11:23:15.300,DEBG,CStrSy:OpenPort,SYNTHESIZER RESOURCE CREATED - Target IP = 10.0.0.171, Target Port = 64480
12/17/2012 11:23:15.301,INFO,ConfLstningSock,[ MRCPv2 Service Listening on port 30000 ]
12/17/2012 11:23:15.301,SEND,HndlSipPrcsrTsk,[ SIP Interface - SENT REPLY TO INVITE ]
12/17/2012 11:23:15.301,SEND,OnOutBouMsgRcvd,Send: SIP/2.0 200 OK 
Via: SIP/2.0/UDP 10.0.0.171:64479;received=127.0.0.1 
From: To: <sip:mresources@127.0.0.1>;tag=5b60807d 
Call-ID: Lumenvox MRCPv2 Client@10.0.0.171:64479 
CSeq: 1 INVITE 
Contact: <sip:127.0.0.1:5070> 
User-Agent: LumenVox Media Server/11.0.300 
Allow: INVITE, OPTIONS, ACK, BYE, UPDATE Supported: timer 
Content-Type: application/sdp 
Content-Disposition: session 
Content-Length: 280
 
v=0
o=- 1234 5678 IN IP4 127.0.0.1 
s=- 
c=IN IP4 127.0.0.1 
t=0 0 
m=application 30000 TCP/MRCPv2 1 
a=setup:passive 
a=connection:new 
a=channel:FF693EB1E50F975F9780@speechsynth 
a=cmid:1 
m=audio 35002 RTP/AVP 0 c=IN IP4 127.0.0.1 
a=rtpmap:0 PCMU/8000 
a=sendonly a=mid:1 

Following SIP protocol, the client sends an ACK to acknowledge the OK, and this is logged out:

12/17/2012 11:23:15.302,RECV,HndlSipPrcsrTsk,ACK sip:mresources@127.0.0.1 SIP/2.0 
Allow: REGISTER,OPTIONS,INVITE,ACK,CANCEL,BYE,NOTIFY,PHACK,REFER,INFO,SUBSCRIBE,UPDATE 
Call-ID: Lumenvox MRCPv2 Client@10.0.0.171:64479 
Contact: <sip:127.0.0.1> 
Content-Length: 0 
Content-Type: application/sdp 
CSeq: 1 ACK 
From: <sip:10.0.0.171:64479> 
Max-Forwards: 70 
Supported: em,timer,replaces,path,resource-priority 
To: <sip:mresources@127.0.0.1> 
Via: SIP/2.0/UDP 10.0.0.171:64479 

12/17/2012 11:23:15.302,RECV,HndlSipPrcsrTsk,[ SIP Interface - GOT ACK ]
12/17/2012 11:23:15.302,DEBG,OnAckFromClient,CSipManagerMessageThread: Received ACK for CallID Lumenvox MRCPv2 Client@10.0.0.171:64479

The last stage in the setup of an MRCPv2 session is the actual MRCP connection (unlike MRCPv1 where RTSP is used to both setup the session and transmit the MRCP messages, MRCPv2 uses SIP to establish the session and then a separate TCP session for the MRCP communication):

12/17/2012 11:23:15.302,INFO,ListenerCB     ,Accepted new MRCP connection from 127.0.0.1 on port 22981, socket = 4636

During the synthesis or speech recognition events, at full verbosity the logs will contain all of the traffic between client and server. This should also help explain why verbosity is by default turned to 1 — a busy server running with full verbosity will generate a lot of log messages. This constant logging can cause performance issues, so in most production cases it is recommended that verbosity be left at 1 or 2.

Importantly, the Media Server logs will contain error messages when things go wrong. The most common error you will in the Media Server log is a response to a SETUP/INVITE message other than 200 OK. Here is an example of a failure in MRCPv1:

12/17/2012 11:40:52.003,DEBG,Rtsp_SETUP     ,RTSP: Received SETUP request 'rtsp://127.0.0.1:554/media/synthesizer'
12/17/2012 11:40:56.206,ERRO,CStrSy:OpenPort,TTSOpenPort returned -58
12/17/2012 11:40:56.206,ERRO,RTSP_Setup     ,Returning Busy Here due to open port failure (Could not obtain a license.), new StreamSynthesizer
12/17/2012 11:40:56.206,SEND,SendPacket     ,RTSP/1.0 486 Busy Here
CSeq: 1
Content-Length: 210
 
v=0
o=- 1234 5678 IN IP4 127.0.0.1
s=LumenVox Media Server/11.0.300
c=IN IP4 127.0.0.1
t=0 0
m=audio 35008 RTP/AVP 0 96
a=rtpmap:0 PCMU/8000
a=rtpmap:96 telephone-event/8000
a=fmtp:96 0-15
a=ptime:20 

12/17/2012 11:40:56.206,DEBG,Rtsp_SETUP     ,Sent Reply to SETUP request (CallIndex 5):
12/17/2012 11:40:56.208,INFO,conn_eventcb   ,[ MRCPV1 Client 5 Disconnected - 127.0.0.1:63429 ]

You can see from the log that the response to the SETUP request was 486 Busy Here. The ERRO log messages indicate the LumenVox error code associated with the attempt to open a TTS port (-58). The logs also indicate the longer version of the error message (“Could not obtain a license”). Here is the same sequence in MRCPv2:

12/17/2012 11:40:56.359,RECV,HndlSipPrcsrTsk,[ SIP Interface - GOT INVITE : Starting new call ]
12/17/2012 11:40:56.359,SEND,HndlSipPrcsrTsk,[ SIP Interface - SENT TRYING REPLY ]
12/17/2012 11:40:56.359,DEBG,PrepareResponse,CREATED SIP CALL Lumenvox MRCPv2 Client@10.0.0.171:50397
12/17/2012 11:40:56.359,SEND,OnOutBouMsgRcvd,Send: SIP/2.0 100 Trying 
Via: SIP/2.0/UDP 10.0.0.171:50397;received=127.0.0.1 
From: <sip:10.0.0.171:50397> 
To: <sip:mresources@127.0.0.1> 
Contact: <sip:127.0.0.1:5070> 
Call-ID: Lumenvox MRCPv2 Client@10.0.0.171:50397 
CSeq: 1 INVITE 
Content-Length: 0 

12/17/2012 11:40:56.360,ERRO,CStrSy:OpenPort,TTSOpenPort returned -58
12/17/2012 11:40:56.360,SEND,HndlSipPrcsrTsk,[ SIP Interface - SENT REPLY TO INVITE ]
12/17/2012 11:40:56.360,SEND,OnOutBouMsgRcvd,Send: SIP/2.0 486 Busy Here 
Via: SIP/2.0/UDP 10.0.0.171:50397;received=127.0.0.1 
From: <sip:10.0.0.171:50397> 
To: <sip:mresources@127.0.0.1>;tag=dfc16212 
Call-ID: Lumenvox MRCPv2 Client@10.0.0.171:50397 
CSeq: 1 INVITE 
Contact: <sip:127.0.0.1:5070> 
User-Agent: LumenVox Media Server/11.0.300 
Allow: INVITE, OPTIONS, ACK, BYE, UPDATE 
Supported: timer 
Content-Type: application/sdp 
Content-Disposition: session 
Content-Length: 280 
 
v=0 
o=- 1234 5678 IN IP4 127.0.0.1 
s=- 
c=IN IP4 127.0.0.1 
t=0 0 
m=application 30002 TCP/MRCPv2 1 
a=setup:passive 
a=connection:new 
a=channel:08AE589D992599384A76@speechsynth 
a=cmid:1 
m=audio 35010 RTP/AVP 0 
c=IN IP4 127.0.0.1 
a=rtpmap:0 PCMU/8000 
a=sendonly 
a=mid:1 

Note that in generating these failures, we also got the following log messages in our lumenvox_critical.txt log file:

12/17/2012 11:40:56.206,CRIT,RplyMQRoutrClnt,030B1F00 Failed to connect to server 127.0.0.1:7569
12/17/2012 11:40:56.206,CRIT,LicClntRqstPort,030B1F00 Failed to allocate TTS license resource. No server available
12/17/2012 11:40:56.360,CRIT,LicClntRqstPort,030B1F00 Failed to allocate TTS license resource. No server available

The vast majority of problems related to MRCP-enabled voice platforms can be identified just by looking through the critical log and the Media Server log, sometimes in conjunction.