Understanding Debug Log Output

The Tellme Studio Debug Log Viewer provides real-time access to your call logs when you run voice applications on Tellme Studio. The Log Viewer traces your application as it executes and includes the following types of information:

This document explains how to interpret and customize the output from the Log Viewer.

Each log message belongs to a single class of log messages. A log message class is identified by a specific color and one or more text keywords. The Log Viewer displays each message in the following general format:

[mm/dd/yyyy] KEYWORD message_detail

The date is in Greenwich Mean Time (GMT).

The following table lists the background color and keywords for each log message class.

Class Color Keyword(s)
Call flow
GOTO
Occurs when the interpreter encounters a goto element.
SELECTED
Occurs when the interpreter begins executing a form or form item.
LEAVING
Occurs when the interpreter finishes executing a form or form item.
Custom
DEBUG
Occurs when the interpreter executes a log element.
Deprecation Warnings
DEPRECATED
Occurs when the interpreter executes a code path that has been deprecated.
Events
NOINPUT
Occurs when the interpreter throws a noinput event.
NOMATCH
Occurs when the interpreter throws a nomatch event.
THROW
Occurs when the interpreter throws an application- or pre-defined event.
File fetches
FILE
Occurs when the interpreter loads a VoiceXML document or other external resource.
Metadata
METADATA
Occurs when the interpreter encounters a meta element in a VoiceXML document.
Recognition
BARGE_IN
Occurs when the recognizer detects that the user has barged-in on a prompt.
LISTEN
Occurs when the interpreter enters a listen state.
RECOGNIZED
Occurs when the recognizer returns a recognition result to the interpreter.
Results
FILLED
Occurs when the interpreter fills an input item (field) with a recognition result.
Tasks
TASK
Occurs when the interpreter executes a log element containing a task completion label. For more information on measuring task completion contact your Solutions Manager.
Telephony
HANGUP
Occurs when the recognizer detects a hangup.
TRANSFER
Occurs when the interpreter executes a transfer element.
Uncategorized
UNKNOWN
Occurs when the interpreter produces a log event for which the Log Viewer has no predefined knowledge. To view the details of uncategorized events, click the "show detail" link.

The VoiceXML interpreter fetches the resources that comprise your voice application from your Web servers and executes them. Such resources include VoiceXML documents, audio files, grammars, and JavaScript files. With the exception of audio files, the Debug Log Viewer displays information about each file fetch.

The following snippet reflects Log Viewer output for the fetching of the fictitious VoiceXML document http://www.example.org/voice/index.vxml. According to the final log message, the file load summary, the file took 10 milliseconds (ms) to load.

[6/17/2003 05:27:02] FILE Checking modification time of http://www.example.org/voice/index.vxml against 6/17/2003 04:56:55 GMT.
[6/17/2003 05:27:02] FILE Beginning to read http://www.example.org/voice/index.vxml [id=0].
[6/17/2003 05:27:02] FILE Kicking possible old version of http://www.example.org/voice/index.vxml out of the cache.
[6/17/2003 05:27:02] FILE Reading 846 bytes... [id=0]
[6/17/2003 05:27:02] FILE Finished reading http://www.example.org/voice/index.vxml [id=0].
[6/17/2003 05:27:02] FILE http://www.example.org/voice/index.vxml LOADED [ Load time 10 ms; HTTP code 200; Parse time 2 ms.]

You can use file fetch information to diagnose performance issues related to your application. In addition to file load times, observe whether or not the resource was loaded from the cache. The Tellme VoiceXML interpreter follows HTTP caching rules.

Call flow messages describe how the VoiceXML interpreter steps through your VoiceXML application according to the Form Interpretation Algorithm (FIA). Call flow messages occur when the interpreter begins executing a document, or when it enters a container such as a form or a form item such as a block or a field.

The following code snippet consists of two documents. The first document ("index.vxml") includes a form containing a block ("blk1"). The block navigates to the second document ("doc1.vxml"). The second document contains a single field ("airport"). When the user utters a valid airport, execution of the filled navigates back to the first document.

