11 — Application Debugging with the RPC Event Logger

[Previous] [Next] [Contents] [Index]

11.1 Overview of Debugging Support

The RPC IDL compiler in Gradient DCE for Tru64 UNIX includes enhanced application debugging support beyond the support provided with OSF DCE. The IDL compiler includes the RPC Event Logger — a software utility that records information about operations relating to the execution of an application. Operational information about the program state at a specific point during processing, called an event, is recorded in a file, called an event log. You have the option of directing event logging information to the terminal screen, rather than to a file. In this guide, the terms event log and log are used interchangeably to refer to the stream of logging output captured in the event log file or displayed on the screen.

Event logging provides a detailed, low-level view of the execution of your RPC application. If development of your RPC application is proceeding well, this level of detail may not be necessary. However, when you are in the debugging phase of application development, the continuous execution information provided by the Event Logger and the ability to change the type and timing of logging can be valuable.

11.2 Introduction to the RPC Event Logging Facility

When event logging is enabled, the Event Logger creates one log for each client and server process. To enable the RPC Event Logger, you specify an IDL compiler option that traces events (described in "Enabling Event Logging").

Enabling event logging when compiling allows you the option of generating logs at runtime without rebuilding the application. Once logging is enabled, you can use environment variables and the RPC Log Manager (rpclm) to control logging operations. The Log Manager provides a command interface for changing logging operations during application execution.

The RPC Event Logger records events about application calls, context handles, errors, miscellaneous events, and logging operations. These are called event types. Typical RPC events include the following:

• call_start — A client application made a call to a server.

• call_failure — A client stub terminated abnormally either through an exception or failing status.

• exception — An exception was detected in the server stub, and the exception caused the call to terminate.

• context_rundown — A context handle on a server was freed by the context rundown procedure.

For application calls, the Event Logger generates events that signal call activation, the call start and end, attempts to rebind to a server, and termination of a server thread.

For context handles, the Event Logger generates events that signal context handle creation and deletion by the client and server, and context handle modification, removal, and rundown.

For errors, the Event Logger generates events that signal call and receive failure from the client, exceptions, server failure, and call transmission failure from the server.

The miscellaneous events provide information about the application manager routine, and input and output argument processing events.

The logging operation itself generates events that display the logging output device, and that signal modification of logging parameters, and event log start and stop.

As a result of using the -trace option in the IDL compile command, idl, RPC events are generated by code in the client and server stub modules created by the compiler. Note that some events are generated at selected points in the RPC runtime library. For this reason, certain events, such as those relating to the logging operation, are always generated into the application code in addition to the event types you specify.

The events generated in each of these areas are shown in Table 11-1. The first column lists events that can be generated, and the second column indicates whether the client or server, or both, can generate the event. See Section 11.7 on page 133 for a complete description of each event.

Table 11-1: Event Types

Event Name	Origin
Call Events
activate	server
call_end	client
call_start	client
rebind	client
terminate	server
Context Handle Events
client_ctx_created	client
client_ctx_deleted	client
client_ctx_destroyed	client
context_created	server
context_deleted	server
context_modified	server
context_rundown	server
Error Events
call_failure	client
exception	server
receive_fault	client
status_fail	server
transmit_fault	server
Miscellaneous Events
await_reply	client
manager_call	server
manager_return	server
receive	client
Logging Events
internal_error	client, server
listening	client, server
log_events	client, server
log_file	client, server
log_start	client, server
log_stop	client, server

In the event log, each event is described on a single line divided into five fields. The five fields are defined in the table below.

Table 11-2: Event Log Fields

Field	Field Description
Event Time	The system clock at the time of the event. Events are listed chronologically in the log.
Thread Identity	The hostname, process ID, and thread ID.
Operation Name	The interface and operation name (if available).
Event Name	Name of the event.
Event Data	Data related to the event. This field contains either specific information about logging operations or a string binding that uniquely identifies the client process, server process, or Log Manager process.

The following is an example of an event log generated for an RPC client. The log contains five columns. To improve readability, columns four and five are shown below the first three columns. In addition, the field names have been added to identify the events; the names do not appear in an actual event log. (In subsequent event log examples, the field names are occasionally used instead of actual data to improve readability where necessary.)

EVENT TIME                          THREAD IDENTITY   OPERATION NAME

1994-02-07:11:48:18.31.160-5:0010.121  ifdef:8710/1      binopwk.binopwk_add   

1994-02-07:11:48:18.32.170-5:0010.121  ifdef:8710/1      binopwk.binopwk_add   

1994-02-07:11:48:18.65.180-5:0010.121  ifdef:8710/1      binopwk.binopwk_add   

EVENT NAME								         EVENT DATA

