BRM Troubleshooting
Disclaimer This document and the subsequent documents give a very high level overview of BRM system and customization of one aspect of the system. In order to get a deeper understanding of the all the concepts at a greater depth, it is recommended to refer to the BRM implementation guide which is provided with any version of the BRM product. The following material has been written taking BRM Documentation as a basis to reflect some custom changes made to Paymenetch engine.
BRM Troubleshooting
Following techniques describe some means by which errors can be troubleshooted occurring either when one writes a custom code or when the module/system behaves abnromally.
Logfiles The first step advised to troubleshoot errors for the above procedure or in general, is to go check the log files at various levels. Logfiles of CM, Oracle DM, Custom DM provide immense amount of information about the flow of the whole process. One can actually segregate the set of opcodes happening for each sub-operation and closely observe the called opcodes, search objects, input flists, output flists, error and warning messages. This process can happen only when the ‘debug mode’ is set in the CM pin.conf file. Logfiles of all modules are present in /opt/portal/7.4/var/module_name by the name module_name.pinlog . In some modules module_name.log is also present which generally records the start and stop of the module as a unix process. Also this directory for a module contains module_name.pid which indicates the process id of that module as a unix process. The following log file displays an error from dm_oracle.pinlog
E Fri Jun 25 17:09:43 2010 IBIZOCA dm:1909 dm_subr.c(124):6278 1:IBIZOCA:cm:3634:-146335520:9:1277503783:1
dm_read_subrows_wild: dm_read_subrow_multiple_select failed
The message decomposition is
- E is an error message. D signifies debug messages; debugging can be set in the pin.conf file of the corresponding module. W signifies a warning.
- Occurred on Fri Jun 25 17:09:43 2010
- Name of the machine on which the service is running is IBIZOCA
- Caused by the module dm
- With process ID 1909
- The source code is given in the file dm_subr.c at line number 124
- IBIZOCA:cm:3634:-146335520:9:1277503783:1 says that it was caused by module cm with process ID 3634 and correlation ID :-146335520:9:
1277503783:1
Look into cm.pinlog with the corresponding correlation ID to find the exact error. The error message at the CM is given below.
E Fri Jun 25 17:09:43 2010 IBIZOCA cm:23202 fm_act_find.c:814 1:IBIZOCA:cm:3634:-146335520:9:1277503783:1 fm_act_find_search_service error<location=PIN_ERRLOC_DM:4 class=UNKNOWN:0 errno=PIN_ERR_BAD_ARG:4> <field num=0:0,0 recid=0 reserved=0 reserved2=0 time(sec:usec)=0:0> facility=0 msg_id=0 version=0>
E Fri Jun 25 17:09:43 2010 IBIZOCA cm:23202 fm_act_find.c:583 1:IBIZOCA:cm:3634:-146335520:9:1277503783:1 fm_act_find_search_singledb login/alias search error:<location=PIN_ERRLOC_DM:4class=UNKNOWN:0 errno=PIN_ERR_BAD_ARG:4><field num=0:0,0 recid=0 reserved=0 reserved2=0 time(sec:usec)=0:0> <facility=0 msg_id=0 version=0>
E Fri Jun 25 17:09:43 2010 IBIZOCA cm:23202 fm_act_find.c:251 1:IBIZOCA:cm:3634:-146335520:9:1277503783:1 fm_act_find_search error<location=PIN_ERRLOC_DM:4 class=UNKNOWN:0 errno=PIN_ERR_BAD_ARG:4> <field num=0:0,0 recid=0 reserved=0 reserved2=0 time(sec:usec)=0:0> <facility=0 msg_id=0 version=0>
E Fri Jun 25 17:09:43 2010 IBIZOCA cm:23202 fm_act_find.c:159 1:IBIZOCA:cm:3634:-146335520:9:1277503783:1 op_act_find error
<location=PIN_ERRLOC_DM:4class=UNKNOWN:0 errno=PIN_ERR_BAD_ARG:4>
<field num=0:0,0 recid=0 reserved=0 reserved2=0 time(sec:usec)=0:0> <facility=0 msg_id=0 version=0>
E Fri Jun 25 17:09:43 2010 IBIZOCA cm:23202 fm_act_find_verify.c: 373 1:IBIZOCA:cm:3634:- 146335520:9:1277503783:1 fm_act_find_verify_search error <location=PIN_ERRLOC_DM:4 class=UNKNOWN:0errno=PIN_ERR_BAD_ARG:4>
<field num=0:0,0 recid=0 reserved=0 reserved2=0 time(sec:usec)=0:0>
<facility=0 msg_id=0 version=0>
E Fri Jun 25 17:09:43 2010 IBIZOCA cm:23202 fm_act_find_verify.c:271 1:IBIZOCA:cm:3634:-146335520:9:1277503783:1 fm_act_verify_credit error
<location=PIN_ERRLOC_DM:4 class=UNKNOWN:0 errno=PIN_ERR_BAD_ARG:4> <field num=0:0,0 recid=0 reserved=0 reserved2=0 time(sec:usec)=0:0>
<facility=0 msg_id=0 version=0>
E Fri Jun 25 17:09:43 2010 IBIZOCA cm:23202 fm_act_login.c:221 1:IBIZOCA:cm:3634:-146335520:9:1277503783:1 fm_act_login_findserv error
<location=PIN_ERRLOC_DM:4 class=UNKNOWN:0 errno=PIN_ERR_BAD_ARG:4>
<field num=0:0,0 recid=0 reserved=0 reserved2=0 time(sec:usec)=0:0>
<facility=0 msg_id=0 version=0>
E Fri Jun 25 17:09:43 2010 IBIZOCA cm:23202 cm_child.c(113):2565 1:IBIZOCA:cm:3634:-146335520:9:1277503783:1 CM bad login attempt from ip_addr=192.168.15.8:47622, err=4(PIN_ERR_BAD_ARG), field=0(0)
It says that there were login errors to the system from the client machine with ip address 192.168.15.8 from port number 47622.
testnap Utility The testnap utility is a command line based program which can interact directly with storabe objects, perform transactions and execute operations by creating a PCM connection with the CM. It is helpful by the fact that one can test an inbuilt opcode or an event and need not write code to test them. In a standard installation testnap is present at /opt/portal/7.4/sys/test. It requires a basic pin.conf file specifying the username and password of the system, BRM database and connection parameters of CM ( location, IP address, port ). The utility runs by placing input data/flists and storing output data/flists in various buffers and each buffer is referenced by an integer.
Syntax
[pin@IBIZOCA test]$ testnap
===> database 0.0.0.1 from pin.conf "userid"
nap(7933)>
After testnap is typed in , its connected to the BRM database with the userid mentioned in the pin.conf file. By changing the userid field to a desired entry in this pin.conf file, one can gain access to other databases/validation systems. But proper userid/password have to be mentioned in the pin.conf file for this data access system.
Commands Type h or help to view the list of commands in testnap. Few commands are discussed in this document.
r : read an object/flist from a buffer
w : write an object/flist to a buffer
w+ : append an object/flist to an existing buffer
d : display the contents of a buffer
l : display the buffer numbers in use
xops : execute an opcode either by its name or number as defined /opt/portal/7.4/include
/ops.
p: display or set properties
id : displays the current pcm_client and session ids. testnap sessions are recorded in /service/pcm_client storable class.
robj : read an object from a database mentioned in the pin.conf file
The following code snippet gives a sequence of testnap operations. In the /opt/portal/7.4/sys/test files list, bill, se.txt and new_data_script have already been written. The contents of the files would be known while they get executed at ‘ nap >’ prompt. Also scripts can be written and saved in the directory and these scripts can be called by ‘>’ operator. The robj output in the end is deliberately shown incorrect to display an error.
nap(29536)> r bill 10
nap(29536)> r list 11
nap(29536)> l
[1] 0.0.0.1 /deal 1123 0
[3] 0.0.0.1 /account 14606 11
[10] 0.0.0.1 /bill 1451 0
[11] 0.0.0.1 /account 14606 11
nap(29536)> d 10
# number of field entries allocated 20, used 1
0 PIN_FLD_POID POID [0] 0.0.0.1 /bill 1451 0
nap(29536)> d 11
# number of field entries allocated 20, used 6
| 0 | PIN_FLD_POID | POID [0] 0.0.0.1 /account 14606 11 |
| 0 | PIN_FLD_PROGRAM_NAME | STR [0] "CC Validation" |
| 0 | PIN_FLD_END_T | TSTAMP [0] (1279061630) Tue Jul 13 17:53:50 2010 |
| 0 | PIN_FLD_START_T | TSTAMP [0] (1279061630) Tue Jul 13 17:53:50 2010 |
| 0 | PIN_FLD_BATCH_INFO | ARRAY [0] allocated 20, used 2 |
| 1 | PIN_FLD_CHANNEL_ID | INT [0] 1 |
| 1 | PIN_FLD_POID_VAL | POID [0] 0.0.0.20 /payment 1000 0 |
| 0 | PIN_FLD_CHARGES | ARRAY [0] allocated 20, used 9 |
| 1 | PIN_FLD_ACCOUNT_OBJ | POID [0] 0.0.0.1 /account 14606 11 |
| 1 | PIN_FLD_ACCOUNT_NO | STR [0] "0.0.0.1-14606" |
| 1 | PIN_FLD_COMMAND | ENUM [0] 1 |
| 1 | PIN_FLD_PAY_TYPE | ENUM [0] 10003 |
| 1 | PIN_FLD_MERCHANT | STR [0] "ibizsoft" |
| 1 | PIN_FLD_CURRENCY | INT [0] 840 |
| 1 | PIN_FLD_AMOUNT | DECIMAL [0] 10 |
| 1 | PIN_FLD_TRANS_ID | STR [0] "T1,39,0" |
| 1 | PIN_FLD_PAYINFO | ARRAY [0] allocated 20, used 1 |
| 2 | PIN_FLD_CC_INFO | ARRAY [0] allocated 20, used 9 |
| 3 | PIN_FLD_SECURITY_ID | STR [0] "234" |
| 3 | PIN_FLD_CITY | STR [0] "New York" |
| 3 | PIN_FLD_STATE | STR [0] "NY" |
| 3 | PIN_FLD_ZIP | STR [0] "10112" |
| 3 | PIN_FLD_COUNTRY | STR [0] "USA" |
| 3 | PIN_FLD_NAME | STR [0] "Michael Chricton" |
| 3 | PIN_FLD_ADDRESS | STR [0] "40 Rockefellar Plaza" |
| 3 | PIN_FLD_DEBIT_EXP | STR [0] "XXXX" |
| 3 | PIN_FLD_DEBIT_NUM | STR [0] "XXXX" |
nap(29536)> robj – $DB_NO /config/ach 41599
| 0 | PIN_FLD_POID | POID [0] 0.0.0.1 /config/ach 41599 0 |
| 0 | PIN_FLD_CREATED_T |
TSTAMP [0] (1279125240) Wed Jul 14 11:34:00 2010 |
| 0 | PIN_FLD_MOD_T | TSTAMP [0] (1279125240) Wed Jul 14 11:34:00 2010 |
| 0 | PIN_FLD_READ_ACCESS |
STR [0] "G" |
| 0 | PIN_FLD_WRITE_ACCESS |
STR [0] "S" |
| 0 | PIN_FLD_ACCOUNT_OBJ |
POID [0] 0.0.0.1 /account 1 0 |
| 0 | PIN_FLD_DESCR |
STR [0] "" |
| 0 | PIN_FLD_HOSTNAME |
STR [0] "-" |
| 0 | PIN_FLD_NAME |
STR [0] "load_pin_ach" |
| 0 | PIN_FLD_PROGRAM_NAME |
STR [0] "load_pin_ach" |
| 0 | PIN_FLD_VALUE |
STR [0] "" |
| 0 | PIN_FLD_VERSION |
STR [0] "" |
| 0 | PIN_FLD_ACH_INFO |
ARRAY [0] allocated 20, used 4 |
| 1 | PIN_FLD_CHANNEL_ID |
INT [0] 0 |
| 1 | PIN_FLD_MERCHANT |
STR [0] "test" |
| 1 | PIN_FLD_NAME |
STR [0] "fusa" |
| 1 | PIN_FLD_POID_VAL |
POID [0] 0.0.1.1 /payment -1 0 |
| 0 | PIN_FLD_ACH_INFO |
ARRAY [1] allocated 20, used 4 |
| 1 | PIN_FLD_CHANNEL_ID |
INT [0] 1 |
| 1 | PIN_FLD_MERCHANT |
STR [0] "ibizsoft" |
| 1 | PIN_FLD_NAME |
STR [0] "chase" |
| 1 | PIN_FLD_POID_VAL |
POID [0] 0.0.0.20 /payment 1000 0 |
nap(29536)> r se.txt 99
nap(29536)> d 99
# number of field entries allocated 20, used 15
| 0 | PIN_FLD_POID |
POID [0] 0.0.0.1 /payinfo/cc 0 0 |
| 0 | PIN_FLD_CREATED_T |
TSTAMP [0] (1274913446) Wed May 26 17:37:26 2010 |
| 0 | PIN_FLD_MOD_T | TSTAMP [0] (1274913446) Wed May 26 17:37:26 2010 |
| 0 | PIN_FLD_READ_ACCESS |
STR [0] "L" |
| 0 | PIN_FLD_WRITE_ACCESS |
STR [0] "L" |
| 0 | PIN_FLD_ACCOUNT_OBJ |
POID [0] 0.0.0.1 /account 32298 9 |
| 0 | PIN_FLD_ACH |
INT [0] 0 |
| 0 | PIN_FLD_DUE_DOM |
INT [0] 0 |
| 0 | PIN_FLD_INVOICE_OBJ |
POID [0] 0.0.0.1 /invoice 1 0 |
| 0 | PIN_FLD_INV_TYPE |
ENUM [0] 0 |
| 0 | PIN_FLD_NAME |
STR [0] "top payinfo obj" |
| 0 | PIN_FLD_PAYMENT_OFFSET |
INT [0] 0 |
| 0 | PIN_FLD_PAYMENT_TERM |
ENUM [0] 0 |
| 0 | PIN_FLD_RELATIVE_DUE_T |
TSTAMP [0] (1274913446) Wed May 26 17:37:26 2010 |
| 0 | PIN_FLD_CC_INFO |
ARRAY [1] allocated 20, used 8 |
| 1 | PIN_FLD_ADDRESS |
STR [0] "9300 Wade Blvd" |
| 1 | PIN_FLD_CITY |
STR [0] "Frisco" |
| 1 | PIN_FLD_COUNTRY |
STR [0] "USA" |
| 1 | PIN_FLD_DEBIT_EXP |
STR [0] "XXXX" |
| 1 | PIN_FLD_DEBIT_NUM |
STR [0] "XXXX" |
| 1 | PIN_FLD_NAME |
STR [0] "Kavan Shah" |
| 1 | PIN_FLD_STATE |
STR [0] "TX" |
| 1 | PIN_FLD_ZIP |
STR [0] "75034" |
nap(29536)> < new_data_script
r se.txt 99
xop 1 PCM_OPFLG_USE_POID_GIVEN 99
xop: opcode 1, flags 0
# number of field entries allocated 20, used 1
| 0 | PIN_FLD_POID |
POID [0] 0.0.0.1 /payinfo/cc 48701 0 |
nap(29536)> robj – $DB_NO /serivce/pcm_client 128
PCM_OP_READ_OBJ failed: err 4:PIN_ERR_BAD_ARG, field 0/16:PIN_FLD_POID,
loc 4:PIN_ERRLOC_DM, errclass 0:UNKNOWN, rec_id 0, resvd 2
# number of field entries allocated 20, used 2
0 PIN_FLD_POID POID [0] 0.0.0.1 /serivce/pcm_client 128 0
0 PIN_FLD_ERR_BUF ERR [0]
<location=PIN_ERRLOC_DM:4 class=UNKNOWN:0 errno=PIN_ERR_BAD_ARG:4>
<field num=PIN_FLD_POID:7,16 recid=0 reserved=2 reserved2=0 time(sec:usec)=0:0>
<facility=0 msg_id=0 version=0>
There are no comments yet.