Full Debugging of a Modem INF File Using Modem Event Logs

Running the MCT can usually provide a gross pass/fail result. However, subtle errors, such as a response string missing from your INF file, can sneak through MCT validation. Examining a debug log of any MCT or dialout session is important to ensure INF robustness and accuracy.

Setting Up a Modem Event Logging Session

The Modem Development Kit provides two executables, LOGGER.VXD and LOGWIN.EXE, which enable you to produce logs in real-time of the events during an MCT run or dialout session. You can display the event log in a window on the screen and/or save the log in a file (named MODEMLOG.TXT) in the WINDOWS subdirectory.

IMPORTANT:

Before any modem event logs can be produced, LOGGER.VXD must be copied from the MDK to your WINDOWS\SYSTEM directory.

To produce the modem event logging information, you must:

1. Make sure your modem is enabled; for example, an external modem must be powered on and connected to a communications port.

2. Enable event logging in the Modem Control Panel.

3. Start up LOGWIN.EXE.

4. Begin your MCT or modem dialout session.

The procedure for enabling event logging, starting LOGWIN.EXE, and starting an MCT session is given in more detail below:

1. Click the Start button, point to Settings, and then click the Control Panel.

2. Double-click the Modems icon in the Control Panel.

3. In the Modems Properties dialog, select the General tab and click the Properties button.

4. When a Properties dialog for your modem appears, select the Connection tab and click the Advanced button.

5. In the Advanced Connection Settings dialog, check the option Record a Log File and click OK on all the open dialogs.

6. Click the Start button and select the Run option.

7. Use the Run dialog to browse for LOGWIN.EXE and then run it.

8. Begin your MCT or modem dialout session. The modem event log data will appear in the LOGWIN.EXE window on-screen. The same information is also always recorded in the file MODEMLOG.TXT in your WINDOWS subdirectory.

NOTE:

If LOGWIN.EXE is not running when you start an MCT or modem dialout session, no log information will appear on the screen and no log information will be written into MODEMLOG.TXT.

Using the Terminal Application as a Debugging Aid

You can use TERMINAL.EXE from Windows 3.1 for simple init and AT command debugging. This is useful if a modem event log file indicates an error immediately after a specific init or command.

1. Copy the program TERMINAL.EXE from Windows 3.1 to your computer (if not already present).

2. Close MCT if it is running.

3. Set up Terminal to access the modem.

4. Issue various AT commands until you find one or more commands which do not produce an OK response in Terminal.

5. Modify these commands in your INF, or remove them from the INF entirely.

6. Uninstall the modem from the Control Panel and reinstall it again so that the newly modified INF is in use.

7. Rerun the MCT.

Another debugging shortcut is to cut and paste, via the Windows clipboard, init strings from an INF into Terminal and then connect to a slave modem to see what verbose or numeric responses you receive.

Interpreting Modem Event Logs

Two sample modem event logs produced by LOGWIN.EXE are shown below, one for a data modem session and the other for a voice modem session. In order to interpret the event logs, you need to understand the following about how LOGWIN.EXE and Unimodem/V work together to produce the logs.

When Unimodem/V receives a DLE from the modem, the DLE is translated to a standard event. Below is the table that maps the translated value to the event. The modem log displays the actual DLE received and it's translated value.

Sample Data Modem Event Log

Following is a sample data modem event log, with annotations added to the logged events.

05:02:55 05-25-1994 - TI V.32bis-V.17 Internal in use.
05:02:55 05-25-1994 - Modem type: TI V.32bis-V.17 Internal

An application has called TAPI to open this modem's line handle. UNIMODEM.TSP called the Win32 function CreateFile("TI V.32bis-V.17 Internal"...) to open a file handle to UNIMODEM.VXD for this modem.

05:02:56 05-25-1994 - 38400,N,8,1

Unimodem has called VCOMM to open the correct serial port for this modem, and set its default COM port settings.