log_start							          all
call_start								         ncacn_ip_tcp:16.31.48.109[1821]
call_end

This small event log indicates that the following events occurred:

1. The log_start event indicates that logging started on February 7, 1994, at 11:48 a.m. on the host named ifdef, in process number 8710, and in thread number 1. Event logging was enabled when the binopwk interface was compiled with the IDL -trace option. The RPC call to the binopwk_add operation in the binopwk interface caused logging to begin and is the first event logged. The Event Data field indicates that all events are being logged.

2. The call_start event indicates an attempt to execute a call to a server. The string binding in the Event Data field shows that the call was made over the TCP/IP transport to host 16.31.48.109 with endpoint 1821. This string binding identifies the server being contacted.

3. The call_end event indicates that the RPC call is completed, and control has returned to the caller of binopwk_add.

This log indicates that the RPC call to the binopwk_add interface was successful because no error events occurred.

11.3 Generating RPC Event Logs

In general, to create an event log you must follow these four basic steps:

1. Specify the -trace option in your idl command line to enable event logging.

2. Compile and link the application.

3. Assign the event log to a filename or to the screen.

4. Execute the application.

The next sections describe how to use the -trace option.

11.3.1 Enabling Event Logging

To enable event logging, specify the -trace option when you use the idl command to compile an interface. The syntax of the idl command with the -trace option is as follows:

% idl filename -trace value

Event types are specified as a value of -trace. Valid values and the event types they denote are listed in the table below.

Table 11-3: Event Values and Types

Value	Event Type
all	Log all events
none	Disable all previously specified trace options
calls	Log events relating to all RPC calls
context	Log events relating to context handles
errors	Log errors
misc	Log all miscellaneous events
log_manager	Enable command interface

For more information on the -trace option, see Section 11.3.2 on page 121.

11.3.2 Using the -trace Option

Once you have used the Event Logger, you will find that it generates a large volume of information to be analyzed. Discard any unneeded log files because the Event Logger will continue to record information in the files, enlarging them until the disk is full.

To help reduce the generation of unwanted information, you can use the -trace options to enable event logging on only a subset of events. That is, rather than specifying the all option, specify only calls or only context_handles. The subset you specify will depend on the part of your application you are debugging. Although the -trace option provides logging control on a per-compilation basis, the interface must be rebuilt to enable or disable logging of different event types. The -trace options offer the ability to select different event types for the various IDL interfaces that might make up a single application.

You can use the -trace option to request logging of a single type of event, such as errors, with a command similar to the following:

% idl binopwk.idl -trace errors

You can also use the -trace option to request logging of multiple event types, such as errors and calls as shown below:

% idl binopwk.idl -trace errors -trace calls

This command enables the Event Logger, specifying error and call event logging.

To enable event logging to trace the execution of RPC calls within a process, perform the following steps:

1. Enable event logging by specifying the -trace option in the idl command you use to compile each interface definition. This example specifies the -trace all option:

   % idl binopwk.idl -trace all
   

2. Build and link the client and server portions of the application.

3. Use the environment variable RPC_LOG_FILE to direct the log output for both the server and client processes. To store Event Logger output in a file, assign the environment variables to a filename. To direct Event Logger output to the standard terminal output for the process (stdout), assign the environment variable to double quotation marks (""). This guide refers to standard terminal output as the screen.

   In the window from which the server portion of the application will be executed, direct logging for the server to a file with the following syntax:

   % setenv RPC_LOG_FILE "server.log"
   

   Or, to direct logging for the server to the screen, use the following syntax:

   % setenv RPC_LOG_FILE ""
   

4. In the window from which the client portion of the application will be executed, direct logging for the client to a file using the following syntax:

   % setenv RPC_LOG_FILE "client.log" 
   

   Or, to direct logging for the client to the screen, use the following syntax:

   % setenv RPC_LOG_FILE "" 
   

Now you can invoke the client and server processes. The event log will be recorded in the specified file or displayed on your screen when you execute the application.

11.3.3 Combining Event Logs

Although event logs are generated locally for each process, you can combine event log files to provide a broader view of application execution.

Note that this section does not give examples of each step in the application development process.

The syntax of a sort command is as follows:

% sort -m server-filename.log client-filename.log > 
client_and_server-filename.log

The -m option is specified, which indicates that the files are already sorted and prevents reordering of events that occurred at the same time.

If two events have the same timestamp, you receive a warning message after the sort is completed.

The following example illustrates how to combine logs from two different systems.

1. The server process command sequence is as follows:

   % idl fpe_server.idl -trace calls -trace errors
   % setenv RPC_LOG_FILE "server.log"
   % server
   