<?xml version="1.0"?>
<!-- index.vxml -->
<vxml version="2.1"
 xmlns="http://www.w3.org/2001/vxml">
<form id="form1">
  <block name="blk1">
    <goto next="doc1.vxml"/>
  </block>
</form>
</vxml>

<?xml version="1.0"?>
<!-- doc1.vxml -->
<vxml version="2.1"
 xmlns="http://www.w3.org/2001/vxml">
<form id="form1">
  <field name="airport">
    <prompt>
      Choose an airport.
    </prompt>
    <grammar src="airports.grxml" mode="voice" type="application/srgs+xml"/>
    <filled>
      You said <value expr="airport"/>
      <goto next="index.vxml"/>
    </filled>
  </field>
</form>
</vxml>

The Debug Log output corresponding to the previous code follows. Call flow messages are preceded by the keyword "GOTO", "SELECTED", or "LEAVING". File messages are preceded by the keyword "FILE"

[07/09/03 18:26:38] GOTO next="http://www.example.org/voice/index.vxml"
[07/09/03 18:26:38] FILE http://www.example.org/voice/index.vxml LOADED [ Load time 17 ms; HTTP code 200; Parse time 1 ms.]
[07/09/03 18:26:38] SELECTED http://www.example.org/voice/index.vxml#form1
[07/09/03 18:26:38] SELECTED http://www.example.org/voice/index.vxml#blk1
[07/09/03 18:26:38] GOTO next="doc1.vxml"
[07/09/03 18:26:38] FILE http://www.example.org/voice/doc1.vxml LOADED [ Load time 9 ms; HTTP code 200; Parse time 2 ms.]
[07/09/03 18:26:38] LEAVING http://www.example.org/voice/index.vxml#blk1
[07/09/03 18:26:38] LEAVING http://www.example.org/voice/index.vxml#form1
[07/09/03 18:26:38] SELECTED http://www.example.org/voice/doc1.vxml#form2
[07/09/03 18:26:38] SELECTED http://www.example.org/voice/doc1.vxml#airport
[07/09/03 18:26:38] FILE http://www.example.org/grammars/airports.grxml NOT_MODIFIED [ Load time 15 ms;]
[07/09/03 18:26:44] LEAVING http://www.example.org/voice/doc1.vxml#airport
[07/09/03 18:26:44] SELECTED http://www.example.org/voice/doc1.vxml#airport
[07/09/03 18:26:44] FILE http://www.example.org/grammars/airports.grxml NOT_MODIFIED [ Load time 6 ms;]
[07/09/03 18:26:51] LEAVING http://www.example.org/voice/doc1.vxml#airport
[07/09/03 18:26:51] SELECTED http://www.example.org/voice/doc1.vxml#airport
[07/09/03 18:26:51] FILE http://www.example.org/grammars/airports.grxml NOT_MODIFIED [ Load time 7 ms;]
[07/09/03 18:26:55] LEAVING http://www.example.org/voice/doc1.vxml#airport
[07/09/03 18:26:55] SELECTED http://www.example.org/voice/doc1.vxml#airport
[07/09/03 18:26:55] GOTO next="index.vxml"
[07/09/03 18:26:55] FILE http://www.example.org/voice/index.vxml NOT_MODIFIED[ Load time 8 ms;]
[07/09/03 18:26:55] LEAVING http://www.example.org/voice/doc1.vxml#airport
[07/09/03 18:26:55] LEAVING http://www.example.org/voice/doc1.vxml#form2

You use the log element to emit custom log messages into your call log.

The following example performs a simple calculation of the area of a circle given the radius, assigns the result to a variable ("area"), and outputs the value of the variable into the debug log.

<?xml version="1.0"?>
<vxml version="2.1"
 xmlns="http://www.w3.org/2001/vxml">
<form>
  <block>
    <var name="radius" expr="10"/>
    <var name="area" expr="Math.PI * Math.pow(radius, 2)"/>
    <log>area = <value expr="area"/></log>
    <exit/>
  </block>
</form>
</vxml>

The Debug Log output corresponding to the previous code follows.

DEBUG area = 314.159

