VISTA XWB Broker Troubleshooting
Contents
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:
- The VOLUME multiple in the Kernel System Parameters isn't filled out properly.
- The VOLUME SET file has the disable flag set to yes.
- There is more than one NULL device or no NULL device.
- Your Mumps Implementation license doesn't allow you to start a new job.
- $$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>...