2. The client process command sequence is as follows:

   % idl fpe_server.idl -trace calls -trace errors
   % setenv RPC_LOG_FILE "client.log"
   % server
   

   These command sequences result in two log files: server.log and client.log, shown below. (Note that, in the following example log files, the Event Data field is not shown.)

   This is file server.log:

   1994-03-03:20:37:03.170-5:0010.121 murp:17924/15 fpe.setup   log_start  
   1994-03-03:20:37:03.170-5:0010.121 murp:17924/15 RPC Log Mgr listening 
   1994-03-03:20:37:03.180-5:0010.121 murp:17924/15 fpe.setup   activate   
   1994-03-03:20:37:03.180-5:0010.121 murp:17924/15 fpe.setup   terminate  
   1994-03-03:20:37:03.200-5:0010.121 murp:17924/15 fpe.float              
   1994-03-03:20:37:03.200-5:0010.121 murp:17924/15             
   transmit_fault 
   1994-03-03:20:37:03.200-5:0010.121 murp:17924/15 fpe.float   terminate 
   
   

   This is file client.log:

   1994-03-03:20:37:02.850-5:0010.121 ifdef:28168/1 fpe.stup log_start     
   1994-03-03:20:37:02.880-5:0010.121 ifdef:28168/1 fpe.stup call_start    
   1994-03-03:20:37:03.190-5:0010.121 ifdef:28168/1 fpe.stup call_end      
   1994-03-03:20:37:03.190-5:0010.121 ifdef:28168/1 fpe.flt  call_start    
   1994-03-03:20:37:03.210-5:0010.121 ifdef:28168/1          receive_fault 
   1994-03-03:20:37:03.210-5:0010.121 ifdef:28168/1          call_failure  
   
   

3. Next, the two log files are combined and sorted with the sort command.

   % sort -m client.log server.log > client_and_server.log
   

   The resulting file client_and_server.log is as follows:

   1994-03-03:20:37:02.850-5:0010.121 ifdef:28168/1 fpe.setup   log_start 
   1994-03-03:20:37:02.880-5:0010.121 ifdef:28168/1 fpe.setup  call_start 
   1994-03-03:20:37:03.170-5:0010.121 murp:17924/15 fpe.setup   log_start  
   1994-03-03:20:37:03.170-5:0010.121 murp:17924/15 RPC Log Mgr listening  
   
   

   1994-03-03:20:37:03.180-5:0010.121 murp:17924/15 fpe.setup   terminate  
   1994-03-03:20:37:03.190-5:0010.121 ifdef:28168/1 fpe.setup    call_end   
   
   

   1994-03-03:20:37:03.190-5:0010.121 ifdef:28168/1 fpe.float  call_start 
   1994-03-03:20:37:03.200-5:0010.121 murp:17924/15 fpe.float    activate  
   1994-03-03:20:37:03.200-5:0010.121 murp:17924/15 fpe.float   exception  
   1994-03-03:20:37:03.200-5:0010.121 murp:17924/15        transmit_fault 
   1994-03-03:20:37:03.200-5:0010.121 murp:17924/15 fpe.float   terminate  
   1994-03-03:20:37:03.210-5:0010.121 ifdef:28168/1         receive_fault 
   1994-03-03:20:37:03.210-5:0010.121 ifdef:28168/1          call_failure 
   

For the combined output to be accurate, the system clocks on all hosts on which event logs are generated must be closely synchronized. The Distributed Time Service (DTS) component of Gradient DCE for Tru64 UNIX provides such a service. Once the clocks are synchronized, the ordering of events in a combined log file is valid only if the difference between timestamps made on different machines is greater than the inaccuracy field in those timestamps. (See the DTS documentation in the OSF DCE Administration Guide — Core Components for more information about timestamps.)

In the preceding client_and_server.log file example, consider the event with the timestamp 1994-03-03:20:37:03.180-5:0010.121 and the event that follows it (these two event lines are separated from the rest of the log by a blank line on either side). Note that the timestamps indicate that the terminate event precedes the call_end event. However, you cannot determine this sequence of events by comparing timestamps because the inaccuracy value at the end of the timestamp is greater than the difference between the timestamps. That is, the difference in time between these events is only 10 milliseconds (the difference between 180 and 190 milliseconds). However, the inaccuracy in the timestamps is 121 milliseconds (10.121). Therefore, the log is not a definitive indicator of which event occurred first. Because of the simplicity of the example and the single thread of control, you can assume that the terminate event preceded the call_end event.

11.3.4 Disabling Event Logging

To disable event logging, simply compile your interface without specifying the -trace option. For example:

% idl binopwk.idl