05:02:56 05-25-1994 - Initializing modem.
05:02:56 05-25-1994 - Send: AT

Unimodem sends an "AT" to initialize the modem's autobaud setting.

05:02:57 05-25-1994 - Recv: ATfOK
05:02:57 05-25-1994 - Interpreted response: Ok

The "ATcr" is echoed back by the modem, along with an "OK" response code. Unimodem discards the echoed command, and correctly interprets the OK response.

05:02:57 05-25-1994 - Send: AT &F0 
05:02:59 05-25-1994 - Recv: AT &F0 fOK
05:02:59 05-25-1994 - Interpreted response: Ok

Unimodem sends the first Init string specified in the INF, discards the echoed command, and interprets the OK response correctly.

05:02:59 05-25-1994 - Send: AT E0 Q0 V0 W1 T L2 M1 &C1 
05:03:01 05-25-1994 - Recv: AT E0 Q0 V0 W1 T L2 M1 &C1 0
05:03:01 05-25-1994 - Interpreted response: Ok

Unimodem sends the second Init string from the INF. The command is echoed back, but notice that numeric response codes are now in use.

05:03:01 05-25-1994 - Send: AT &D2 &S0 X4 %C1 \J0 \N7 \Q3 \V1 \T0 
05:03:03 05-25-1994 - Recv: 0
05:03:03 05-25-1994 - Interpreted response: Ok

Unimodem successfully sends the third Init string from the INF. Note that this command was not echoed back by the modem.

05:03:03 05-25-1994 - Send: ATS7=50\T0L2M1%C1\N7\Q3B1X4
05:03:04 05-25-1994 - Recv: 0
05:03:04 05-25-1994 - Interpreted response: Ok

This is the dynamic initialization stage. Unimodem sent a string to configure the modem to settings requested by the user and/or application. The command string is built dynamically based on registry keys, originally specified by "Settings" values in the INF file.

05:03:04 05-25-1994 - Dialing ''.
05:03:04 05-25-1994 - Send: ATX4
05:03:06 05-25-1994 - Recv: 0
05:03:07 05-25-1994 - Interpreted response: Ok

Unimodem first sets dial tone detection on.

05:03:07 05-25-1994 - Send: ATDT;
05:03:09 05-25-1994 - Recv: 0
05:03:09 05-25-1994 - Interpreted response: Ok

Unimodem takes the modem off-hook.

05:03:09 05-25-1994 - Dialing '9242 9992'.
05:03:09 05-25-1994 - Send: ATX4
05:03:11 05-25-1994 - Recv: 0
05:03:11 05-25-1994 - Interpreted response: Ok

Unimodem sets dial tone detection on again (probably a bug).

05:03:11 05-25-1994 - Send: ATDT9242 9992;
05:03:15 05-25-1994 - Recv: 0
05:03:15 05-25-1994 - Interpreted response: Ok

Unimodem dials the phone number provided by the application via a TAPI lineMakeCall function.

05:03:15 05-25-1994 - Originating the call.
05:03:15 05-25-1994 - Send: ATX3D

Unimodem originals the call. Note that 'X3' is included because this modem will not work correctly without it. Some modems do not require this.

05:03:30 05-25-1994 - Recv: 527769
05:03:30 05-25-1994 - Interpreted response: Ignore

"Ignore" is misleading. Here, Unimodem recognized "52" as a call progress response code.

05:03:30 05-25-1994 - Recv: 7769
05:03:30 05-25-1994 - Interpreted response: Ignore

Unimodem recognized "77" as a call progress response code.

05:03:30 05-25-1994 - Recv: 69
05:03:30 05-25-1994 - Interpreted response: Connect

Unimodem recognized "69" as indication of a connection.

05:03:30 05-25-1994 - Connection established at 14400bps.
05:03:30 05-25-1994 - Error-control activated.
05:03:30 05-25-1994 - No data compression, or modem does not support compression reporting.

Unimodem knows that this is a 14400 call with error compression but no data compression, based on the "527769" response codes.

