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]
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.