In addition to the -trace options, the Event Logger offers two other methods for controlling information in the event log. Each facility is advantageous in different circumstances, depending on the type of processes with which you are working and the type of events you need to log. The two methods are as follows:

• Controlling Logged Events with Environment Variables: Select a subset of event types specified previously with the -trace option by creating the environment variable RPC_EVENTS. You assign the environment variable to the required event types before executing the process. This method allows you to use event logging without rebuilding the interface; however, you must first stop the process or assign the environment variable before starting it. This method is also useful in cases where you specified all-inclusive event logging (such as with the -trace all option) but you determine while the application is executing that you need only a subset of events.

• Controlling Logged Events with the RPC Log Manager: Select a subset of event types specified previously with the -trace option by using the RPC Log Manager command interface. This method allows you to modify event logging parameters for an executing image — there is no need to rebuild the interface or to stop and restart the process. In addition, you can use the Log Manager to modify event types specified with the environment variable RPC_EVENTS.

The following sections provide detailed descriptions of how to use each of these methods to control the type of events logged.

11.4.1 Controlling Logged Events with Environment Variables

One way to control the type of events logged is by assigning the environment variable RPC_EVENTS. This method is ideal for an application that contains a single RPC interface because environment variables provide control at the process level, rather than at the interface-by-interface level. However, to enable the environment variable you must first stop the client or server process.

To use environment variables to control event logging, first use the IDL -trace option in your idl compile command and then assign the log file with RPC_LOG_FILE. You can then use the environment variable RPC_EVENTS to reduce the number of events currently being logged. That is, if you used the -trace errors option to request error event logging, you can subsequently use only the environment variable to request logging of errors or none. You cannot use the environment variable to increase the number of event types to be logged. To do this, you must recompile the interface with the required -trace options.

The value of RPC_EVENTS is a list of event types separated by commas. The list identifies the event types to be monitored. Valid values are the same as those for -trace (except log_manager). These values are all, none, calls, context, errors, and misc.

An example command line follows:

% setenv RPC_EVENTS "calls,errors"

If the environment variable RPC_EVENTS was not assigned, then by default all of the events specified with the -trace option are written into the event log.

11.4.2 Controlling Logged Events with the RPC Log Manager

During application development, certain problems occur only after a server has executed some number of calls. Other problems may require more information than anticipated to debug. These problems can be addressed by enabling the RPC Log Manager in your application image. The Log Manager offers a command line interface (rpclm) for manipulating logging operations during application execution. When you use the rpclm command line interface, you need not rebuild your interface or stop and restart your server or client process to manipulate logging operations.

The rpclm commands are shown in Table 11-4.

Table 11-4: Command Interface to rpclm

Command	Description
inquire	Inquire about the currently logged events and determine the name of the active log file.
log	Specify additional events to log. Valid values are all, none, calls, context, errors, and misc.
unlog	Disable logging of the specified event types. Valid values are all, none, calls, context, errors, and misc.
file	Change the output device or file to which events are logged.
quit	Terminate the rpclm session.
help	Display a description of rpclm commands.

Follow these steps to enable the RPC Log Manager to control event logging:

1. Use the -trace log_manager option in your idl compile command.

2. Create the RPC_LOG_FILE environment variable and assign it to a filename or to screen output.

3. Execute the client or server process, or both.

4. When the first call is made to an interface compiled with the -trace option, a listening event will be generated into the event log. Invoke the rpclm command interface (as specified in step 4 below) by specifying the string binding from the listening event.

NOTE: Only string bindings from a listening event can be used to invoke rpclm.

The rpclm command interface allows you to control event logging parameters from your keyboard. You can use the command interface to reduce the events currently being logged as well as to manipulate logging operations. You can enable or disable logging of different event types (within the set selected with the -trace option), store event logging in a file or display it on the screen, inquire about the current event types being logged, and display the name of the current log file.

The following procedure illustrates how to use the Log Manager:

1. When you compile your interface with the idl compile option, include the -trace log_manager option. For example:

   % idl binopwk.idl -trace all -trace log_manager
   

2. Assign the RPC_LOG_FILE environment variable to a filename. For example:

   % setenv RPC_LOG_FILE "client.log"
   

3. Execute the client or server process, or both.

4. Upon the first remote procedure call to an interface compiled with the -trace log_manager option, a listening event will be generated into the log. Examine the Event Data field of the listening event in the log to determine the Log Manager string binding. (The RPC Event Logger is itself a client/server application: the Log Manager is a server process, and rpclm is its client. The rpclm client uses the string binding of the listening event to communicate with the Log Manager server.) Invoke rpclm and specify the Log Manager string binding. For example, consider the following event:

   murp:17868/15  RPC Log Mgr  listening ncacn_ip_tcp:16.31.48.144[3820]
   

   The listening event indicates that the RPC Log Manager is waiting for commands from rpclm. (Note that, in the example, the Time field is not shown.) To invoke rpclm, enter the listening event string binding for this server process from the Event Data field as follows:

   % rpclm "ncacn_ip_tcp:16.31.48.144[3820]"
   

   NOTE: You must enclose the string binding in double quotation marks ("").

