Difference between revisions of "VISTA XWB Broker Troubleshooting"

From VistApedia
Jump to: navigation, search
(→‎Troubleshooting)
(→‎Broker Logging)
 
Line 96: Line 96:
  
 
=== Broker Logging ===
 
=== Broker Logging ===
−
If you have further issues, the easiest way to troubleshoot them is to turn on broker logging, like this:
+
If you have further issues, the easiest way to troubleshoot them is to turn on broker logging.
  
−
<pre>
+
The following illustrates the use of the RPCBroker logging functionality that
−
GTM>S DUZ=1 D ^XUP
+
was initially added by Wally Fort.  This can be controlled from within the
 +
menu system or at the programmer level.
  
−
Setting up programmer environment
+
'''''Caution -- If you use 'very Verbose' logging in a production system, it will create a very large amount of logging since it includes all input from the client as well as all output from the server.  This may be overwhelming, since there is currently no mechanism provided to isolate logging to one or a few individuals.  The use of very Verbose logging is best used in test systems or during off hours on a production system (and then remember to set it back down or off).'''''
−
This is a TEST account.
 
  
−
Terminal Type set to: C-VT220
+
The following illustrates the different levels of logging and its control from within the menu system, starting at EVE or the System Manager Menu.
  
−
Select OPTION NAME: XWB MENU      RPC Broker Management Menu
+
<pre> 
 +
Select Systems Manager Menu Option: OPerations Management
  
 +
Select Operations Management Option: RPC Broker Management Menu
  
 
           RPC Listener Edit
 
           RPC Listener Edit
Line 116: Line 118:
 
           View XWB Log
 
           View XWB Log
  
−
Select RPC Broker Management Menu <TEST ACCOUNT> Option: DEBUG Parameter Edit
+
Select RPC Broker Management Menu Option: DEBUG Parameter Edit
 +
 
 +
----- Setting RPCBroker debug logging  for System: JIVEY3.JIVEYSOFT.COM -----
 +
Enable Broker Logging: No// ?
 +
 
 +
Enter a code from the list.
 +
 
 +
    Select one of the following:
 +
 
 +
          0        No
 +
          1        Yes
 +
          2        Verbose
 +
          3        very Verbose
 +
 
 +
Enable Broker Logging: No// 1  Yes
 +
</pre>
 +
 
 +
At this point a broker connection was made with BrokerExample and Execute RPC selected on the Pass By Reference tab.
 +
 
 +
<pre>
 +
Select RPC Broker Management Menu Option: VIEw XWB Log
 +
Log Files
  
 +
Log from Job 13584 7 Lines              <-- output from 1 or Yes logging -->
 +
09:03:28 = Log start: Jul 22, 2013@09:03:28
 +
09:03:28 = XWBTCPM
 +
09:03:28 = MSG format is [XWB] type NEW
 +
09:03:28 = accept
 +
09:06:53 = SETTIME IN POST2^XUSRB
 +
09:07:07 = BYE CMD
 +
09:07:07 = Exit: #BYE#
 +
Return to continue, Next log, Exit: Continue// ? <-- note Kill is not listed -->
  
 +
Enter RETURN to continue, Next for next log, Kill to remove log, Exit to
 +
quit log view.
  
−
-------- Setting RPCBroker debug logging  for System: FOIA.PLATINUM  --------
+
    Select one of the following:
−
Enable Broker Logging: very Verbose// ?
+
 
 +
          1        Continue
 +
          2        Next
 +
          3        Exit
 +
          4        Kill
 +
 
 +
Return to continue, Next log, Exit: Continue// Kill
 +
Log XWBLOG13584 deleted.
 +
 
 +
 
 +
Select RPC Broker Management Menu Option: CLear XWB Log Files
 +
Remove all XWB log entries? No// YES
 +
Done
 +
 
 +
Select RPC Broker Management Menu Option: DEbug Parameter Edit
 +
 
 +
 
 +
 
 +
----- Setting RPCBroker debug logging  for System: JIVEY3.JIVEYSOFT.COM -----
 +
Enable Broker Logging: Yes// ?
  
 
Enter a code from the list.
 
Enter a code from the list.
Line 132: Line 185:
 
           3        very Verbose
 
           3        very Verbose
  
−
Enable Broker Logging: very Verbose// 3 very Verbose
+
Enable Broker Logging: Yes// 2 Verbose
 
</pre>
 
</pre>
  
−
After you do that, you need to clear the old logs:
+
Again an RPCBroker connection was made and the same RPC used.
  
 
<pre>
 
<pre>
−
Select RPC Broker Management Menu <TEST ACCOUNT> Option: CLEAR XWB Log Files
+
Select RPC Broker Management Menu Option: View XWB Log
−
Remove all XWB log entries? No// YES
+
Log Files
−
Done
+
 
 +
Log from Job 11516 18 Lines          <-- output from 2 or Verbose logging -->
 +
09:09:25 = Log start: Jul 22, 2013@09:09:25
 +
09:09:25 = XWBTCPM
 +
09:09:25 = MSG format is [XWB] type NEW
 +
09:09:25 = CMD: TCPConnect
 +
09:09:25 = accept
 +