The interpreter outputs deprecation warnings when it executes code that will no longer be supported in a future version of the Tellme Voice Application Network. You should make every effort to modify your code to eliminate the deprecation warning.

In the following example, the code neglects to include an explicit exit or disconnect element. Instead the code simply falls off the end of the form.

<?xml version="1.0"?>
<vxml version="2.1"
 xmlns="http://www.w3.org/2001/vxml">
<form>
  <block>
    <prompt>Hello, world.</prompt>
    <!-- should exit or disconnect -->
  </block>
</form>
</vxml>

The corresponding Debug Log output follows:

[07/09/03 19:39:29] DEPRECATED: being translated into goto _home
[07/09/03 19:39:29] DEPRECATED: goto _home should no longer be used.

The interpreter emits a log message whenever a predefined or a custom event is thrown.

The following code snippet requests an airport from the user. If the timeout interval elapses and the user doesn't specify any input, the interpreter throws a noinput event. If the user utters an invalid airport, the interpreter throws a nomatch event. If the user specifies an invalid airport three times, the nomatch handler throws a custom event com.example.reservations.operator.

<?xml version="1.0"?>
<vxml version="2.1"
 xmlns="http://www.w3.org/2001/vxml">
<catch event="com.example.reservations.operator">
  <goto next="operator.vxml"/>
</catch>
<form id="form1">
  <field name="airport">
    <prompt>
      Choose an airport.
    </prompt>
    <grammar src="airports.grxml" type="application/srgs+xml" mode="voice"/>

    <noinput>
      Sorry. Didn't hear you.
      <reprompt/>
    </noinput>
    <nomatch>
      Sorry. Didn't get that.
      <reprompt/>
    </nomatch>
    <catch event="nomatch noinput" count="3">
      <throw event="com.example.reservations.operator"/>
    </catch>    

    <filled>
      You said <value expr="airport"/>
      <exit/>
    </filled>
  </field>
</form>
</vxml>

The corresponding Debug Log output follows:

[07/09/03 20:27:55] FILE http://www.example.org/voice/airports.grxml NOT_MODIFIED [ Load time 9 ms;]
[07/09/03 19:59:35] LISTEN
[07/09/03 20:28:00] NOMATCH [airport]
[07/09/03 20:28:00] FILE http://www.example.org/voice/airports.grxml NOT_MODIFIED [ Load time 8 ms;]
[07/09/03 19:59:35] LISTEN
[07/09/03 20:28:12] NOINPUT [airport]
[07/09/03 20:28:00] FILE http://www.example.org/voice/airports.grxml NOT_MODIFIED [ Load time 8 ms;]
[07/09/03 19:59:35] LISTEN
[07/09/03 20:28:12] NOMATCH [airport]
[07/09/03 20:28:00] FILE http://www.example.org/voice/airports.grxml NOT_MODIFIED [ Load time 8 ms;]
[07/09/03 19:59:35] LISTEN
[07/09/03 20:28:12] NOMATCH [airport]
[07/09/03 20:28:12] THROW com.example.reservations.operator

For more information on VoiceXML events, see the Events tutorial.

The interpreter emits information about voice and DTMF recognition in your debug log output. The following code example prompts the user for an airport and listens for the user's response.

<?xml version="1.0"?>
<vxml version="2.1"
 xmlns="http://www.w3.org/2001/vxml">
<form id="form1">
  <field name="airport">
    <prompt>
      Choose an airport.
    </prompt>
    <grammar src="airports.grxml" type="application/srgs+xml" mode="voice"/>
    <filled>
      You said <value expr="airport"/>
      <exit/>
    </filled>
  </field>
</form>
</vxml>

The corresponding Debug Log output follows:

[07/09/03 19:59:35] FILE http://www.example.org/voice/index.vxml LOADED [ Load time 6 ms; HTTP code 200; Parse time 2 ms.]
[07/09/03 19:59:35] LISTEN
[07/09/03 19:59:35] FILE http://www.example.org/grammars/airports.grxml LOADED [ Load time 10 ms; HTTP code 200; Parse time 2 ms.]
[07/09/03 19:59:58] RECOGNIZED slot [airport] = [boston_ma], result = [boston massachusetts], confidence = 68%

