LOG REQUEST BLOCKS UTILITY Release Level TUE 06/08/93 15:17 PM This application consists of one runfile: LogRequestBlocks.Run Product Name : Log Request Blocks Supported On : B24, B26, B27, B28, B38, B39, and all SuperGen hardware Supported OS : BTOS II, CTOS I, CTOS II, CTOS III Description : The Log Request Blocks programs allow you to save and examine selected request blocks that are exchanged during a period of time. The programs are intended for trouble shooting and reverse engineering applications. The package consists of three programs. Log Request Blocks is the program that does the logging. It can run either as an installed system service or in its own partition under the Context Manager, and functions as a filter. Stop Logging Request Blocks causes the Logging program to write its data to disk, then try to restore the system to its previous state, then deinstall itself. Print Logged Request Blocks is a utility that displays the data collected by Log Request Blocks in a format to assist with interpretation. Directions/Use : All numerical arguments, to the /Log Request Blocks command may be entered either in decimal, or in hex by prefixing them with an 'x'. For example, request code 0DB55h would be entered as 'xDB55'. On older XE O/S, use MCDTIO, MCLI, or CLI to run the program on the board where the requests to be logged are being served. If filtering BNet requests, run the program on the board where the Net Agent is installed (usually the master FP (FP00)). The Logging program can also log request blocks sent directly to it by other programs. If a program wishes to have certain requests logged, then it should do a GetPartitionHandle, specifying the partition name 'LogRqBlk', to obtain the partition handle for the Logging program's partition. It should then do a GetPartitionExchange to obtain the Logging program's exchange. It should then do a RequestDirect in order to send the request to that exchange. The Logging program then does a normal Request to issue the request block. This technique may not work properly in the case of one-way filtering. If BNet requests are being filtered, then this technique should not be used for request blocks that already have the routing code field set. Every attempt is made to save the data. In case of problems, such as disk write errors, disk full, etc., the Logging program will abort and issue two beeps. Normally it can still be deinstalled using the Stop Logging Request Blocks program, but of course, the some of the data will not be output. In case of other fatal errors, such as for example running out of request control blocks (the sixth installation parameter), it will output the remaining data to disk if possible.To execute the Log Request Blocks utility use the /Log Request Blocks command, with the following installation parameters as described and detailed below: [Request codes to filter (default none)] This field is optional. Enter a list of request codes that the Logging program should intercept and log, before sending them on for normal processing. The codes may be taken from a file, using the '@' feature. If the program is loaded from a Batch file and multiple requests code are specified, then they should be enclosed in parentheses. The Logging program dynamically allocates memory for data structures associated with the request codes, so there is no practical limit to the number of request codes specified. (Note that in BTOS/CTOS, when you filter a request code, it is considered good practice also to filter the corresponding termination, abort, and swapping requests, although in practice you can usually get away without doing so, especially in non- production environments.) For each request code, the Logging program does a 'query exchange' to determine the current server, then a 'serve request' to take over servicing the request code. The Logging program will intercept request blocks issued using the 'Request' primitive, but cannot intercept ones issued using 'Request Direct', 'Forward Request', or of course, 'Send', primitives. It also will not intercept requests that the BTOS kernel decides are 'remote' and tries to send to BNet (for that, see other options below). The Logging program can intercept requests that the BTOS kernel would normally send to the Cluster Agent. If a request code on the list is not being served, then the Logging program will exit with an error. In order to allow you to filter requests that the program also uses internally, the program uses RequestDirect to execute its internal commands. Of course, the requests issued by the logging program itself will not be logged. The request codes involved are: OpenFile (4), CreateFile (5), SetFileStatus (9), CloseFile (10), ChangeFileLength (13), Write (36), Beep (52), and ServeRq(99). GetNxtFilePrt (120) and DCCommand (-1) should not be filtered, as they are used by the program for its own deinstall command. ReadKbd (53) can be filtered when the program is running as a system service, but not when it is running under the Context Manager. It is also possible that you may encounter problems filtering other requests, if they in turn are called by any of these functions, possibly through some other single threaded filter program. [Output file (default RequestBlocks.log)] This field is optional. Enter the name of the output file for the data, which by default is '[sys]RequestBlocks.log'. The Logging program allows up to 10 output files, so that, if a large amount of data is to be collected, none of it is lost. In order to differentiate the files, the Logging program appends a numeric digit to the name entered. Thus if the user enters 'myfile', the first portion of data will be saved to the file 'myfile0', the next portion to 'myfile1', etc. When the last file, say 'myfile9', is full, the Logging program reuses 'myfile0'. Data is normally collected in memory and only occassionally written to disk, so as to minimize the impact of the logging on the timing relationships of the system being monitored. When the data collected reaches approximately 60K bytes, it is written to disk. When the size of a file reaches approximately 240K, it is closed and a new one opened. You can use the Files command with details and examine the time of last modification to determine the last file written. If there is doubt, the sequence numbers may also been examined; see discussion below concerning displaying the data. In order to accomodate loading this program from the Sysinit.jcl file on password protected disks, if the second argument begins with a caret (^), the rest of the entry is assumed to be the password. In that case, the default file spec is used. [One way filter (y/n, default n)?] This field is optional. Enter 'No' if you want to filter both requests and responses (the default), or 'Yes' to filter requests only. Note that if a request is issued before the Logging program is installed but the response occurs afterward, then the response will not be logged. [Filter Net Agent input (y/n, default n)?] This field is optional. Enter 'No' if you want to filter requests that are sent by the BTOS kernel to BNet. In that case, the Logging program masquerades as BNet to intercept the requests, then passes them on to the real BNet. BNet must already be installed for this to work. Setting this parameter does not cause the Logging program to log those requests that are sent to BNet because BNet is serving them, such as BNet status, abort, and termination requests. To monitor these requests you need to specify them in the first parameter. The Logging program cannot use RequestDirect or ForwardRequest to send the requests on to the real BNet on some versions of the O/S, as those O/S's override the specified exchange and send the requests back to the Logging program, which they think is really BNet. To get around this problem, the program uses the Send primitive to deliver the request to the real BNet, and issues a dummy Request, with the user's number on it, to itself, to balance out some Kernel counters. If you specify a particular request code in the first parameter and also filter BNet requests, a problem can occur if a request block is issued that would have been handled locally, but which has the routing code field set, as the Logging program will then assume that it should be sent to BNet. This problem should only occur if the application issuing the request sets the routing code. The application normally should not do so; it is the BTOS kernel's responsibility to supply this field. Obviously if you are filtering BNet requests, you should not specify as your output file a file on a remote node. [Length of PbCb fields (default 64000)] This field is optional. Enter the number of bytes of data should be saved for each request. The request blocks themselves are always saved. If only the first few bytes of data are likely to be of interest, then you can save disk space or increase the number of requests that you can save by limiting the number of bytes. The default is to save 64000 bytes of data, which in practice will be the entire request block in all but extreme cases. This is also the effective maximum number of bytes that the Logging program can save. [Number of request outstanding (default 50)] This field is optional. Enter the number of requests which may be outstanding at one time. This is only important for two-way filtering. A request remains outstanding until its response is received. [Number of files (default 2)] This field is optional. Enter the number of output files as described under [Output file (default RequestBlocks.log] above. [Priority of process (default 5)] This field is optional. Specifiy the priority of the Logging program. By default, it runs at a very high priority. The idea is not to distort the order of messages, since whenever a message is sent, the Logging program wakes up immediately and sends it on. If it runs at a low priority, it may be pre- empted, and then its logging may not reflect the order that events would have occurred in its absence. However, there are two cases where it may be desirable to use a low priority (say 144 or higher). First, the Logging program may introduce substantial overhead itself so as to distort certain tests. Second, certain application, particular Cobol programs, use a coding technique where they issue the request block, then execute a Wait, specifying the response exchange in the request block just submitted. If the Logging program is run at higher priority with two-way filtering, then when the request is issued, the Logging program will pre-empt the application and replace the response exchange in the request block with its own. When the application gets control again, it pulls the altered response exchange out of the request block and does its Wait based on that, so that it is waiting at the wrong exchange. This leads several types of failure. The problem is avoided if the Logging program runs at a lower priority than the application, since then the application is not pre-empted, and the response exchange is not altered before the application uses it. [Immediate save (y/n, default n)?] This field is optional. Specify whether the program should save each message to disk as soon as it is received, or only save to disk when its internal buffer becomes full (which is the normal case). In cases where the system is crashing after only a few requests, it may be desirable to use this option. In that case, for each request or response, the program will open the file, write the data, then close the file again. If the system crashes or hangs, all the data will still be saved to disk. Note however, that this is extremely slow, and thus may change the timing pattern of the sequence being studied. It is also wasteful in disk space, since the buffering requires at least one sector per message. Thus it is usually only useful for studying crashes that occur fairly quickly. [Include User numbers (default all)] This field is optional. Enter a list of user numbers. If you do so, then the program will only log request blocks from users on that list. If you place a tilde (~) immediately in front of the first entry on the list, then the program will only log requests from users NOT on the list. In order to stop the logging of request blocks, use the /Stop Logging Request Blocks command (which has no parameters). This program issues a Stop request. (Request code 0FFFFh is used, which corresponds to a 'user' or level -1.). If that is unsuccessful, it uses request code 120 as an alternate. (That is an older Spooler request code which I believe is no longer used.) When the Logging program receives this request code, it writes out any remaining data, closes the output file, issues a double beep, then resets the request codes to the original service exchanges, and if on a protected mode system, deinstalls itself. If on a real mode system, the Stop program must do the deinstallation. If the Logging program is present on the master, then the Stop program can be run on a cluster workstation (although this doesn't always seem to work). If the master is protected mode, all should be OK. If the master is real mode, then the output will be written and the file closed, but the Logging program will remain in memory. On an XE, the Stop program should be run on the same board as the Logging program, if at all possible. If the Logging program is running in its own partition under the Context Manager, then you can also use the FINISH key to cause it to complete. (Using ACTION FINISH however, will not result in the last data being written to the file, and may cause other processes to hang.) The Logging program can also be stopped using the debugger (assuming that file access is still possible). While in the debugger, set the process to the Logging program, then load its symbol table (logRequestBlocks.sym). Then examine the six-word data structure 'TRB'. Set the sixth word to a value of 0FFFFh, then set the first word to a value of 2. (This structure is a timer block. When the first word counts down to 0, its address will be sent to the Logging program. If the sixth word is set to 0FFFFh, the Logging program will interpret the message as a Stop request, and will proceed to save the data.) If the symbol table is not handy, you can find the TRB easily by starting at the beginning of the data segment (ds:0) and examining memory until you find the hex pattern: AAAA, BBBB, CCCC, DDDD, EEEE, FFFF. The next word is the first word of the TRB, will generally have a large value, which will decrease at a rate of 10 counts per second. The second word of the TRB has a value of FFFF. The sixth word has a value of zero, and is followed by the hex pattern in reverse order (starting with FFFF). When the output has been successfully saved, the Logging program will issue a double beep. If you hear the double beep, you can be fairly certain that the output has been saved, even if other problems cause things to hang or the system to crash. On the other hand, if the double beep does not occur, then the output data is suspect. Unfortunately, if the system crashes, or enters the debugger on a fatal error such that file I/O cannot be used, there is no way to save the data. In that case, on the next try you may want to set the ninth argument to assure that all the data is saved to disk. Although the Logging program tries to clean up before exiting, nevertheless if you stop it while requests are outstanding, there is a possibility that things may be left in a funny state. If this is a concern, try to deinstall the other modules before stopping the logging. In order to display the request blocks, execute the /Print Logged Request Blocks command, which uses the paramters which are detailed and described below: [Input file (default RequestBlocks.log0)] This field is optional. Enter the file name which is to be used as the input file (the file produced by the Logging program). If you enter a file name that does not end with a numeric digit, and the file does not exist, then the display program will append a '0' to it. The default file name is [sys]RequestBlocks.log0. If you enter a number sign (#) followed by a string, for the first parameter, then the program will use the file name which is the same as the default, with the last character replaced with the string. Thus is you enter '#2', the program will use the file [sys]RequestBlocks.log2 as its input. If you enter '#- LAN', the program will use the file [sys]RequestBlocks.log-LAN. [Output device (default [VID]) This field is optional. This parameter is used to designate the output device, which by default is the screen but which may be a disk file or printer. [First entry (default start of file)] This field is optional. As each request is received by the Logging program, it is assigned a sequence number, starting at one; the corresponding response references the same number. This parameter and the next allow you to specify a range of sequence numbers, so that you can skip over other requests. The output starts when the first sequence number is encountered (either in a request or a response), and ends when the last one is encountered, or when the end of the file is reached. If the first number is not encountered, the program outputs the message: 'Starting entry not found', and displays the first and last sequence numbers. [Last entry (default end of file)] This field is optional. See [First entry (default start of file] parameter description above for usage instructions. [# of bytes to print for each PbCb] This field is optional. Enter a limit for the number of bytes to be displayed for each PbCb (data) field. It often happens that a request block contains several fields, some of which may contain large blocks of data of which only the first few bytes are of interest. By using this parameter the user can reduce the output size while retaining the important information. [Match User #s (def all)] This field is optional. If a user number(s) is entered here, then only requests which match that user number(s) will be displayed. [Match Rq Codes (def all)] This field is optional. If a specific request code(s) is entered here, then only only that request(s) will be displayed. [Match Rsp Exchanges (def all)] This field is optional. If a specific response exchange(s) is entered here, then only only that response exchange(s) will be displayed. [Match Resource Handles (def all)] This field is optional. If a specific Resource Handle(s) is entered here, then only only that Resource Handle(s) will be displayed. The resource handle is arbitrarily assumed to be the first word of the control field; thus a request that opens a resource and returns a handle is not shown. [Match Ercs Returned (def all)] This field is optional. If a specific Erc(s) is entered here, then only only that Erc(s) will be displayed (those contained in the response only). [Match Routing Code (def all)] This field is optional. If a specific routing code(s) is entered here, then only only that routing code(s) will be displayed. Any request blocks that contain the specified non- zero bits in their routing fields are displayed. If the routing code entry is preceeded by an equal sign (=), then only request blocks whose routing codes exactly match are displayed. If the routing code entry is preceeded by a tilde (~), then request blocks that contain all of the specified non-zero bits in their routing codes are NOT displayed. [List Rqs Outstanding?] This field is optional. This parameter indicates whether the program should display the list of requests outstanding (by sequence number, in no particular order). If set to 'yes', it will display the list of outstanding requests after each entry; otherwise it will only display the list at the end of the program. It only considers requests that match the criteria of parameters 6 to 11. Thus if you are only displaying requests for a particular user, then the program will only display outstanding requests for that user. If one of the fields of the request block changes between the request and the response in such a manner that the response is not displayed, then the request will appear on the list. For example, if you display only requests which have ercOK, then for any responses that have another erc, the request will continue to appear in the outstanding list even after the response has occurred. For parameters six through ten, the values may be specified in several ways. If preceeded by a greater than (>) or less than (<) sign, then only those requests that match that criteria are included. An interval may be included by enclosing the parameters in square brackets ([]). If the first parameter entry is preceeded by a tilde (~), then the request block is NOT displayed if it matches the criteria. The criteria for each parameter are 'OR'ed. For example, the parameter input '<10 50 80 >200 [110 114]' would include all requests whose values were 0-9, 50, 80, 110-114, or above 200. The parameter input '~<10 50 80 >200 [110 114]' would inlude all requests whose values were 10-49, 51-79, 81-109, and 115-200. The criteria for the different parameters are 'AND'ed. Thus if a request does not satisfy ALL of the criteria for display, then it is omitted from the display. Limitations The logging program can become confused if a request block is issued while it is already outstanding. In that case, /Log Request Blocks will detect it, and will flag it. /Print Log Request Blocks will print a message on the line preceeding the second entry indicating that it is a duplicate. It is quite likely that the second response will not be logged, since the response exchange is altered when the first response occurs. (It is also highly likely that such requests will lead to protection faults in the process servicing the request, or even in the logging program.) Similar descrepencies can occur if a program alters a request block while it is outstanding, especially if it changes the request code or the response exchange. Of course, the logging program will not see any requests that were issued before it was installed. It will also not see any of the responses to those requests, even if they occur after the logging program is installed. Sample Output The following is a sample output of the display program. The fifth parameter was set the 32 bytes; the others were defaulted. All outputs are in hex, except for the error code and the time, which are shown in decimal. The first field indicates whether the entry is a request or a response. The second entry is the sequence number. Requests and responses can be matched using that sequence number. The third field is a time stamp, which is in 100 millisecond increments from the time the Logging program was installed. Thus the first entry occurred 5.0 seconds after installation. The next field is the physical address of the request block in memory. This is followed by the request block header, and the control field (displayed as words). If the size of the control field is odd, an extra, extraneous, byte will be shown. If the control field will not fit on one line, it continues on the next. Next we have the PbCb's (pointer and count) describing the data fields. These are following by the data itself. For a request, only the request PbCbs are shown; for a response, only the response PbCbs. Thus the first entry (request #1) displays PbCb0-5, while the second entry (response #1) displays PbCb6. Each line displays 16 bytes in hex, with the corresponding ASCII on the right. Null PbCb fields are not listed; thus for the first entry, no data is shown for PbCb3 and PbCb4. Because we limited the output to 32 bytes, only that much data is displayed for PbCb0, although it contains more data. Of course, only the data actually saved by the Logging program will be displayed. Ty Seq Time Phy sCtl Rt Req Rsp User Resp Erc Req Ctl pe # Addr info Cd Pbs Pbs # exch Ret code info RQ 0001 50 2E1E40 06 00 06 01 0008 003C 00000 6160 0602 0000 0000 PbCbs = 26D0:FEEE 58, 26D0:E758 1, 26D0:E4C6 D, 0000:0000 0, 0000:0000 0, 26D0:E804 2, 26D0:DB98 2 PbCb0 0A FF 80 00 02 00 00 00 8C 00 4C 02 28 00 18 FF ..........L.(... . . . 0C 00 01 00 00 00 00 00 00 00 8C 00 02 04 42 4E ..............BN PbCb1 00 . PbCb2 06 53 6E 75 66 66 79 00 00 00 00 00 00 .Snuffy...... PbCb5 00 21 .! RS 0001 50 2E1E40 06 00 06 01 0008 003C 00000 6160 0602 0000 0000 PbCbs = 26D0:FEEE 58, 26D0:E758 1, 26D0:E4C6 D, 0000:0000 0, 0000:0000 0, 26D0:E804 2, 26D0:DB98 2 PbCb6 05 09 .. RQ 0002 50 2E63DE 06 00 00 07 0008 003D 00000 6162 0602 0000 0000 PbCbs = 2768:0B6E 58, 0000:0000 0, 2700:EF8C A74, 0000:0000 0, 0000:0000 0, 2768:0B6C 2, 2768:0B6A 2 RS 0002 52 2E63DE 06 00 00 07 0008 003D 00000 6162 0602 0000 0000 PbCbs = 2768:0B6E 58, 0000:0000 0, 2700:EF8C A74, 0000:0000 0, 0000:0000 0, 2768:0B6C 2, 2768:0B6A 2 PbCb0 58 00 00 00 00 00 00 00 00 00 01 00 00 00 00 00 X............... . . . 00 00 F9 FF FF FF FF FF 00 00 00 00 02 0B 40 02 ..............@. PbCb2 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................ . . . 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................ PbCb5 01 12 .. PbCb6 05 09 .. RQ 0003 52 2E63DE 06 00 00 07 0008 003D 00000 6162 0602 0000 0000 PbCbs = 2768:0B6E 58, 0000:0000 0, 2700:EF8C A74, 0000:0000 0, 0000:0000 0, 2768:0B6C 2, 2768:0B6A 2 RQ 0004 52 2E1E4E 06 00 06 01 0008 003C 00000 6160 0602 0905 0000 PbCbs = 26D0:FF00 58, 26D0:DA04 16, 0000:0000 0, 0000:0000 0, 0000:0000 0, 26D0:E808 2, 26D0:FEFE 2 PbCb0 01 00 80 02 00 00 00 00 8C 00 02 04 42 4E 65 74 ............BNet . . . 00 00 00 00 08 04 04 DA 8C 00 16 00 00 00 00 00 ................ PbCb1 00 00 00 00 06 00 00 00 00 00 00 00 00 00 AC 63 ...............c . . . 34 0A 00 00 00 00 4..... PbCb5 02 22 .' RS 0004 52 2E1E4E 06 00 06 01 0008 003C 00000 6160 0602 0905 0000 PbCbs = 26D0:FF00 58, 26D0:DA04 16, 0000:0000 0, 0000:0000 0, 0000:0000 0, 26D0:E808 2, 26D0:FEFE 2 PbCb6 05 09 .. RS 0003 52 2E63DE 06 00 00 07 0008 003D 00000 6162 0602 0000 0000 PbCbs = 2768:0B6E 58, 0000:0000 0, 2700:EF8C A74, 0000:0000 0, 0000:0000 0, 2768:0B6C 2, 2768:0B6A 2 PbCb0 10 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................ . . . 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................ PbCb2 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................ . . . 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................ PbCb5 1A 12 .. PbCb6 05 09 .. RQ 0005 52 2E63DE 06 00 00 07 0008 003D 00000 6162 0602 0000 0000 PbCbs = 2768:0B6E 58, 0000:0000 0, 2700:EF8C A74, 0000:0000 0, 0000:0000 0, 2768:0B6C 2, 2768:0B6A 2 RS 0005 53 2E63DE 06 00 00 07 0008 003D 00000 6162 0602 0000 0000 PbCbs = 2768:0B6E 58, 0000:0000 0, 2700:EF8C A74, 0000:0000 0, 0000:0000 0, 2768:0B6C 2, 2768:0B6A 2 PbCb0 11 00 80 02 00 00 00 00 00 00 16 00 00 00 00 00 ................ . . . 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................ PbCb2 00 00 00 00 06 00 00 00 00 00 00 00 00 00 AC 63 ...............c . . . 34 0A 00 00 00 00 00 00 00 00 00 00 00 00 00 00 4............... PbCb5 02 12 .. PbCb6 05 09 .. End of file reached. The next table shows the layout of the entries in the disk files produced by the Logging program. This is also the format of the data in the Logging program's memory, where, if necessary, it may be examined. It is pointed to by 'pBuffer', and its current length is given by 'curpos'. The byte count is the length of the entry. If the number of bytes is odd, then a filler byte is inserted so that the next entry starts on a word boundary. If the byte count is zero, then the rest of the current 512 byte disk sector is unused, and the next entry starts at the next 512 byte boundary. Most entries are an odd number of bytes, and the filler byte is set to hex 21 (ASCII exclamation point). Thus you can often find the start of entries by looking for exclamation points. Entry format: Byte count (size of entry) WORD, Entry Type (0 request, 1 response) BYTE, SequenceNum WORD, Time Stamp WORD, Physical Address of request DWORD, Request block (*) BYTE, Data (PbCb) Fields (*) BYTE; COMMAND /Log Request Blocks [Request codes to filter (default none)] [Output file (default RequestBlocks.log)] [One way filter (y/n, default n)?] [Filter Net Agent input (y/n, default n)?] [Length of PbCb fields (default 64000)] [Number of request outstanding (default 50)] [Number of files (default 2)] [Priority of process (default 5)] [Immediate save (y/n, default n)?] [Include User numbers (default all)] /Stop Logging Request Blocks /Print Logged Request Blocks [Input file (default RequestBlocks.log0)] [Output device (default [VID]) [First entry (default start of file)] [Last entry (default end of file)] [# of bytes to print for each PbCb] [Match User #s (def all)] [Match Rq Codes (def all)] [Match Rsp Exchanges (def all)] [Match Resource Handles (def all)] [Match Ercs Returned (def all)] [Match Routing Code (def all)] [List Rqs Outstanding?]