09:09:25 = RPC: XUS SIGNON SETUP
 +
09:09:25 = RPC: XUS INTRO MSG
 +
09:09:33 = RPC: XUS AV CODE
 +
09:09:34 = SETTIME IN POST2^XUSRB
 +
09:09:34 = RPC: XUS GET USER INFO
 +
09:09:34 = RPC: XWB GET BROKER INFO
 +
09:09:34 = RPC: XUS DIVISION GET
 +
09:09:34 = RPC: XWB CREATE CONTEXT
 +
09:09:34 = RPC: XWB CREATE CONTEXT
 +
09:09:40 = RPC: XWB GET VARIABLE VALUE
 +
09:09:46 = CMD: #BYE#
 +
09:09:46 = BYE CMD
 +
09:09:46 = Exit: #BYE#
 +
Return to continue, Next log, Exit: Continue// Kill
 +
Log XWBLOG11516 deleted.
 +
 
 +
Select RPC Broker Management Menu Option: DEBug Parameter Edit
 +
 
 +
 
 +
 
 +
----- Setting RPCBroker debug logging  for System: JIVEY3.JIVEYSOFT.COM -----
 +
Enable Broker Logging: Verbose// ?
 +
 
 +
Enter a code from the list.
 +
 
 +
    Select one of the following:
 +
 
 +
          0        No
 +
          1        Yes
 +
          2        Verbose
 +
          3        very Verbose
 +
 
 +
Enable Broker Logging: Verbose// 3  very Verbose
 +
 
 +
</pre>
 +
 
 +
Another RPCBroker connection was made and the RPC selected
 +
<pre>
 +
Select RPC Broker Management Menu Option: View XWB Log
 +
Log Files
 +
 
 +
Log from Job 13652 53 Lines  <-- output from 3 or very Verbose logging -->
 +
09:10:44 = Log start: Jul 22, 2013@09:10:44
 +
09:10:44 = XWBTCPM
 +
09:10:44 = rd: [XWB]10304\10TCPConnect50013192.168.1.100f00010f0006Jivey3f\04
 +
09:10:44 = MSG format is [XWB] type NEW
 +
09:10:44 = CMD: TCPConnect
 +
09:10:44 = wrt (9): \00\00accept\04
 +
09:10:44 = accept
 +
09:10:44 = rd: [XWB]11302\010\16XUS SIGNON SETUP50048"_"x"g"Ex"DXeT|vD*G|"mevgg
 +
          |e*Dm"xDxxg*gDv*ynm**x$f\04
 +
09:10:44 = RPC: XUS SIGNON SETUP
 +
09:10:44 = Call: SETUP^XUSRB(.XWBY,XWB(5,"P",0))
 +
09:10:44 = wrt (83): \00\00Jivey3\13\10VISTA\13\10VISTA\13\10//./nul:13652\13\1
 +
          05\13\100\13\10JIVEY3.JIVEYSOFT.COM\13\100\13\10\04
 +
09:10:44 = rd: [XWB]11302\010\13XUS INTRO MSG54f\04
 +
09:10:44 = RPC: XUS INTRO MSG
 +
09:10:44 = Call: INTRO^XUSRB(.XWBY)
 +
09:10:44 = wrt (3): \00\00\04
 +
09:10:51 = rd: [XWB]11302\010\11XUS AV CODE50020&NFb/#NFmmm0Zyyyyyq.f\04
 +
09:10:51 = RPC: XUS AV CODE
 +
09:10:51 = Call: VALIDAV^XUSRB(.XWBY,XWB(5,"P",0))
 +
09:10:51 = SETTIME IN POST2^XUSRB
 +
Return to continue, Next log, Exit: Continue// [H [J [2J [H
 +
09:10:51 = wrt (176): \00\002802\13\100\13\100\13\10\13\100\13\100\13\10\13\10G
 +
          ood morning Joel\13\10    You last signed on today at 09:09\13\10Yo
 +
          u have 2 new messages. (2 in the 'IN' basket)\13\10\13\10Enter '^NML
 +
          ' to read your new messages.\13\10\04
 +
09:10:51 = rd: [XWB]11302\010\17XUS GET USER INFO54f\04
 +
09:10:51 = RPC: XUS GET USER INFO
 +
09:10:51 = Call: USERINFO^XUSRB2(.XWBY)
 +
09:10:51 = wrt (83): \00\002802\13\10IVEY,JOEL L\13\10Joel L Ivey\13\101^SOFTWA
 +
          RE SERVICE^050\13\10PROGRAMMER\13\10IRM\13\10\13\10600\13\10\04
 +
09:10:51 = rd: [XWB]11302\010\19XWB GET BROKER INFO54f\04
 +
09:10:51 = RPC: XWB GET BROKER INFO
 +
09:10:51 = Call: BRKRINFO^XWBLIB(.XWBY)
 +
09:10:51 = wrt (8): \00\00200\13\10\04
 +
09:10:51 = rd: [XWB]11302\010\16XUS DIVISION GET54f\04
 +
09:10:51 = RPC: XUS DIVISION GET
 +
09:10:51 = Call: DIVGET^XUSRB2(.XWBY)
 +