5. As you execute rpclm commands, the Log Manager displays current logging parameters that indicate the changes made to event logging for this process. For example:

   rpclm> >unlog all Event types: Events logged to terminal rpclm> log calls Event types: calls

   Events logged to terminal

   The log for this server process will have corresponding events logged as follows:

   <time>  murp:17868/15 RPC Log Mgr   log_events      none
   <time>  murp:17868/15 RPC Log Mgr   log_events      calls
   

The following example illustrates a command dialog between the user and rpclm. The dialog begins when the user specifies a string binding from a listening event to rpclm.

% rpclm "ncacn_ip_tcp:cltdce[1821]"
rpclm> help
rpclm Commands:
inquire - Display logged events and log filename
log     - Specify additional events to log
unlog   - Specify events that should no longer be logged
file    - Change file into which events are logged
quit    - Exit log manager
rpclm> inquire
Event Types: calls
Events logged to terminal
rpclm> log errors
Event Types: calls errors
Events logged to terminal
rpclm> file server.log
Event Types: calls errors
Events logged to file 'server.log'
rpclm> quit

In this dialog, the user enters the help command to display the rpclm commands and command descriptions.

The user then enters the inquire command to display the types of events being logged and the log filename. In this example, errors are being logged to the screen.

The user enters the log calls command to specify that the Log Manager should start logging all events relating to calls, in addition to error events.

The user then enters the file command and specifies a filename. This command requests that rpclm change its output device from the terminal screen to a file named server.log.

The user then enters the quit command to terminate the rpclm session.

11.5 Using the -trace Option, Environment Variables, and the Log Manager Together

This section describes a few different ways to use the -trace options, environment variables, and the Log Manager together. When you are learning to use the Event Logger, one possible approach is to specify all-inclusive event logging with the -trace all IDL compilation option, and then examine the event log to get an understanding of typical output. You can then use the environment variable RPC_EVENTS to log only those events needed, such as calls or errors.

In the case of a running process that you do not want to terminate, use a different method. First enable the Event Logger, specifying logging of all events, and enable the Log Manager also, as follows:

% idl filename -trace all -trace log_manager

Set the event log to display on the screen, as follows:

% setenv RPC_LOG_FILE ""

Then, assign the RPC_EVENTS environment variable so it will not log any event types, as follows:

% setenv RPC_EVENTS "none"

With these parameters set, the only event that will be displayed is the listening event once the first call is made to a server interface compiled with the -trace log_manager option. You can then obtain the string binding for the process and use it later, if needed. Once you start the process, if an error occurs, use the string binding to invoke the rpclm command interface and log the needed events. Any rpclm commands issued at this point will modify the RPC_EVENTS environment variable assignment. For example, if you assign the environment variable RPC_EVENTS to calls and then issue a command to rpclm to log errors, errors as well as calls will be logged.

Once you are familiar with Event Logger output, consider regularly using the command interface to enable or disable subsets of event types as needed.

This section provides an example of common tasks you may need to perform during event logging. In this particular example, a distributed server process provides a mathematical calculation service. The client process passes data to be calculated to the server process. This type of processing often generates exception events such as those in the example event log. That is, some operations are interrupted by floating point overflow and integer division by zero exceptions, as well as others. This example uses rpclm to control logging of a server process; however, rpclm can also be used to control event logging for a client process.

The following processes are shown in three windows: a server process window, a client process window, and an rpclm window.

1. Server Window: The user first enables the RPC Event Logger by specifying the -trace all and -trace log_manager options in the idl command line:

   % idl server.calc -trace all -trace log_manager

2. Server Window: The user starts the server process. The server receives a client call and initializes the RPC Log Manager. The environment variables were assigned to enable event logging with no event types selected, so only Log Manager events are output, as shown. Note that the endpoint displayed for the listening event is the endpoint of the Log Manager. (The time field is not shown.)

   % setenv RPC_LOG_FILE  ""
   % setenv RPC_EVENTS "none"
   % server ncacn_ip_tcp
   

   murp:17868/15 fpe.setup     log_start  none
   murp:17868/15 RPC Log Mgr listening ncacn_ip_tcp:16.31.48.144[3820]
   

3. Client Window: The user invokes the client process. The specified string binding is used to find the server. The client process displays the output PASS 1 upon completion.

   % Client ncacn_ip_tcp 16.31.48.86 [3123]
   PASS 1
   