The interpreter emits a log message when a recognition occurs and the interpreter fills an input item with the result. In the previous code example, if the user specifies a valid airport, the input item airport is filled with the recognition result.

If the user says "Boston, Massachusetts", the corresponding Debug Log output follows:

[07/09/03 18:26:55] FILLED "boston_ma"

The interpreter emits a log message whenever the interpreter executes a transfer, a disconnect or detects a hangup.

The following code snippet executes a disconnect.

<?xml version="1.0"?>
<vxml version="2.1"
 xmlns="http://www.w3.org/2001/vxml">
<form>
  <block>
    <disconnect/>
  </block>
</form>
</vxml>

The corresponding Debug Log output is shown below.

[07/09/03 23:03:42] FILE http://www.example.org/voice/index.vxml LOADED [ Load time 44 ms; HTTP code 200; Parse time 1 ms.]
[07/09/03 23:03:42] HANGUP
[07/09/03 23:03:42] THROW "telephone.disconnect.hangup"

The following code snippet executes a transfer.

<?xml version="1.0"?>
<vxml version="2.1"
 xmlns="http://www.w3.org/2001/vxml">
<form>
  <transfer name="xfer" dest="tel:+18005558355" bridge="true" maxtime="10s">
    <filled>
      <log>xfer filled with <value expr="xfer"/></log>
    </filled>      
  </transfer>

  <block>
    <exit/>
  </block>
</form>
</vxml>

The corresponding Debug Log output is shown below.

[07/09/03 23:14:31] TRANSFER to tel:+18005558355 starting...
[07/09/03 23:15:08] TRANSFER to tel:+18005558355 ended because the original caller hung up.
[07/09/03 23:15:09] HANGUP

The interpreter emits a log message whenever the interpreter encounters runtime error in your voice application.

The following code snippet references an undefined variable.

<?xml version="1.0"?>
<vxml version="2.1"
 xmlns="http://www.w3.org/2001/vxml">
<error>
  <prompt>Sorry. An error has occurred.</prompt>
  <log>error handler caught: <value expr="_event"/></log>
  <disconnect/>
</error>

<form>
  <block>
    <!-- reference to an undefined var -->
    <var name="x" expr="y"/>   
  </block>
</form>

</vxml>

When executed, the Debug Log output follows:

[07/09/03 23:52:18] FILE http://www.example.org/voice/index.vxml LOADED [ Load time 9 ms; HTTP code 200; Parse time 1 ms.]
[07/09/03 23:52:18] JAVASCRIPT ERROR "ReferenceError: y is not defined" on line 0
[07/09/03 23:52:18] ERROR "error setting 'x' variable; probably an error parsing a 'name' or 'expr' attribute" at <var> tag (line 13, column 4 in file http://www.example.org/voice/index.vxml)
[07/09/03 23:52:18] THROW "error.semantic"

You can customize the output from the debug log in two ways:

  • By modifying your Tellme Studio preferences.
  • By setting the filters for a specific log request.

Your Studio preferences allow you to set the filter for all of your log requests. To set your global log filter preferences, following these steps:

  1. Navigate to your Studio preferences
  2. Scroll down to the "Debug Log Message Filters" section of the page.
  3. Check and uncheck the specific log message classes that you wish to display and hide.
  4. Scroll to the bottom of your preferences page, and click the "Submit" button.

Subsequent logs requests will display only those log message classes that you selected.

Note. Error messages cannot be filtered and are always displayed.

When you make a request for a specific log, the window that displays the log presents you with a set of checkboxes. Each checkbox corresponds to a specific class of log messages.

A checkbox is enabled only if the corresponding message class is enabled in your global Studio preferences.

To enable or disable one or more message classes, check or uncheck the corresponding checkbox, and click the filter button.

Note. The filter options for the current log are only available if you are using Microsoft Internet Explorer 4.0 or later.

[24]7 Inc.| Terms of Service| Privacy Policy| General Disclaimers