09:10:51 = wrt (6): \00\000\13\10\04
 +
09:10:51 = rd: [XWB]11302\010\18XWB CREATE CONTEXT50002&,f\04
 +
09:10:51 = RPC: XWB CREATE CONTEXT
 +
09:10:51 = Call: CRCONTXT^XWBSEC(.XWBY,XWB(5,"P",0))
 +
09:10:51 = wrt (4): \00\001\04
 +
09:10:51 = rd: [XWB]11302\010\18XWB CREATE CONTEXT50020 @|d]deAYVe]V@ENLRV"f\04
 +
09:10:51 = RPC: XWB CREATE CONTEXT
 +
09:10:51 = Call: CRCONTXT^XWBSEC(.XWBY,XWB(5,"P",0))
 +
Return to continue, Next log, Exit: Continue// [H [J [2J [H
 +
09:10:51 = wrt (4): \00\001\04
 +
09:10:56 = rd: [XWB]11302\010\22XWB GET VARIABLE VALUE51008$HOROLOGf\04
 +
09:10:56 = RPC: XWB GET VARIABLE VALUE
 +
09:10:56 = Call: VARVAL^XWBLIB(.XWBY,XWB(5,"P",0))
 +
09:10:56 = wrt (14): \00\0063025,33056\04
 +
09:11:04 = rd: [XWB]11302\010\22XWB GET VARIABLE VALUE51008$HOROLOGf\04
 +
09:11:04 = RPC: XWB GET VARIABLE VALUE
 +
09:11:04 = Call: VARVAL^XWBLIB(.XWBY,XWB(5,"P",0))
 +
09:11:04 = wrt (14): \00\0063025,33064\04
 +
09:11:08 = rd: [XWB]10304\05#BYE#\04
 +
09:11:08 = CMD: #BYE#
 +
09:11:08 = wrt (8): \00\00#BYE#\04
 +
09:11:08 = BYE CMD
 +
09:11:08 = Exit: #BYE#
 +
Return to continue, Next log, Exit: Continue// Kill
 +
Log XWBLOG13652 deleted.
 +
 
 +
Select RPC Broker Management Menu Option: DEbug Parameter Edit
 +
 
 +
 
 +
 
 +
----- Setting RPCBroker debug logging  for System: JIVEY3.JIVEYSOFT.COM -----
 +
Enable Broker Logging: very Verbose// 0  No
 +
</pre>
 +
 
 +
These commands can also be run from Programmer Mode
 +
 
 +
<pre>
 +
 
 +
Select RPC Broker Management Menu Option: ^PG
 +
 
 +
 
 +
 
 +
VISTA>D EDITPAR^XPAREDIT("XWBDEBUG")
 +
 
 +
 
 +
----- Setting RPCBroker debug logging  for System: JIVEY3.JIVEYSOFT.COM -----
 +
Enable Broker Logging: No// ?
 +
 
 +
Enter a code from the list.
 +
 
 +
    Select one of the following:
 +
 
 +
          0        No
 +
          1        Yes
 +
          2        Verbose
 +
          3        very Verbose
 +
 
 +
Enable Broker Logging: No// 3  very Verbose
 +
 
 
</pre>
 
</pre>
  
−
Now, perform the connection, replicate the error that you encounter, and then check-out the broker logs using the option 'View XWB Log'. A good familiarity with the broker TCP protocol will help you understand it; here's an excerpt:
+
Again a connection was made with RPCBroker and the same RPC used.
  
 
<pre>
 
<pre>
−
Log from Job 4115 25 Lines
+
 
−
09:43:36 = Log start: Apr 09, 2012@09:43:36
+
VISTA>D VIEW^XWBDLOG
−
09:43:36 = XWBTCPM
+
 
−
09:43:36 = rd: [XWB]
+
Log Files
−
09:43:36 = MSG format is [XWB] type NEW
+
 