4. rpclm Window: The user invokes rpclm and specifies the string binding displayed in the listening event output by the server process, shown in step 2. The string binding must be enclosed in double quotation marks (""). The user issues the inquire command, and the event logging parameters for the server process are displayed. The Log Manager reply indicates that no event types are enabled and that the event log is being displayed on the screen from which the server process was started. The user issues the log errors command to enable logging of error events for the server process.

   % rpclm "ncacn_ip_tcp:16.31.48.144[3820]"
   

   rpclm> inquire
Event types:
Events logged to terminal
rpclm> log errors
Event types: errors
Events logged to terminal
   

5. Client Window: The user invokes the client process a second time. The error events that occur during server execution are logged to the server window. The client process displays the output PASS 2 upon completion.

   % Client ncacn_ip_tcp 16.31.48.86 [3123]
   PASS 2
   

6. Server Window: The server process receives the command from rpclm to start logging errors. Any errors that occur in the server process are logged. (The time field is not shown.)

   murp:17868/15 RPC Log Mgr       log_events     errors
   murp:17868/15 fpe.flt_overflw   exception      Floating point
                                                    overflow (dce/thd)
   murp:17868/15                   transmit_fault rpc_s_fault_fp_overflow
   murp:17868/15 fpe.flt_underflw  exception      Floating point
                                                    underflow (dce/thd) 
   murp:17868/15                   transmit_fault rpc_s_fault_fp_underflow
   murp:17868/15 fpe.flt_divbyzer  exception      Floating point/decimal
                                                  divide by zero (dce/thd)
   murp:17868/15                   transmit_fault rpc_s_fault_fp_div_by_zero
   murp:17868/15 fpe.dble_overflw  exception      Floating point
                                                    overflow (dce/thd)
   murp:17868/15                   transmit_fault rpc_s_fault_fp_overflow
   murp:17868/15 fpe.dble_underflw exception      Floating point
                                                    underflow (dce/thd)
   murp:17868/15                   transmit_fault rpc_s_fault_fp_underflow
   murp:17868/15 fpe.dble_divbyzer exception      Floating point/decimal 
                                                    divide by zero (dce/thd)
   murp:17868/15                   transmit_fault rpc_s_fault_fp_div_by_zero
   

7. rpclm Window: The user issues the unlog all command to disable logging of all previously specified event types.

   rpclm> unlog all Event types: Events logged to terminal

8. Server Window: The event log now contains an entry that indicates the Event Logger will stop logging previously specified events.

   <time>  murp:17868/15   RPC Log Mgr    log_events       none
   

9. rpclm Window: The user issues a log calls command to enable logging of call events.

   rpclm> log calls
Event types: calls
Events logged to terminal
   

10. Server Window: The newest event log entry indicates that the Event Logger will start logging call events.

    <time>   murp:17868/15   RPC Log Mgr     log_events     calls
    

11. rpclm Window: Because logging output will increase now that call events are being logged, the user issues an rpclm command to redirect logging output to a file named server_calc.log. When the application terminates and logging is complete, the user can use a text editor to view and search for entries in the log. This log file will contain only those call events from the server process.

    rpclm> file server_calc.log
Event types: calls
Events logged to file 'server_calc.log'
    

12. Server Window: The newest event log entry indicates that the logger will start redirecting logging information to file server_calc.log.

    <time>  murp:17868/15  RPC Log Mgr    log_file      server_calc.log
    

13. ClientWindow: The user invokes the client process a third time. The call events that occur during server execution are logged to file server_calc.log. The client process displays the output PASS 3 upon completion.

    % Clientncacn_ip_tcp 16.31.48.86 [3123]
    PASS 3
    

14. Server Log: This is log file server_calc.log (the time field is not shown):

    % more server_calc.log
    

    murp:17868/15 RPC Log Mgr       log_start server_calc.log
    murp:17868/15 fpe.setup         activate ncacn_ip_tcp:16.31.48.109[2905]
    murp:17868/15 fpe.setup         terminate ncacn_ip_tcp:16.31.48.109[2905]
    murp:17868/15 fpe.flt_overflw   activate  ncacn_ip_tcp:16.31.48.109[2905]
    murp:17868/15 fpe.flt_overflw   terminate
    murp:17868/15 fpe.flt_underflw  activate  ncacn_ip_tcp:16.31.48.109[2905]
    murp:17868/15 fpe.flt_underflw  terminate
    murp:17868/15 fpe.flt_divbyzer  activate  ncacn_ip_tcp:16.31.48.109[2905]
    murp:17868/15 fpe.flt_divbyzer  terminate
    murp:17868/15 fpe.dble_overflw  activate  ncacn_ip_tcp:16.31.48.109[2905]
    murp:17868/15 fpe.dble_overflw  terminate
    murp:17868/15 fpe.dble_underflw activate  ncacn_ip_tcp:16.31.48.109[2905]
    murp:17868/15 fpe.dble_underflw terminate
    murp:17868/15 fpe.dble_divbyzer activate  ncacn_ip_tcp:16.31.48.109[2905]
    murp:17868/15 fpe.dble_divbyzer terminate
    