The call is now in progress, in use by the application.

05:03:41 05-25-1994 - Remote modem hung up.

Unimodem detected carrier loss. The call was disconnected by the other computer. This output would appear different if Unimodem had been called to disconnect.

05:03:41 05-25-1994 - Hanging up the modem.

Unimodem dropped DTR to cause the modem to hang up.

05:03:41 05-25-1994 - TI V.32bis-V.17 Internal closed.

UNIMODEM.TSP closed its Win32 file handle to the modem.

Sample Voice Modem Event Log

Following is a sample voice modem event log, with annotations added to the logged events.

11-08-1995 14:49:28.64 - Microsoft Voice Modem in use.

<p>11-08-1995 14:49:28.69 - Modem type: Microsoft Voice Modem

An application has called TAPI to open this modem's line handle. UNIMODEM.TSP called the Win32 function CreateFile("Microsoft Voice Modem"...) to open a file handle to UNIMODEM.VXD for this modem.

11-08-1995 14:49:28.95 - 19200,N,8,1

Unimodem has called VCOMM to open the correct serial port for this modem, and set its default COM port settings.

11-08-1995 14:49:29.52 - Initializing modem.
11-08-1995 14:49:29.52 - Send: AT
11-08-1995 14:49:29.52 - Recv: AT
11-08-1995 14:49:29.67 - Recv: OK
11-08-1995 14:49:29.67 - Interpreted response: Ok
11-08-1995 14:49:29.67 - Send: AT &F E0 V1 &D2 &C1 W2 S95=47
11-08-1995 14:49:29.68 - Recv: AT &F E0 V1 &D2 &C1 W2 S95=47
11-08-1995 14:49:29.82 - Recv: OK
11-08-1995 14:49:29.82 - Interpreted response: Ok
11-08-1995 14:49:29.82 - Send: ATS7=60S30=0L1M1\N3%C3&K3B0 N1X4
11-08-1995 14:49:29.98 - Recv: OK
11-08-1995 14:49:29.98 - Interpreted response: Ok
11-08-1995 14:49:29.98 - Waiting for a call.

Normal data init process.

11-08-1995 14:49:29.98 - Send: at#cid=1
11-08-1995 14:49:30.14 - Recv: OK
11-08-1995 14:49:30.14 - Interpreted response: Ok

EnableCallerID commands sent to modem.

11-08-1995 14:49:30.14 - Send: at-sdr=7
11-08-1995 14:49:30.27 - Recv: OK
11-08-1995 14:49:30.27 - Interpreted response: Ok

EnableDistinctiveRing commands sent to modem.

11-08-1995 14:49:30.27 - Send: ATS0=0
11-08-1995 14:49:30.41 - Recv: OK
11-08-1995 14:49:30.41 - Interpreted response: Ok

Monitoring command sent to modem.

11-08-1995 14:49:44.25 - Recv: RING1
11-08-1995 14:49:44.25 - Interpreted response: Distinctive Ring A

Incoming ring. Since distinctive ringing is enabled, distinctive ring is reported.

11-08-1995 14:49:46.90 - Answering the voice call.
11-08-1995 14:49:46.90 - Send: at#cls=8
11-08-1995 14:49:47.16 - Recv: OK
11-08-1995 14:49:47.16 - Interpreted response: Ok
11-08-1995 14:49:47.16 - Send: at#vls=0
11-08-1995 14:49:47.31 - Recv: OK
11-08-1995 14:49:47.31 - Interpreted response: Ok
11-08-1995 14:49:47.31 - Send: at#vbt=1
11-08-1995 14:49:47.45 - Recv: OK
11-08-1995 14:49:47.45 - Interpreted response: Ok
11-08-1995 14:49:47.45 - Send: at#vsr=7200
11-08-1995 14:49:47.59 - Recv: OK
11-08-1995 14:49:47.59 - Interpreted response: Ok
11-08-1995 14:49:47.59 - Send: at#vbs=4
11-08-1995 14:49:47.73 - Recv: OK
11-08-1995 14:49:47.74 - Interpreted response: Ok
11-08-1995 14:49:47.74 - Send: ats30=60
11-08-1995 14:49:47.88 - Recv: OK
11-08-1995 14:49:47.88 - Interpreted response: Ok
11-08-1995 14:49:47.88 - Send: ata