−
09:43:36 = rd: 1030
+
Log from Job 7376 49 Lines     <-- output from 3 or very Vebose logging -->
−
09:43:36 = rd: 4
+
09:13:21 = Log start: Jul 22, 2013@09:13:21
−
09:43:36 = rd: \10
+
09:13:21 = XWBTCPM
−
09:43:36 = rd: TCPConnect
+
09:13:21 = rd: [XWB]10304\10TCPConnect50013192.168.1.100f00010f0006Jivey3f\04
−
09:43:36 = CMD: TCPConnect
+
09:13:21 = MSG format is [XWB] type NEW
−
09:43:36 = rd: 5
+
09:13:21 = CMD: TCPConnect
−
09:43:36 = rd: 0
+
09:13:21 = wrt (9): \00\00accept\04
−
09:43:36 = rd: 012
+
09:13:21 = accept
−
09:43:36 = rd: 192.168.0.17
+
09:13:22 = rd: [XWB]11302\010\16XUS SIGNON SETUP50048&H[e[f[xe[xWl_j(xosj[el(ff
−
09:43:36 = rd: f
+
          jloxW[exfefofx(o[eooe)f\04
−
09:43:36 = rd: 0
+
09:13:22 = RPC: XUS SIGNON SETUP
−
09:43:36 = rd: 001
+
09:13:22 = Call: SETUP^XUSRB(.XWBY,XWB(5,"P",0))
−
09:43:36 = rd: 0
+
09:13:22 = wrt (82): \00\00Jivey3\13\10VISTA\13\10VISTA\13\10//./nul:7376\13\10
−
09:43:36 = rd: f
+
          5\13\100\13\10JIVEY3.JIVEYSOFT.COM\13\100\13\10\04
−
09:43:36 = rd: 0
+
09:13:22 = rd: [XWB]11302\010\13XUS INTRO MSG54f\04
−
09:43:36 = rd: 006
+
09:13:22 = RPC: XUS INTRO MSG
−
09:43:36 = rd: icarus
+
09:13:22 = Call: INTRO^XUSRB(.XWBY)
−
09:43:36 = rd: f
+
09:13:22 = wrt (3): \00\00\04
−
09:43:36 = rd: \04
+
09:13:32 = rd: [XWB]11302\010\11XUS AV CODE50020)'6aHt'6ew6k{wt56U!1f\04
 +
09:13:32 = RPC: XUS AV CODE
 +
09:13:32 = Call: VALIDAV^XUSRB(.XWBY,XWB(5,"P",0))
 +
09:13:32 = SETTIME IN POST2^XUSRB
 +
Return to continue, Next log, Exit: Continue//
 +
09:13:32 = wrt (176): \00\002802\13\100\13\100\13\10\13\100\13\100\13\10\13\10G
 +
          ood morning Joel\13\10    You last signed on today at 09:10\13\10Yo
 +
          u have 2 new messages. (2 in the 'IN' basket)\13\10\13\10Enter '^NML
 +
          ' to read your new messages.\13\10\04
 +
09:13:32 = rd: [XWB]11302\010\17XUS GET USER INFO54f\04
 +
09:13:32 = RPC: XUS GET USER INFO
 +
09:13:32 = Call: USERINFO^XUSRB2(.XWBY)
 +
09:13:32 = wrt (83): \00\002802\13\10IVEY,JOEL L\13\10Joel L Ivey\13\101^SOFTWA
 +
          RE SERVICE^050\13\10PROGRAMMER\13\10IRM\13\10\13\10600\13\10\04
 +
09:13:32 = rd: [XWB]11302\010\19XWB GET BROKER INFO54f\04
 +
09:13:32 = RPC: XWB GET BROKER INFO
 +
09:13:32 = Call: BRKRINFO^XWBLIB(.XWBY)
 +
09:13:32 = wrt (8): \00\00200\13\10\04
 +
09:13:32 = rd: [XWB]11302\010\16XUS DIVISION GET54f\04
 +
09:13:32 = RPC: XUS DIVISION GET
 +
09:13:32 = Call: DIVGET^XUSRB2(.XWBY)
 +
09:13:32 = wrt (6): \00\000\13\10\04
 +
09:13:32 = rd: [XWB]11302\010\18XWB CREATE CONTEXT50002'/f\04
 +
09:13:32 = RPC: XWB CREATE CONTEXT
 +
09:13:32 = Call: CRCONTXT^XWBSEC(.XWBY,XWB(5,"P",0))
 +
09:13:32 = wrt (4): \00\001\04
 +
09:13:32 = rd: [XWB]11302\010\18XWB CREATE CONTEXT50020+G4@]@TBlET]EGS.b0E,f\04
 +
09:13:32 = RPC: XWB CREATE CONTEXT
 +
09:13:32 = Call: CRCONTXT^XWBSEC(.XWBY,XWB(5,"P",0))
 +
Return to continue, Next log, Exit: Continue//
 +
09:13:32 = wrt (4): \00\001\04
 +
09:13:36 = rd: [XWB]11302\010\22XWB GET VARIABLE VALUE51008$HOROLOGf\04
 +
09:13:36 = RPC: XWB GET VARIABLE VALUE
 +
09:13:36 = Call: VARVAL^XWBLIB(.XWBY,XWB(5,"P",0))
 +
09:13:36 = wrt (14): \00\0063025,33216\04
 +
09:13:39 = rd: [XWB]10304\05#BYE#\04
 +
09:13:39 = CMD: #BYE#
 +
09:13:39 = wrt (8): \00\00#BYE#\04
 +
09:13:39 = BYE CMD
 +
09:13:39 = Exit: #BYE#
 +
Return to continue, Next log, Exit: Continue// ?
 +
 
 +
Enter RETURN to continue, Next for next log, Kill to remove log, Exit to
 +
quit log view.
 +
 
 +
    Select one of the following:
 +
 
 +
          1        Continue
 +
          2        Next
 +
          3        Exit
 +
          4        Kill
 +
 
 +
Return to continue, Next log, Exit: Continue// Kill
 +
Log XWBLOG7376 deleted.
 +
 
 +
VISTA>D KILLALL^XWBDLOG
 +
 
 +
Remove all XWB log entries? No// YES
 +
Done
 +
VISTA>
 
</pre>
 
</pre>
  
−
Some essential parts to understand: a byte that is <code>x04</code> (\04) always ends a message. A byte "f" means it's the end of the argument. The item just before the argument is the argument length (<code>006</code>). The client creates this message. Therefore, if this message is not created properly at the client, it won't be read properly by VISTA.
+
Some essential parts to understand: a byte that is <code>x04</code> (\04) always ends a message. A byte "f" means it's the end of the argument. The item just before the argument is the argument length (<code>006</code>). The client creates this message. Therefore, if this message is not created properly at the client, it won't be read properly by VISTA. VISTA replies usually start with <code>x00x00</code> signifying that there is no error to send to the client.
  
 
=== Foreground Debugging of Broker Calls ===
 
=== Foreground Debugging of Broker Calls ===

Latest revision as of 22:05, 22 July 2013

Starting the Broker

On GT.M, to start the broker, you need to create an OS service (Xinetd on Linux) that calls GTMLNX^XWBTCPM.

On Cache, you can start a broker listener using the start-up file ZSTU by calling this: J ZISTCP^XWBTCPM1(<port no>):"<namespace>"

On Cache, you can also fill out the RPC Broker Site Parameters file like this: 

Select OPTION NAME: XWB MENU       RPC Broker Management Menu


          RPC Listener Edit
          Start All RPC Broker Listeners
          Stop All RPC Broker Listeners
          Clear XWB Log Files
          Debug Parameter Edit
          View XWB Log

Select RPC Broker Management Menu <TEST ACCOUNT> Option: RPC LISTener Edit

Select RPC BROKER SITE PARAMETERS DOMAIN NAME: ?
    Answer with RPC BROKER SITE PARAMETERS DOMAIN NAME, or STATUS:
   VISTA.PLATINUM    
    
Select RPC BROKER SITE PARAMETERS DOMAIN NAME:    VISTA.PLATINUM 
Select BOX-VOLUME PAIR: ICARUS:icarus// 
  BOX-VOLUME PAIR: ICARUS:icarus// 
  Select PORT: 9000
  Are you adding '9000' as a new PORT (the 1ST for this LISTENER)? No// Y
  (Yes)
    STATUS: STOPPED// 
    TYPE OF LISTENER: ?
     Choose from: 
       0        Original
       1        New Style
    TYPE OF LISTENER: 1  New Style
    CONTROLLED BY LISTENER STARTER: ?
     Choose from: 
       0        NO
       1        YES
    CONTROLLED BY LISTENER STARTER: 1  YES

Then ask Taskman to start this upon Taskman start-up, by creating this entry in file 19.2: 

OUTPUT FROM WHAT FILE: OPTION SCHEDULING// 
Select OPTION SCHEDULING NAME:    XWB LISTENER STARTER
ANOTHER ONE: 
STANDARD CAPTIONED OUTPUT? Yes//   (Yes)
Include COMPUTED fields:  (N/Y/R/B): NO//  - No record number (IEN), no Computed
 Fields

NAME: XWB LISTENER STARTER              SPECIAL QUEUEING: STARTUP

When you start taskman from ZSTU using J ^ZTMB:"<namespace>", the broker will be started by taskman.

Troubleshooting

Environment Check and Unit Test

The broker can fail at several points. All of them are covered by an environment check that either Wally or Joel wrote: D CHECK^XWBTCPMT. Here's an example: 

GTM>D CHECK^XWBTCPMT

This will check for some of the errors that can prevent the Broker
from getting started.

Debugging is set to Very Verbose
Broker activity timeout is set to 180
Checking can Write to null device
The NULL device is OK.
Checking if new JOB's can start.
New jobs are allowed.
Done with the checks.

From the above, you can glean why a broker might not start or accept connections:

  1. The VOLUME multiple in the Kernel System Parameters isn't filled out properly.
  2. The VOLUME SET file has the disable flag set to yes.
  3. There is more than one NULL device or no NULL device.
  4. Your Mumps Implementation license doesn't allow you to start a new job.
  5. $$ACTJ^%ZOSV says you ran out of licenses.

In the same routine, there is also a broker tester to test your broker system by connecting to it, only you are doing it directly from Mumps. Here's an example: 

GTM>D CALL^XWBTCPMT

Interactive Broker Test
IP ADDRESS: 127.0.0.1
PORT: 9200
Success, response: accept

If this call succeeds (and you need to make sure that this is indeed the right port that hooks up to your VISTA system), then you are now certain that the new style broker works to some extent.

Broker Logging

If you have further issues, the easiest way to troubleshoot them is to turn on broker logging.

The following illustrates the use of the RPCBroker logging functionality that was initially added by Wally Fort. This can be controlled from within the menu system or at the programmer level.

Caution -- If you use 'very Verbose' logging in a production system, it will create a very large amount of logging since it includes all input from the client as well as all output from the server. This may be overwhelming, since there is currently no mechanism provided to isolate logging to one or a few individuals. The use of very Verbose logging is best used in test systems or during off hours on a production system (and then remember to set it back down or off).

The following illustrates the different levels of logging and its control from within the menu system, starting at EVE or the System Manager Menu. 

  
Select Systems Manager Menu Option: OPerations Management

Select Operations Management Option: RPC Broker Management Menu

          RPC Listener Edit
          Start All RPC Broker Listeners
          Stop All RPC Broker Listeners
          Clear XWB Log Files
          Debug Parameter Edit
          View XWB Log

Select RPC Broker Management Menu Option: DEBUG Parameter Edit

----- Setting RPCBroker debug logging  for System: JIVEY3.JIVEYSOFT.COM -----
Enable Broker Logging: No// ?

Enter a code from the list.

     Select one of the following:

          0         No
          1         Yes
          2         Verbose
          3         very Verbose

Enable Broker Logging: No// 1  Yes

At this point a broker connection was made with BrokerExample and Execute RPC selected on the Pass By Reference tab. 

Select RPC Broker Management Menu Option: VIEw XWB Log
Log Files

Log from Job 13584 7 Lines               <-- output from 1 or Yes logging -->
09:03:28 = Log start: Jul 22, 2013@09:03:28
09:03:28 = XWBTCPM
09:03:28 = MSG format is [XWB] type NEW
09:03:28 = accept
09:06:53 = SETTIME IN POST2^XUSRB
09:07:07 = BYE CMD
09:07:07 = Exit: #BYE#
Return to continue, Next log, Exit: Continue// ? <-- note Kill is not listed -->

Enter RETURN to continue, Next for next log, Kill to remove log, Exit to 
quit log view.

     Select one of the following:

          1         Continue
          2         Next
          3         Exit
          4         Kill

Return to continue, Next log, Exit: Continue// Kill
Log XWBLOG13584 deleted.


Select RPC Broker Management Menu Option: CLear XWB Log Files
Remove all XWB log entries? No// YES
Done

Select RPC Broker Management Menu Option: DEbug Parameter Edit



----- Setting RPCBroker debug logging  for System: JIVEY3.JIVEYSOFT.COM -----
Enable Broker Logging: Yes// ?

Enter a code from the list.

     Select one of the following:

          0         No
          1         Yes
          2         Verbose
          3         very Verbose

Enable Broker Logging: Yes// 2  Verbose

Again an RPCBroker connection was made and the same RPC used. 

Select RPC Broker Management Menu Option: View XWB Log
Log Files

Log from Job 11516 18 Lines           <-- output from 2 or Verbose logging -->
09:09:25 = Log start: Jul 22, 2013@09:09:25
09:09:25 = XWBTCPM
09:09:25 = MSG format is [XWB] type NEW
09:09:25 = CMD: TCPConnect
09:09:25 = accept
09:09:25 = RPC: XUS SIGNON SETUP
09:09:25 = RPC: XUS INTRO MSG
09:09:33 = RPC: XUS AV CODE
09:09:34 = SETTIME IN POST2^XUSRB
09:09:34 = RPC: XUS GET USER INFO
09:09:34 = RPC: XWB GET BROKER INFO
09:09:34 = RPC: XUS DIVISION GET
09:09:34 = RPC: XWB CREATE CONTEXT
09:09:34 = RPC: XWB CREATE CONTEXT
09:09:40 = RPC: XWB GET VARIABLE VALUE
09:09:46 = CMD: #BYE#
09:09:46 = BYE CMD
09:09:46 = Exit: #BYE#
Return to continue, Next log, Exit: Continue// Kill
Log XWBLOG11516 deleted.

Select RPC Broker Management Menu Option: DEBug Parameter Edit



----- Setting RPCBroker debug logging  for System: JIVEY3.JIVEYSOFT.COM -----
Enable Broker Logging: Verbose// ?

Enter a code from the list.

     Select one of the following:

          0         No
          1         Yes
          2         Verbose
          3         very Verbose

Enable Broker Logging: Verbose// 3  very Verbose

Another RPCBroker connection was made and the RPC selected 

Select RPC Broker Management Menu Option: View XWB Log
Log Files

Log from Job 13652 53 Lines   <-- output from 3 or very Verbose logging -->
09:10:44 = Log start: Jul 22, 2013@09:10:44
09:10:44 = XWBTCPM
09:10:44 = rd: [XWB]10304\10TCPConnect50013192.168.1.100f00010f0006Jivey3f\04
09:10:44 = MSG format is [XWB] type NEW
09:10:44 = CMD: TCPConnect
09:10:44 = wrt (9): \00\00accept\04
09:10:44 = accept
09:10:44 = rd: [XWB]11302\010\16XUS SIGNON SETUP50048"_"x"g"Ex"DXeT|vD*G|"mevgg
           |e*Dm"xDxxg*gDv*ynm**x$f\04
09:10:44 = RPC: XUS SIGNON SETUP
09:10:44 = Call: SETUP^XUSRB(.XWBY,XWB(5,"P",0))
09:10:44 = wrt (83): \00\00Jivey3\13\10VISTA\13\10VISTA\13\10//./nul:13652\13\1
           05\13\100\13\10JIVEY3.JIVEYSOFT.COM\13\100\13\10\04
09:10:44 = rd: [XWB]11302\010\13XUS INTRO MSG54f\04
09:10:44 = RPC: XUS INTRO MSG
09:10:44 = Call: INTRO^XUSRB(.XWBY)
09:10:44 = wrt (3): \00\00\04
09:10:51 = rd: [XWB]11302\010\11XUS AV CODE50020&NFb/#NFmmm0Zyyyyyq.f\04
09:10:51 = RPC: XUS AV CODE
09:10:51 = Call: VALIDAV^XUSRB(.XWBY,XWB(5,"P",0))
09:10:51 = SETTIME IN POST2^XUSRB
Return to continue, Next log, Exit: Continue// [H [J [2J [H
09:10:51 = wrt (176): \00\002802\13\100\13\100\13\10\13\100\13\100\13\10\13\10G
           ood morning Joel\13\10     You last signed on today at 09:09\13\10Yo
           u have 2 new messages. (2 in the 'IN' basket)\13\10\13\10Enter '^NML
           ' to read your new messages.\13\10\04
09:10:51 = rd: [XWB]11302\010\17XUS GET USER INFO54f\04
09:10:51 = RPC: XUS GET USER INFO
09:10:51 = Call: USERINFO^XUSRB2(.XWBY)
09:10:51 = wrt (83): \00\002802\13\10IVEY,JOEL L\13\10Joel L Ivey\13\101^SOFTWA
           RE SERVICE^050\13\10PROGRAMMER\13\10IRM\13\10\13\10600\13\10\04
09:10:51 = rd: [XWB]11302\010\19XWB GET BROKER INFO54f\04
09:10:51 = RPC: XWB GET BROKER INFO
09:10:51 = Call: BRKRINFO^XWBLIB(.XWBY)
09:10:51 = wrt (8): \00\00200\13\10\04
09:10:51 = rd: [XWB]11302\010\16XUS DIVISION GET54f\04
09:10:51 = RPC: XUS DIVISION GET
09:10:51 = Call: DIVGET^XUSRB2(.XWBY)
09:10:51 = wrt (6): \00\000\13\10\04
09:10:51 = rd: [XWB]11302\010\18XWB CREATE CONTEXT50002&,f\04
09:10:51 = RPC: XWB CREATE CONTEXT
09:10:51 = Call: CRCONTXT^XWBSEC(.XWBY,XWB(5,"P",0))
09:10:51 = wrt (4): \00\001\04
09:10:51 = rd: [XWB]11302\010\18XWB CREATE CONTEXT50020 @|d]deAYVe]V@ENLRV"f\04
09:10:51 = RPC: XWB CREATE CONTEXT
09:10:51 = Call: CRCONTXT^XWBSEC(.XWBY,XWB(5,"P",0))
Return to continue, Next log, Exit: Continue// [H [J [2J [H
09:10:51 = wrt (4): \00\001\04
09:10:56 = rd: [XWB]11302\010\22XWB GET VARIABLE VALUE51008$HOROLOGf\04
09:10:56 = RPC: XWB GET VARIABLE VALUE
09:10:56 = Call: VARVAL^XWBLIB(.XWBY,XWB(5,"P",0))
09:10:56 = wrt (14): \00\0063025,33056\04
09:11:04 = rd: [XWB]11302\010\22XWB GET VARIABLE VALUE51008$HOROLOGf\04
09:11:04 = RPC: XWB GET VARIABLE VALUE
09:11:04 = Call: VARVAL^XWBLIB(.XWBY,XWB(5,"P",0))
09:11:04 = wrt (14): \00\0063025,33064\04
09:11:08 = rd: [XWB]10304\05#BYE#\04
09:11:08 = CMD: #BYE#
09:11:08 = wrt (8): \00\00#BYE#\04
09:11:08 = BYE CMD
09:11:08 = Exit: #BYE#
Return to continue, Next log, Exit: Continue// Kill
Log XWBLOG13652 deleted.

Select RPC Broker Management Menu Option: DEbug Parameter Edit



----- Setting RPCBroker debug logging  for System: JIVEY3.JIVEYSOFT.COM -----
Enable Broker Logging: very Verbose// 0  No

These commands can also be run from Programmer Mode 


Select RPC Broker Management Menu Option: ^PG



VISTA>D EDITPAR^XPAREDIT("XWBDEBUG")


----- Setting RPCBroker debug logging  for System: JIVEY3.JIVEYSOFT.COM -----
Enable Broker Logging: No// ?

Enter a code from the list.

     Select one of the following:

          0         No
          1         Yes
          2         Verbose
          3         very Verbose

Enable Broker Logging: No// 3  very Verbose

Again a connection was made with RPCBroker and the same RPC used. 


VISTA>D VIEW^XWBDLOG

Log Files

Log from Job 7376 49 Lines      <-- output from 3 or very Vebose logging -->
09:13:21 = Log start: Jul 22, 2013@09:13:21
09:13:21 = XWBTCPM
09:13:21 = rd: [XWB]10304\10TCPConnect50013192.168.1.100f00010f0006Jivey3f\04
09:13:21 = MSG format is [XWB] type NEW
09:13:21 = CMD: TCPConnect
09:13:21 = wrt (9): \00\00accept\04
09:13:21 = accept
09:13:22 = rd: [XWB]11302\010\16XUS SIGNON SETUP50048&H[e[f[xe[xWl_j(xosj[el(ff
           jloxW[exfefofx(o[eooe)f\04
09:13:22 = RPC: XUS SIGNON SETUP
09:13:22 = Call: SETUP^XUSRB(.XWBY,XWB(5,"P",0))
09:13:22 = wrt (82): \00\00Jivey3\13\10VISTA\13\10VISTA\13\10//./nul:7376\13\10
           5\13\100\13\10JIVEY3.JIVEYSOFT.COM\13\100\13\10\04
09:13:22 = rd: [XWB]11302\010\13XUS INTRO MSG54f\04
09:13:22 = RPC: XUS INTRO MSG
09:13:22 = Call: INTRO^XUSRB(.XWBY)
09:13:22 = wrt (3): \00\00\04
09:13:32 = rd: [XWB]11302\010\11XUS AV CODE50020)'6aHt'6ew6k{wt56U!1f\04
09:13:32 = RPC: XUS AV CODE
09:13:32 = Call: VALIDAV^XUSRB(.XWBY,XWB(5,"P",0))
09:13:32 = SETTIME IN POST2^XUSRB
Return to continue, Next log, Exit: Continue// 
09:13:32 = wrt (176): \00\002802\13\100\13\100\13\10\13\100\13\100\13\10\13\10G
           ood morning Joel\13\10     You last signed on today at 09:10\13\10Yo
           u have 2 new messages. (2 in the 'IN' basket)\13\10\13\10Enter '^NML
           ' to read your new messages.\13\10\04
09:13:32 = rd: [XWB]11302\010\17XUS GET USER INFO54f\04
09:13:32 = RPC: XUS GET USER INFO
09:13:32 = Call: USERINFO^XUSRB2(.XWBY)
09:13:32 = wrt (83): \00\002802\13\10IVEY,JOEL L\13\10Joel L Ivey\13\101^SOFTWA
           RE SERVICE^050\13\10PROGRAMMER\13\10IRM\13\10\13\10600\13\10\04
09:13:32 = rd: [XWB]11302\010\19XWB GET BROKER INFO54f\04
09:13:32 = RPC: XWB GET BROKER INFO
09:13:32 = Call: BRKRINFO^XWBLIB(.XWBY)
09:13:32 = wrt (8): \00\00200\13\10\04
09:13:32 = rd: [XWB]11302\010\16XUS DIVISION GET54f\04
09:13:32 = RPC: XUS DIVISION GET
09:13:32 = Call: DIVGET^XUSRB2(.XWBY)
09:13:32 = wrt (6): \00\000\13\10\04
09:13:32 = rd: [XWB]11302\010\18XWB CREATE CONTEXT50002'/f\04
09:13:32 = RPC: XWB CREATE CONTEXT
09:13:32 = Call: CRCONTXT^XWBSEC(.XWBY,XWB(5,"P",0))
09:13:32 = wrt (4): \00\001\04
09:13:32 = rd: [XWB]11302\010\18XWB CREATE CONTEXT50020+G4@]@TBlET]EGS.b0E,f\04
09:13:32 = RPC: XWB CREATE CONTEXT
09:13:32 = Call: CRCONTXT^XWBSEC(.XWBY,XWB(5,"P",0))
Return to continue, Next log, Exit: Continue// 
09:13:32 = wrt (4): \00\001\04
09:13:36 = rd: [XWB]11302\010\22XWB GET VARIABLE VALUE51008$HOROLOGf\04
09:13:36 = RPC: XWB GET VARIABLE VALUE
09:13:36 = Call: VARVAL^XWBLIB(.XWBY,XWB(5,"P",0))
09:13:36 = wrt (14): \00\0063025,33216\04
09:13:39 = rd: [XWB]10304\05#BYE#\04
09:13:39 = CMD: #BYE#
09:13:39 = wrt (8): \00\00#BYE#\04
09:13:39 = BYE CMD
09:13:39 = Exit: #BYE#
Return to continue, Next log, Exit: Continue// ?

Enter RETURN to continue, Next for next log, Kill to remove log, Exit to 
quit log view.

     Select one of the following:

          1         Continue
          2         Next
          3         Exit
          4         Kill

Return to continue, Next log, Exit: Continue// Kill
Log XWBLOG7376 deleted.

VISTA>D KILLALL^XWBDLOG

Remove all XWB log entries? No// YES
Done
VISTA>

Some essential parts to understand: a byte that is x04 (\04) always ends a message. A byte "f" means it's the end of the argument. The item just before the argument is the argument length (006). The client creates this message. Therefore, if this message is not created properly at the client, it won't be read properly by VISTA. VISTA replies usually start with x00x00 signifying that there is no error to send to the client.

Foreground Debugging of Broker Calls

Last but not least, for desperate debuggers, you can put breakpoints in your current process and run the listener process in the foreground and then connect your client. You will hit the breakpoint: 

GTM>D DEBUG^XWBTCPM

Before running this entry point set your debugger to stop at
the place you want to debug. Some spots to use:
'SERV+1^XWBTCPM', 'MAIN+1^XWBTCPM' or 'CAPI+1^XWBPRS.'

or location of your choice.

IP Socket to Listen on: <etc>...
Retrieved from "https://vistapedia.com/index.php?title=VISTA_XWB_Broker_Troubleshooting&oldid=15858"