15. rpclm Window: The user issues a file command to redirect event logging output from server_calc.log to the terminal screen. To do this, press the Return key without specifying a filename when the Log Manager prompts for one.

    rpclm> file
New File Name: <Return>
Event types: calls
Events logged to terminal
rpclm>
    

16. Server Window: The final event in the server_calc.log file is a log_file event, which indicates that event logging output is being redirected, in this case to the terminal screen. Therefore, no filename is displayed to the right of the event name.

    <time>    murp:17868/15    RPC Log Mgr    log_file
    

The RPC Event Logger is designed to help you debug your distributed application and is an enhancement over the basic diagnostics in the RPC product. The diagnostics alone provide minimal information. For example, the sample program called test2, which is provided with the Gradient DCE for Tru64 UNIX, generates the rpc_x_no_more_bindings exception when the client fails to contact the server. Without the aid of RPC event logging, this is the only diagnostic information available.

The following example shows the basic RPC diagnostic information that an application displays when an error occurs.

% test2

*** Unable to obtain server binding information
Make sure environment variable RPC_DEFAULT_ENTRY = .:/test2_server
Exception: no more bindings (dce / rpc)
IOT trap (core dumped)

If you enable RPC event logging by defining the environment variable RPC_LOG_FILE, then the details of client execution can be captured in a file. From the event log, you can determine which servers the client tried to contact and the reason each attempt failed.

In the following event log example, the Event Data field on the rebind events indicates that the interface is not registered in the endpoint map and that a communications failure occurred. This information indicates that the server either is not running or it failed to register properly with the endpoint mapper.

The final event, call_failure, indicates that the call was terminated with the no more bindings status. This event indicates that the client tried all available servers but failed to communicate with any of them. (Note that in the first column the word time represents the actual value for time.)

% test2

time ko:11436/1 test2.test2_add  log_start   all
time ko:11436/1 test2.test2_add  call_start  ncacn_ip_tcp:16.20.16.27[]
time ko:11436/1 test2.test2_add  rebind      not registered in endpoint
                                              map(dce/rpc)
time ko:11436/1 test2.test2_add  call_start  ncacn_dnet_nsp:4.262[]
time ko:11436/1 test2.test2_add  rebind      not registered in endpoint
                                              map(dce/rpc)
time ko:11436/1 test2.test2_add  call_start  ncadg_ip_udp:16.20.16.27[]
time ko:11436/1 test2.test2_add  rebind      comm failure (dce/rpc)
time ko:11436/1 call_failure                 no more bindings (dce/rpc)
*** Unable to obtain server binding information
Make sure environment variable RPC_DEFAULT_ENTRY = .:/test2_server
Exception: no more bindings (dce / rpc)
IOT trap (core dumped)

This section lists and describes RPC events. See the table in Section 11.2 on page 117 for a list of events by type (calls, context handles, errors, miscellaneous, and logging) and their origin (client or server).