VoiceAnswer commands sent to modem. This happens in response to the TAPI function lineAnswer.

11-08-1995 14:49:48.11 - Recv: VCON
11-08-1995 14:49:48.11 - Interpreted response: Ok

Voice connect response. The voice connect response is normally mapped to an OK response.

11-08-1995 14:49:48.11 - Issuing Speakerphone command.
11-08-1995 14:49:48.11 - Send: at#vls=6
11-08-1995 14:49:48.26 - Recv: OK
11-08-1995 14:49:48.26 - Interpreted response: Ok

SpeakerphoneEnable commands sent to modem.

11-08-1995 14:49:48.26 - Send: at#vls=6
11-08-1995 14:49:48.41 - Recv: OK
11-08-1995 14:49:48.41 - Interpreted response: Ok
11-08-1995 14:49:48.41 - Send: at#spk=0,,,
11-08-1995 14:49:48.55 - Recv: OK
11-08-1995 14:49:48.55 - Interpreted response: Ok

SpeakerphoneMute commands sent to modem.

11-08-1995 14:49:48.55 - Send: at#vls=6
11-08-1995 14:49:48.69 - Recv: OK
11-08-1995 14:49:48.69 - Interpreted response: Ok
11-08-1995 14:49:48.69 - Send: at#spk=,0,3
11-08-1995 14:49:48.84 - Recv: OK
11-08-1995 14:49:48.84 - Interpreted response: Ok

SpeakerphoneSetVolumeGain commands sent to modem

The above commands (SpeakerphoneEnable, SpeakerphoneMute, and SpeakerphoneSetVolumeGain) are sent in response to the TAPI call phoneSetHookSwitch(hPhone, PHONESHOOKSWITCHDEV_SPEAKER, PHONEHOOKSWITCHMODE_SPEAKER), which takes the speakerphone off hook, and mutes it.

11-08-1995 14:49:48.84 - Voice Modem Wave Open.

waveOutOpen/waveInOpen called

11-08-1995 14:49:48.85 - Setting wave format.
11-08-1995 14:49:48.85 - Send: at#vls=0
11-08-1995 14:49:48.99 - Recv: OK
11-08-1995 14:49:48.99 - Interpreted response: Ok

LineSetPlayFormat commands sent to modem.

11-08-1995 14:49:48.99 - Starting wave play/record.
11-08-1995 14:49:48.99 - Send: at#vtx
11-08-1995 14:49:49.17 - Recv: CONNECT
11-08-1995 14:49:49.17 - Interpreted response: Connect

StartPlay commands sent to modem.

11-08-1995 14:49:49.40 - Received DLE Raw=117, Translated=255.

DLE received from modem. The Raw value is the actual value received, and the Translated value is the value Unimodem has mapped it to. See the DLE translation table in Interpreting Modem Event Logs. In this example, the DLE is translated to 255, which means that Unimodem/V ignores this DLE.

11-08-1995 14:49:54.78 - Ending wave play/record.
11-08-1995 14:49:54.78 - Voice Modem Wave Close.

waveInClose/waveOutClose has been called.

.
.
.
11-08-1995 14:50:41.48 - Received DLE Raw=49, Translated=1.

DLE received from modem. This is translated to the DTMF digit 1.

11-08-1995 14:50:41.51 - Ending wave play/record.
11-08-1995 14:50:41.51 - Voice Modem Wave Close.

waveInClose/waveOutClose has been called.

11-08-1995 14:50:41.94 - Received DLE Raw=35, Translated=15.

DLE received from modem. This is translated to the DTMF digit #.