activate	A thread was assigned to process an RPC call on a server, and the server stub has started processing input arguments. The Event Data field of the event log contains the string binding of the client application making the call.
await_reply	The transmission of input arguments in a call from a client application to a server is completed. The event is generated by the client stub. The client application is waiting for output arguments from the server.
call_end	A call from a client application is complete and the client stub is returning to the caller.
call_failure	A client stub terminated abnormally because either an exception occurred or a failing status was returned. The Event Data field of the event log contains the error text associated with the exception or RPC status code.
call_start	A client application attempted to make a call to a server. The event is generated by the stub within the client application. The Event Data field of the event log displays the string binding of the server being contacted.
client_ctx_created	A client application has allocated a context handle on a particular server. The Event Data field of the event log contains the following information about this event: The address representing the context handle in the client address space (an opaque pointer) The UUID which can be used to identify the corresponding context handle on the server The string binding of the server on which the actual context resided
client_ctx_deleted	The client application representation of a context handle is being deleted to reflect the deletion of the context handle on the server. The Event Data field of the event log contains the following information about this event: The address representing the context handle in the client address space (an opaque pointer) The UUID which can be used to identify the corresponding context handle on the server The string binding of the server on which the actual context resided
client_ctx_destroyed	A client application has destroyed the client representation of a context handle through the rpc_ss_destroy_client_context( ) routine. The Event Data field of the event log contains the following information about this event: The address representing the context handle in the client address space (an opaque pointer) The UUID which can be used to identify the corresponding context handle on the server The string binding of the server on which the actual context resided
context_created	A new context handle was created on a server and returned from the application manager routine. The Event Data field of the event log contains both the application value of the context handle and the UUID assigned to represent this context handle.
context_deleted	A context handle on a server has been deleted by the application manager routine. The Event Data field of the event log contains both the application value of the context handle and the UUID assigned to represent this context handle.
context_modified	A context handle on a server was returned from the application manager routine with a value that is different from its previous value. The Event Data field of the event log contains both the application value of the context handle and the UUID assigned to represent this context handle.
context_rundown	A context handle on a server was freed by the context rundown procedure. The Event Data field of the event log contains both the application value of the context handle and the UUID assigned to represent this context handle.
exception	An exception was detected in the server stub, and the exception caused the call to terminate. The Event Data field of the event log contains a text description of the exception.
internal_error	A failure occurred in the support routines that manage the Event Logger. Check the Event Data field of the event log for a description of the cause of the event. If the error does not seem to indicate a transient network problem or an environmental failure, report the failure in a Software Performance Report (SPR).
listening	The RPC Log Manager has started to listen for rpclm commands. The listening event is generated by the portion of the RPC Log Manager built into your application by the RPC runtime when you specify the -trace log_manager option on your IDL compilation. The RPC Log Manager services the requests generated by the rpclm command. You use one of the string bindings from a listening event to invoke the rpclm command interface.
log_events	Event logging was modified through the Log Manager command interface rpclm. The Event Data field of the event log contains the new set of events being logged.
log_file	Event logging was modified through the Log Manager command interface rpclm. The Event Data field of the event log contains the new filename for the event log. If no filename is displayed, events are being logged to the screen.
log_start	A new event log was created or event logging was resumed after being suspended by a user command to the Log Manager command interface rpclm. The Event Data field in the event log contains a list of event types being logged.
log_stop	Event logging was stopped through the Log Manager command interface rpclm.
manager_call	The server stub is about to call the application manager routine.
manager_return	Control has just returned from the application manager routine to the server stub.
rebind	A call from a client application to a server failed. The Event Data field in the event log shows the reason for the failure to contact the server. The event is generated by the stub within the client application. The call failed on an auto_handle operation and the client is attempting to rebind to the next server.
receive	Following the transmission of input arguments from a client application call to a server, the client received a reply and has started processing output arguments.
receive_fault	The client received a fault indicating a failure on the server. The Event Data field of the event log contains the RPC status that identifies the failure. All failures have fault codes which you can find in the file ncastat.idl. If the fault code in the ncastat.idl file is too general (such as unspecified fault), examine the server event log for precise failure information.
status_fail	A failure status was encountered in the server stub. The Event Data field of the event log describes the failure.
terminate	The server thread has completed processing the call and has terminated.
transmit_fault	The server runtime is sending fault information to the client application. The Event Data field of the event log indicates the name of the fault being sent. The fault information in this field is listed in the ncastat.idl file. The fault information in this field may be less descriptive than the information logged about the actual error. (See the exception or status_fail events in the event log to obtain precise failure information.)

11.8 Summary

The RPC Event Logger is a developer's aid for debugging DCE RPC applications. The RPC Event Logger allows you to modify IDL-generated stub routines in order to generate event logs of runtime execution of RPC calls on the screen or in a file. In addition, the RPC Log Manager command interface (rpclm) provides command line access to event logging parameters, allowing you to enable and disable debugging support of clients and servers as they execute.

The DCE RPC application development environment is designed to create applications that are portable to other DCE platforms and that can interoperate with other DCE applications. Use of Gradient DCE for Tru64 UNIX RPC Event Logger does not affect code portability or interoperability. Because the Event Logger does not modify the application, you can take advantage of event logging without affecting application portability to other hardware or software platforms.

In addition, use of Gradient DCE for Tru64 UNIX RPC Event Logger does not limit interoperability with other DCE implementations. Because event logs are generated only in the local application, communication protocols are not modified. You can, for example, use the event logging facility with any server process running under Gradient DCE for Tru64 UNIX or with any client process communicating with an RPC server on any hardware or software platform.

[Previous] [Next] [Contents] [Index]

To make comments or ask for help, contact support@entegrity.com.

Copyright © 2001 Entegrity Solutions Corporation & its subsidiaries.

Copyright © 1998-2001 Compaq Computer Corporation.

All rights reserved.